Re: Re : Solaris Performance - Profiling

>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]

-----------------------------------------------