Re: not exactly a bug report, but surprising behaviour

Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> writes:

> Greg Stark <gsstark(at)mit(dot)edu> writes:
>
> Er ... did you look all the way through the output? The standard gprof
> output shows the flat timings you quoted followed by a call-tree report.

Well, yes but I wasn't sure what to look for. It sort of looks to me like
gprof chose an odd place to root the recursive cycle which makes the result
confusing. At least to me.

index % time self children called name
[1] 88.3 194.70 326.46 228+534992216 <cycle 2 as a whole> [1]
97.88 35.00 69608411 ExecMakeFunctionResult <cycle 2> [5]
3.68 121.86 5731762 postquel_execute <cycle 2> [6]
13.08 39.77 17360724 ExecTargetList <cycle 2> [17]
26.52 23.01 192211935 ExecEvalExpr <cycle 2> [18]
1.74 32.89 6127527 ExecScan <cycle 2> [23]
0.67 30.64 448463 ExecUnique <cycle 2> [26]
15.18 0.00 69608411 ExecEvalFuncArgs <cycle 2> [47]
4.16 8.86 11463396 ExecEvalArrayRef <cycle 2> [54]
2.74 8.95 5731958 ExecutePlan <cycle 2> [60]
1.48 8.56 5412663 ExecSort <cycle 2> [65]
2.70 7.04 17360724 ExecProject <cycle 2> [66]
3.11 3.13 5560629 ExecNestLoop <cycle 2> [86]
2.00 3.23 5731890 ExecResult <cycle 2> [93]
5.20 0.00 23281174 ExecProcNode <cycle 2> [94]
4.16 0.05 35012021 ExecEvalFunc <cycle 2> [104]
3.28 0.34 5731762 fmgr_sql <cycle 2> [113]
3.21 0.03 34596390 ExecEvalOper <cycle 2> [117]
1.18 1.70 5731958 ExecutorRun <cycle 2> [122]
1.12 0.00 5731762 postquel_getnext <cycle 2> [152]
0.47 0.35 5748363 ExecQual <cycle 2> [167]
0.81 0.00 5678894 ExecIndexScan <cycle 2> [168]
0.00 0.49 2116 make_op <cycle 2> [182]
0.13 0.32 59133 ExecIndexReScan <cycle 2> [187]
0.12 0.00 59133 ExecReScan <cycle 2> [217]
0.00 0.05 1054 ParseFuncOrColumn <cycle 2> [244]
0.05 0.00 448463 SubqueryNext <cycle 2> [245]
0.00 0.04 184 pg_parse_and_rewrite <cycle 2> [263]
0.01 0.02 4657 simplify_op_or_func <cycle 2> [266]
0.00 0.03 1005 coerce_to_target_type <cycle 2> [270]
0.00 0.03 1735 coerce_type <cycle 2> [276]
0.00 0.03 9859 expression_tree_mutator <cycle 2> [277]
0.00 0.02 759 typecast_expression <cycle 2> [291]
0.01 0.01 198+409 set_plan_references <cycle 2> [292]
0.01 0.00 448463 ExecSubqueryScan <cycle 2> [313]
0.00 0.00 60857 ExecEvalExprSwitchContext <cycle 2> [350]
0.00 0.00 242 transformArraySubscripts <cycle 2> [366]
0.00 0.00 184 init_sql_fcache <cycle 2> [373]
0.00 0.00 446+6484 transformExpr <cycle 2> [375]
0.00 0.00 10680 eval_const_expressions_mutator <cycle 2> [377]
0.00 0.00 198 transformSelectStmt <cycle 2> [387]
0.00 0.00 5 set_base_rel_pathlists <cycle 2> [391]
0.00 0.00 202 pg_analyze_and_rewrite <cycle 2> [395]
0.00 0.00 5 make_one_rel <cycle 2> [408]
0.00 0.00 5 subplanner <cycle 2> [417]
0.00 0.00 202 parse_analyze <cycle 2> [438]
0.00 0.00 199 query_planner <cycle 2> [440]
0.00 0.00 184 init_execution_state <cycle 2> [450]
0.00 0.00 200 transformTargetEntry <cycle 2> [453]
0.00 0.00 198 transformTargetList <cycle 2> [463]
0.00 0.00 198 planner <cycle 2> [489]
0.00 0.00 1 transformInsertStmt <cycle 2> [527]
0.00 0.00 199 grouping_planner <cycle 2> [536]
0.00 0.00 597 preprocess_expression <cycle 2> [538]
0.00 0.00 199 subquery_planner <cycle 2> [540]
0.00 0.00 1 ExecAgg <cycle 2> [557]
0.00 0.00 7 create_plan <cycle 2> [562]
0.00 0.00 11 transformColumnRef <cycle 2> [571]
0.00 0.00 1 set_subquery_pathlist <cycle 2> [610]
0.00 0.00 27 join_references_mutator <cycle 2> [637]
0.00 0.00 199+8 pull_up_subqueries <cycle 2> [651]
0.00 0.00 396 transformWhereClause <cycle 2> [667]
0.00 0.00 1 create_nestloop_plan <cycle 2> [708]
0.00 0.00 8 ResolveNew_mutator <cycle 2> [757]
0.00 0.00 203 transformStmt <cycle 2> [860]
0.00 0.00 1 set_uppernode_references <cycle 2> [887]
0.00 0.00 1 create_join_plan <cycle 2> [919]
0.00 0.00 4232 make_operand <cycle 2> [994]
0.00 0.00 1837 eval_const_expressions <cycle 2> [1005]
0.00 0.00 1266 transformIndirection <cycle 2> [1008]
0.00 0.00 1054 make_arguments <cycle 2> [1015]
0.00 0.00 199+6 preprocess_qual_conditions <cycle 2> [1069]
0.00 0.00 198 pg_plan_query <cycle 2> [1072]
0.00 0.00 170 ExecSeqScan <cycle 2> [1084]
0.00 0.00 33 replace_correlation_vars_mutator <cycle 2> [1149]
0.00 0.00 5 join_references <cycle 2> [1220]
0.00 0.00 3 replace_vars_with_subplan_refs_mutator <cycle 2> [1276]
0.00 0.00 3 SS_replace_correlation_vars <cycle 2> [1266]
0.00 0.00 3 ResolveNew <cycle 2> [1265]
0.00 0.00 2 replace_vars_with_subplan_refs <cycle 2> [1325]
0.00 0.00 1+1 resolvenew_in_jointree <cycle 2> [1449]
0.00 0.00 1 set_join_references <cycle 2> [1453]
-----------------------------------------------
0.00 23.77 11/201 _SPI_execute [11]
0.00 410.53 190/201 _SPI_execute_plan [4]
[2] 73.6 0.00 434.30 201 _SPI_pquery [2]
162.25 272.05 190/228 ExecutorRun <cycle 2> [122]
0.00 0.00 190/5731956 ExecutorStart [8]
0.00 0.00 189/5731953 ExecutorEnd [38]
0.00 0.00 127/130 _SPI_checktuples [4917]
-----------------------------------------------
<spontaneous>
[3] 69.6 0.00 410.54 SPI_execp [3]
0.00 410.53 190/190 _SPI_execute_plan [4]
0.00 0.00 190/212 _SPI_copy_plan [365]
0.00 0.00 189/203 _SPI_end_call [439]
0.00 0.00 190/215 _SPI_begin_call [788]
-----------------------------------------------
0.00 410.53 190/190 SPI_execp [3]
[4] 69.6 0.00 410.53 190 _SPI_execute_plan [4]
0.00 410.53 190/201 _SPI_pquery [2]
0.00 0.00 379/395 CommandCounterIncrement [454]
0.00 0.00 190/441 CreateExecutorState [443]
0.00 0.00 190/389 CreateQueryDesc [535]
0.00 0.00 189/155883526 MemoryContextAlloc [21]

--
greg