Re: Re : Solaris Performance - Profiling
| От | Mark kirkwood |
|---|---|
| Тема | Re: Re : Solaris Performance - Profiling |
| Дата | |
| Msg-id | 1017741670.1360.57.camel@spikey.slithery.org обсуждение исходный текст |
| Ответ на | Re: Re : Solaris Performance - Profiling (Tom Lane <tgl@sss.pgh.pa.us>) |
| Ответы |
Re: Re : Solaris Performance - Profiling
(Tom Lane <tgl@sss.pgh.pa.us>)
|
| Список | pgsql-general |
>Previously (snippage....) > > It looks like you profiled the postmaster (parent process), not the > backend you were interested in.... > 1. Backends will drop their gmon.out files into the database > subdirectory they connect to ($PGDATA/base/nnn/gmon.out). > Any gmon.out you see in the top-level directory is from the postmaster > itself or a checkpoint process --- neither of which are likely to be > interesting. > Thanks Tom... I looked just about everywhere _except_ there :-( The backend profile is in $PGDATA/base/nnnn. I am a little concerned that the cpu time recored by the profiler seems to be a bit on the short side at 4047.53 seconds (67 minutes), as opposed to 119.2 for the backend itself. Are these two numbers supposed to match closely ? (they did for shorter queries..) Anyway in the hope that this captured output is interesting enough, here it is...or rather here is some of it (biggish file), so I am leaving a complete copy under : http://homepages.slingshot.co.nz/~markir/tar/solaris/ Let me know if further information is likely to be helpful. I have profiled the same query (on the same dataset) on Freebsd and have the output available at : http://homepages.slingshot.co.nz/~markir/tar/freebsd/ regards Mark The interesting bits of the flat profile looks like : % cumulative self self total time seconds seconds calls ms/call ms/call name 30.8 1268.83 1268.83 internal_mcount [20] 19.5 2070.96 802.13 1680561053 0.00 0.00 comparetup_heap [7] 18.8 2843.64 772.68 3361298446 0.00 0.00 nocachegetattr [24] 4.8 3041.20 197.56 1680926512 0.00 0.00 _memset [27] 4.3 3218.96 177.76 1680561053 0.00 0.00 varcharcmp [25] 4.1 3386.71 167.75 1680561053 0.00 0.00 qsort_comparetup [6] 3.8 3543.21 156.50 1680835238 0.00 0.00 FunctionCall2 <cycle 14> [23] 3.4 3684.64 141.43 1680561053 0.00 0.00 ApplySortFunction [21] 3.4 3825.56 140.92 3361298219 0.00 0.00 pg_detoast_datum [28] 2.8 3941.52 115.96 1680649052 0.00 0.00 varstr_cmp [26] 2.0 4023.16 81.64 1680649731 0.00 0.00 strncmp [29] 1.7 4094.92 71.76 _mcount (5712) 0.5 4114.65 19.73 1 19730.00 2774314.94 qst [5] 0.0 4115.28 0.63 3078 0.20 0.20 _read [41] 0.0 4115.59 0.31 616267 0.00 0.00 ExecEvalVar [52] 0.0 4115.76 0.17 440367 0.00 0.00 AllocSetReset [62] 0.0 4115.93 0.17 264093 0.00 0.00 heap_formtuple [47] 0.0 4116.09 0.16 264093 0.00 0.00 ExecTargetList [38] 0.0 4116.24 0.15 533566 0.00 0.00 AllocSetAlloc [59] 0.0 4116.39 0.15 365666 0.00 0.00 LWLockAcquire [58] 0.0 4116.53 0.14 96464 0.00 0.00 .rem [67] 0.0 4116.67 0.14 88400 0.00 0.02 heap_fetch [34] 0.0 4116.78 0.11 365666 0.00 0.00 LWLockRelease [63] 0.0 4116.88 0.10 731332 0.00 0.00 tas [75] 0.0 4116.98 0.10 352190 0.00 0.01 ExecProcNode <cycle 3> [30] 0.0 4117.07 0.09 977319 0.00 0.00 AllocSetFreeIndex [78] 0.0 4117.16 0.09 264093 0.00 0.00 ComputeDataSize [82] 0.0 4117.25 0.09 264093 0.00 0.00 DataFill [70] 0.0 4117.34 0.09 120472 0.00 0.00 _memcmp [80] 0.0 4117.43 0.09 89883 0.00 0.01 ReadBufferInternal [36] 0.0 4117.52 0.09 88491 0.00 0.00 _bt_checkkeys <cycle 14> [81] 0.0 4117.61 0.09 88088 0.00 0.00 HeapTupleSatisfiesSnapshot [74] 0.0 4117.70 0.09 5198 0.02 0.02 .div [79] 0.0 4117.77 0.07 88497 0.00 0.00 btgettuple <cycle 14> [56] 0.0 4117.84 0.07 88001 0.00 0.01 ExecNestLoop <cycle 3> [44] 0.0 4117.90 0.06 528386 0.00 0.00 ExecClearTuple [54] 0.0 4117.96 0.06 264093 0.00 0.00 ExecProject [37] 0.0 4118.02 0.06 96981 0.00 0.00 hash_search [50] 0.0 4118.08 0.06 88177 0.00 0.03 ExecScan [32] 0.0 4118.14 0.06 88092 0.00 0.00 _bt_restscan [72] 0.0 4118.19 0.05 533564 0.00 0.00 MemoryContextAlloc [55] 0.0 4118.24 0.05 443729 0.00 0.00 AllocSetFree [77] 0.0 4118.29 0.05 271989 0.00 0.00 _memcpy [92] 0.0 4118.34 0.05 264291 0.00 0.00 heap_freetuple [71] 0.0 4118.39 0.05 89797 0.00 0.00 UnpinBuffer [86] 0.0 4118.44 0.05 88177 0.00 0.02 IndexNext [33] 0.0 4118.49 0.05 88094 0.00 0.00 _bt_step [87] 0.0 4118.54 0.05 86858 0.00 0.00 PinBuffer [91] and similarly the call graph like : granularity: each sample hit covers 4 byte(s) for 0.00% of 4047.53 seconds called/total parents index %time self descendents called+self name index called/total children 0.00 2778.68 1/1 main [2] [1] 68.7 0.00 2778.68 1 PostmasterMain [1] 0.00 1391.42 1/1 ServerLoop [8] 0.00 1387.23 1/1 load_password_cache [18] 0.00 0.01 1/1 load_hba_and_ident [136] 0.00 0.01 1/1 reset_shared [138] 0.00 0.00 1/1 pgstat_start [221] 0.00 0.00 1/1 SSDataBase [220] 0.00 0.00 1/1 ProcessConfigFile [335] 0.00 0.00 1/1 checkDataDir [345] 0.00 0.00 1/1 CreateOptsFile [440] 0.00 0.00 1/1 StreamServerPort [443] 0.00 0.00 1/1 CreateDataDirLockFile [445] 0.00 0.00 1/2 FindExec [560] 0.00 0.00 1/1 RemovePgTempFiles [639] 0.00 0.00 1/1 XLOGPathInit [696] 0.00 0.00 1/1 pgstat_init [697] 0.00 0.00 1/1 MemoryContextInit [701] 0.00 0.00 1/70 AllocSetContextCreate [505] 0.00 0.00 1/1056908 MemoryContextSwitchTo [112] 0.00 0.00 11/28 pqsignal [873] 0.00 0.00 2/39 getenv [857] 0.00 0.00 2/5 _getopt [4913] 0.00 0.00 1/1 _umask [4973] 0.00 0.00 1/7 _getpid [4902] 0.00 0.00 1/1 EnableExceptionHandling [1096] 0.00 0.00 1/1 ResetAllOptions [1120] 0.00 0.00 1/1 SetDataDir [1124] 0.00 0.00 1/1 IgnoreSystemIndexes [1109] 0.00 0.00 1/1 DLNewList [1094] 0.00 0.00 1/2 pqinitmask [1077] 0.00 0.00 1/11 _sigprocmask [4893] ----------------------------------------------- 0.00 2778.68 1/1 _start [3] [2] 68.7 0.00 2778.68 1 main [2] 0.00 2778.68 1/1 PostmasterMain [1] 0.00 0.00 2/5 _geteuid [4912] 0.00 0.00 1/1 save_ps_display_args [1173] 0.00 0.00 1/264 malloc [818] 0.00 0.00 1/53 _strdup [4875] 0.00 0.00 1/2 _getuid [4939] 0.00 0.00 1/3826 strlen [768] 0.00 0.00 1/403 strcmp [809] ----------------------------------------------- <spontaneous> [3] 68.7 0.00 2778.68 _start [3] 0.00 2778.68 1/1 main [2] 0.00 0.00 2/4 atexit [987] ----------------------------------------------- 0.00 1387.23 1/2 load_password_cache [18] 0.00 1387.23 1/2 tuplesort_performsort [19] [4] 68.5 0.00 2774.46 2 qsort [4] 19.73 2754.58 1/1 qst [5] 0.01 0.14 88012/1680561053 qsort_comparetup [6] 0.00 0.00 1/61473 .umul [154] ----------------------------------------------- 19.73 2754.58 1/1 qsort [4] [5] 68.5 19.73 2754.58 1 qst [5] 167.74 2586.81 1680473041/1680561053 qsort_comparetup [6] 0.02 0.00 59630/59703 .udiv [114] 0.01 0.00 59630/61473 .umul [154] ----------------------------------------------- 0.01 0.14 88012/1680561053 qsort [4] 167.74 2586.81 1680473041/1680561053 qst [5] [6] 68.1 167.75 2586.95 1680561053 qsort_comparetup [6] 802.13 1784.82 1680561053/1680561053 comparetup_heap [7] ----------------------------------------------- 802.13 1784.82 1680561053/1680561053 qsort_comparetup [6] [7] 63.9 802.13 1784.82 1680561053 comparetup_heap [7] 141.43 870.75 1680561053/1680561053 ApplySortFunction [21] 772.64 0.00 3361122106/3361298446 nocachegetattr [24] ----------------------------------------------- 0.00 1391.42 1/1 PostmasterMain [1] [8] 34.4 0.00 1391.42 1 ServerLoop [8] 0.00 1391.42 1/1 BackendStartup [9] 0.00 0.00 1/1 ConnCreate [526] 0.00 0.00 4/271989 _memcpy [92] 0.00 0.00 1/1 initMasks [750] 0.00 0.00 4/11 _sigprocmask [4893] 0.00 0.00 2/7 _gettimeofday [4903] 0.00 0.00 2/2 select [1078] ----------------------------------------------- 0.00 1391.42 1/1 ServerLoop [8] [9] 34.4 0.00 1391.42 1 BackendStartup [9] 0.00 1391.42 1/1 DoBackend [10] 0.00 0.00 1/3 _fork [152] 0.00 0.00 2/8 fflush [915] 0.00 0.00 1/5 PostmasterRandom [945] 0.00 0.00 1/264 malloc [818] 0.00 0.00 1/99 free [836] ----------------------------------------------- 0.00 1391.42 1/1 BackendStartup [9] [10] 34.4 0.00 1391.42 1 DoBackend [10] 0.00 1391.41 1/1 PostgresMain [11] 0.01 0.00 1/1 ClientAuthentication [145] 0.00 0.00 1/1 ProcessStartupPacket [535] 0.00 0.00 1/1 enable_sigalrm_interrupt [536] 0.00 0.00 2/2140 strncpy [155] 0.00 0.00 1/9 set_ps_display [502] 0.00 0.00 1/1 init_ps_display [729] 0.00 0.00 1/62 sprintf [515] 0.00 0.00 1/33 MemoryContextDelete <cycle 15> [571] 0.00 0.00 1/1056908 MemoryContextSwitchTo [112] 0.00 0.00 3/28 pqsignal [873] 0.00 0.00 2/11 _sigprocmask [4893] 0.00 0.00 2/2 split_opts [1081] 0.00 0.00 1/1 on_exit_reset [1160] 0.00 0.00 1/1 ClosePostmasterPorts [1089] 0.00 0.00 1/7 _getpid [4902] 0.00 0.00 1/1 pq_init [1170] 0.00 0.00 1/1 disable_sigalrm_interrupt [1145] 0.00 0.00 1/7 _gettimeofday [4903] 0.00 0.00 1/2 srandom [1082] ----------------------------------------------- 0.00 1391.41 1/1 DoBackend [10] [11] 34.4 0.00 1391.41 1 PostgresMain [11] 0.00 1391.39 3/3 pg_exec_query_string [12] 0.00 0.01 1/1 InitPostgres [134] 0.00 0.00 5/9 set_ps_display [502] 0.00 0.00 1/1 proc_exit [537] 0.00 0.00 1/1 BaseInit [582] 0.00 0.00 4/4 makeStringInfo [612] 0.00 0.00 4/7 MemoryContextResetAndDeleteChildren [603] 0.00 0.00 4/4 ReadyForQuery [725] 0.00 0.00 1/70 AllocSetContextCreate [505] 0.00 0.00 1/10 pq_endmessage [593] 0.00 0.00 1/14 initStringInfo [577] 0.00 0.00 2/31 pq_sendint [587] 0.00 0.00 4/1056908 MemoryContextSwitchTo [112] 0.00 0.00 14/28 pqsignal [873] 0.00 0.00 7/7 pgstat_report_activity [929] 0.00 0.00 4/4 pgstat_report_tabstat [997] 0.00 0.00 4/4 IsTransactionBlock [977] 0.00 0.00 4/4 EnableNotifyInterrupt [969] 0.00 0.00 4/4 ReadCommand [978] 0.00 0.00 4/4 DisableNotifyInterrupt [968] 0.00 0.00 3/5 _getopt [4913] 0.00 0.00 3/3 strspn [1042] 0.00 0.00 2/11 _sigprocmask [4893] 0.00 0.00 1/1 set_default_datestyle [1175] 0.00 0.00 1/53 _strdup [4875] 0.00 0.00 1/1 atoi [1139] 0.00 0.00 1/2 pqinitmask [1077] 0.00 0.00 1/39 _sigdelset [4879] 0.00 0.00 1/10 pq_sendbyte [906] 0.00 0.00 1/1 pgstat_bestart [1164] 0.00 0.00 1/1 _sigsetjmp [4965] ----------------------------------------------- 0.00 1391.39 3/3 PostgresMain [11] [12] 34.4 0.00 1391.39 3 pg_exec_query_string [12] 0.00 1391.35 3/3 ProcessQuery [13] 0.00 0.03 3/3 pg_plan_query [95] 0.00 0.02 3/3 pg_analyze_and_rewrite [125] 0.00 0.00 3/3 start_xact_command [287] 0.00 0.00 3/3 pg_parse_query [501] 0.00 0.00 3/3 finish_xact_command [516] 0.00 0.00 3/3 SetQuerySnapshot [585] 0.00 0.00 3/3 CommandCounterIncrement [626] 0.00 0.00 3/7 MemoryContextResetAndDeleteChildren [603] 0.00 0.00 12/1056908 MemoryContextSwitchTo [112] 0.00 0.00 3/3 IsAbortedTransactionBlockState [1017] ----------------------------------------------- 0.00 1391.35 3/3 pg_exec_query_string [12] [13] 34.4 0.00 1391.35 3 ProcessQuery [13] 0.00 1391.32 3/3 ExecutorRun [14] 0.00 0.02 3/3 ExecutorEnd [103] 0.00 0.01 3/3 ExecutorStart [177] 0.00 0.00 3/9 set_ps_display [502] 0.00 0.00 3/3 BeginCommand [572] 0.00 0.00 3/3 EndCommand [634] 0.00 0.00 3/3 CreateExecutorState [674] 0.00 0.00 3/3 CreateQueryDesc [685] 0.00 0.00 3/3 CreateOperationTag [1009] 0.00 0.00 3/3 UpdateCommandInfo [1020] ----------------------------------------------- 0.00 1391.32 3/3 ProcessQuery [13] [14] 34.4 0.00 1391.32 3 ExecutorRun [14] 0.00 1391.32 3/3 ExecutePlan [15] 0.00 0.00 3/3 printtup_cleanup [671] 0.00 0.00 3/3 DestToFunction [686] 0.00 0.00 3/3 printtup_setup [1037] ----------------------------------------------- 0.00 1391.32 3/3 ExecutorRun [14] [15] 34.4 0.00 1391.32 3 ExecutePlan [15] 0.20 1391.12 8/8 ExecProcNode <cycle 3> [30] 0.00 0.00 5/5 ExecRetrieve [238] ----------------------------------------------- [16] 34.4 0.20 1391.12 8+704194 <cycle 3 as a whole> [16] 0.03 1387.42 88001 ExecSort <cycle 3> [17] 0.10 2.50 352190 ExecProcNode <cycle 3> [30] 0.07 0.50 88001 ExecNestLoop <cycle 3> [44] 0.00 0.55 88003 ExecGroupEveryTuple <cycle 3> [45] 0.00 0.15 4 ExecAgg <cycle 3> [65] 0.00 0.00 88003 ExecGroup <cycle 3> [763] ----------------------------------------------- 88001 ExecProcNode <cycle 3> [30] [17] 34.3 0.03 1387.42 88001 ExecSort <cycle 3> [17] 0.00 1387.23 1/1 tuplesort_performsort [19] 0.02 0.12 88000/88000 tuplesort_puttuple [69] 0.01 0.04 88001/528274 ExecStoreTuple [53] 0.00 0.00 1/1 tuplesort_begin_heap [332] 0.00 0.00 1/1 ExtractSortKeys [705] 0.00 0.00 2/443727 pfree [73] 0.00 0.00 88001/88001 tuplesort_gettuple [765] 0.00 0.00 1/8 ExecGetTupType [912] 0.00 0.00 1/9 ExecAssignResultType [907] 88001 ExecProcNode <cycle 3> [30] ----------------------------------------------- 0.00 1387.23 1/1 PostmasterMain [1] [18] 34.3 0.00 1387.23 1 load_password_cache [18] 0.00 1387.23 1/2 qsort [4] 0.00 0.00 2/2 fgets [384] 0.00 0.00 1/1 crypt_openpwdfile [444] 0.00 0.00 1/92 MemoryContextStrdup [486] 0.00 0.00 1/533564 MemoryContextAlloc [55] 0.00 0.00 1/3826 strlen [768] 0.00 0.00 1/7 FreeFile [925] ----------------------------------------------- 0.00 1387.23 1/1 ExecSort <cycle 3> [17] [19] 34.3 0.00 1387.23 1 tuplesort_performsort [19] 0.00 1387.23 1/2 qsort [4] ----------------------------------------------- <spontaneous> [20] 31.3 1268.83 0.00 internal_mcount [20] 0.00 0.00 1/4 atexit [987] ----------------------------------------------- 141.43 870.75 1680561053/1680561053 comparetup_heap [7] [21] 25.0 141.43 870.75 1680561053 ApplySortFunction [21] 156.67 714.08 1680561053/1680739842 FunctionCall2 <cycle 14> [23] ----------------------------------------------- [22] 21.5 156.69 714.15 1680739842+368109 <cycle 14 as a whole> [22] 156.50 713.84 1680835238 FunctionCall2 <cycle 14> [23] 0.07 0.17 88497 btgettuple <cycle 14> [56] 0.03 0.13 88092 _bt_next <cycle 14> [64] 0.09 0.00 88491 _bt_checkkeys <cycle 14> [81] 0.00 0.02 405 _bt_search <cycle 14> [117] 0.00 0.00 405 _bt_first <cycle 14> [270] 0.00 0.00 5666 _bt_compare <cycle 14> [4858] 0.00 0.00 781 _bt_binsrch <cycle 14> [4862] 0.00 0.00 376 _bt_moveright <cycle 14> [4865] -----------------------------------------------
В списке pgsql-general по дате отправления: