pg_stat_statements produces multiple entries for a single query with track = 'top'

While at 2ndQuadrant, I was responsible for a project called
pg_stat_plans, which as some people subscribed to this mailing list
will be aware is essentially a tool for instrumenting Postgres query
execution costs at the plan granularity rather than at the query
granularity. It is derivative of pg_stat_statements.

While investigating this pg_stat_plans bug report:

https://github.com/2ndQuadrant/pg_stat_plans/issues/16

I realized that it pointed to a deeper issue that also affected
pg_stat_statements. The following is a psql session
(REL9_2_STABLE-tip) that illustrates the problem:

postgres=# create database bug;
CREATE DATABASE
postgres=# \c bug
You are now connected to database "bug" as user "pg".
bug=# create extension pg_stat_statements;
CREATE EXTENSION
bug=# create table places
(
id integer primary key,
coordinate double precision[],
category_id integer
);
NOTICE: CREATE TABLE / PRIMARY KEY will create implicit index
"places_pkey" for table "places"
CREATE TABLE
bug=# create extension cube;
CREATE EXTENSION
bug=# create extension earthdistance ;
CREATE EXTENSION
bug=# SELECT "places".* FROM "places" WHERE
(earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @>
ll_to_earth(coordinate[0], coordinate[1])) AND ((places.category_id IS
NULL OR places.category_id != 15));
id | coordinate | category_id
----+------------+-------------
(0 rows)

bug=# select query,calls from pg_stat_statements;

query
| calls
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------
SELECT cube_enlarge($1, gc_to_sec($2), ?)

| 1
SELECT "places".* FROM "places" WHERE (earth_box(ll_to_earth(?, ?),
?) @> ll_to_earth(coordinate[?], coordinate[?])) AND
((places.category_id IS NULL OR places.category_id != ?)); | 1
select pg_stat_statements_reset();

| 1
SELECT pg_catalog.quote_ident(datname) FROM pg_catalog.pg_database
WHERE substring(pg_catalog.quote_ident(datname),?,?)=?
+| 1
LIMIT ?

|
create extension pg_stat_statements;

| 1
SELECT "places".* FROM "places" WHERE (earth_box(ll_to_earth(?, ?),
?) @> ll_to_earth(coordinate[?], coordinate[?])) AND
((places.category_id IS NULL OR places.category_id != ?)); | 1
create table places

+| 1
(

+|
id integer primary key,

+|
coordinate double precision[],

+|
category_id integer

+|
);

|
create extension cube;

| 1
select query,calls from pg_stat_statements;

| 1
SELECT ?::float8

| 4
create extension earthdistance ;

| 1
SELECT cube_enlarge($1, gc_to_sec($2), ?)

| 1
SELECT ?::float8

| 4
SELECT cube(cube(cube(earth()*cos(radians($1))*cos(radians($2))),earth()*cos(radians($1))*sin(radians($2))),earth()*sin(radians($1)))::earth
| 1
SELECT pg_catalog.quote_ident(name) FROM
pg_catalog.pg_available_extensions WHERE
substring(pg_catalog.quote_ident(name),?,?)=? AND installed_version IS
NULL +| 1
LIMIT ?

|
create database bug;

| 1
SELECT cube(cube(cube(earth()*cos(radians($1))*cos(radians($2))),earth()*cos(radians($1))*sin(radians($2))),earth()*sin(radians($1)))::earth
| 1
(17 rows)

Note my "track" setting:

bug=# show pg_stat_statements.track;
pg_stat_statements.track
--------------------------
top
(1 row)

So with this single earthdistance query, there are multiple
invocations of the executor, and thus multiple associated
pg_stat_statements entries (one with 4 "calls"). Here is a backtrace
for the query "SELECT '6378168'::float8" within pgss_ExecutorEnd,
where instrumentation is (generally) stored (that is, where
pgss_store() is called). I set this break-point immediately before
running the above verbose query in a psql session. Here is what I see
when the breakpoint is initially hit:

Breakpoint 1, pgss_ExecutorEnd (queryDesc=0x2484628) at pg_stat_statements.c:759
759 uint32 queryId = queryDesc->plannedstmt->queryId;
(gdb) p *queryDesc
$1 = {operation = CMD_SELECT, plannedstmt = 0x24a8510, utilitystmt =
0x0, sourceText = 0x24a6ab8 "SELECT '6378168'::float8", snapshot =
0x2393930, crosscheck_snapshot = 0x0, dest = 0x24a88f0, params = 0x0,
instrument_options = 0, tupDesc = 0x24a8e88, estate = 0x24a8998,
planstate = 0x24a8ab0, totaltime = 0x24a9120}
(gdb) bt
#0 pgss_ExecutorEnd (queryDesc=0x2484628) at pg_stat_statements.c:759
#1 0x000000000061c6fe in ExecutorEnd (queryDesc=0x2484628) at execMain.c:401
#2 0x0000000000630025 in postquel_end (es=0x24a85a8) at functions.c:867
#3 0x0000000000630608 in fmgr_sql (fcinfo=0x24a4b00) at functions.c:1151
#4 0x00000000006237ba in ExecMakeFunctionResult (fcache=0x24a4a90,
econtext=0x24a52a8, isNull=0x7fff761074fc "", isDone=0x0) at
execQual.c:1927
#5 0x00000000006242c9 in ExecEvalFunc (fcache=0x24a4a90,
econtext=0x24a52a8, isNull=0x7fff761074fc "", isDone=0x0) at
execQual.c:2366
#6 0x0000000000628250 in ExecEvalExprSwitchContext
(expression=0x24a4a90, econtext=0x24a52a8, isNull=0x7fff761074fc "",
isDone=0x0) at execQual.c:4282
#7 0x00000000006e1306 in evaluate_expr (expr=0x24a36b8,
result_type=701, result_typmod=-1, result_collation=0) at
clauses.c:4404
#8 0x00000000006e073c in evaluate_function (funcid=16596,
result_type=701, result_typmod=-1, result_collid=0, input_collid=0,
args=0x0, func_tuple=0x7f885726b560, context=0x7fff7610ad10) at
clauses.c:3967
#9 0x00000000006dfc4a in simplify_function (funcid=16596,
result_type=701, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff76107678, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610ad10) at clauses.c:3610
#10 0x00000000006dd74b in eval_const_expressions_mutator
(node=0x24a1308, context=0x7fff7610ad10) at clauses.c:2310
#11 0x000000000066ca9e in expression_tree_mutator (node=0x24a15e0,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610ad10) at nodeFuncs.c:2467
#12 0x00000000006dfc0f in simplify_function (funcid=216,
result_type=701, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff76107d28, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610ad10) at clauses.c:3601
#13 0x00000000006dd8d6 in eval_const_expressions_mutator
(node=0x24a1640, context=0x7fff7610ad10) at clauses.c:2356
#14 0x000000000066ca9e in expression_tree_mutator (node=0x24a1918,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610ad10) at nodeFuncs.c:2467
#15 0x00000000006dfc0f in simplify_function (funcid=216,
result_type=701, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff761083d8, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610ad10) at clauses.c:3601
#18 0x00000000006dfc0f in simplify_function (funcid=16548,
result_type=16524, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff76108a88, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610ad10) at clauses.c:3601
#19 0x00000000006dd74b in eval_const_expressions_mutator
(node=0x24a1ae0, context=0x7fff7610ad10) at clauses.c:2310
#20 0x000000000066ca9e in expression_tree_mutator (node=0x24a1b60,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610ad10) at nodeFuncs.c:2467
#21 0x00000000006dfc0f in simplify_function (funcid=16550,
result_type=16524, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff76109138, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610ad10) at clauses.c:3601
#22 0x00000000006dd74b in eval_const_expressions_mutator
(node=0x24a23e8, context=0x7fff7610ad10) at clauses.c:2310
#23 0x000000000066ca9e in expression_tree_mutator (node=0x24a2468,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610ad10) at nodeFuncs.c:2467
#24 0x00000000006dfc0f in simplify_function (funcid=16550,
result_type=16524, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff761097e8, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610ad10) at clauses.c:3601
#25 0x00000000006dd74b in eval_const_expressions_mutator
(node=0x24a29b8, context=0x7fff7610ad10) at clauses.c:2310
#26 0x000000000066c850 in expression_tree_mutator (node=0x24a2a10,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610ad10) at nodeFuncs.c:2408
#27 0x00000000006df67c in eval_const_expressions_mutator
(node=0x24a2a10, context=0x7fff7610ad10) at clauses.c:3263
#28 0x000000000066c8d4 in expression_tree_mutator (node=0x24a2a68,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610ad10) at nodeFuncs.c:2418
#29 0x00000000006df67c in eval_const_expressions_mutator
(node=0x24a2a68, context=0x7fff7610ad10) at clauses.c:3263
#30 0x000000000066ca9e in expression_tree_mutator (node=0x24a2ae8,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610ad10) at nodeFuncs.c:2467
#31 0x00000000006df67c in eval_const_expressions_mutator
(node=0x24a2ae8, context=0x7fff7610ad10) at clauses.c:3263
#32 0x00000000006dd31f in eval_const_expressions (root=0x24a33f0,
node=0x24a2ae8) at clauses.c:2202
#33 0x00000000006c60e9 in preprocess_expression (root=0x24a33f0,
expr=0x24a2ae8, kind=1) at planner.c:626
#34 0x00000000006c5bc3 in subquery_planner (glob=0x24a3358,
parse=0x24a1198, parent_root=0x0, hasRecursion=0 '\000',
tuple_fraction=0, subroot=0x7fff7610ae78) at planner.c:416
#35 0x00000000006c5622 in standard_planner (parse=0x24a1198,
cursorOptions=0, boundParams=0x0) at planner.c:204
#36 0x00000000006c5488 in planner (parse=0x24a1198, cursorOptions=0,
boundParams=0x0) at planner.c:133
#37 0x000000000075be59 in pg_plan_query (querytree=0x24a1198,
cursorOptions=0, boundParams=0x0) at postgres.c:751
#38 0x000000000062f688 in init_execution_state
(queryTree_list=0x24a3170, fcache=0x247c4e8, lazyEvalOK=1 '\001') at
functions.c:490
#39 0x000000000062fcc6 in init_sql_fcache (finfo=0x249c680,
collation=0, lazyEvalOK=1 '\001') at functions.c:740
#40 0x000000000063045d in fmgr_sql (fcinfo=0x249c6d0) at functions.c:1040
#41 0x00000000006237ba in ExecMakeFunctionResult (fcache=0x249c660,
econtext=0x249cf70, isNull=0x7fff7610b2fc "", isDone=0x0) at
execQual.c:1927
#42 0x00000000006242c9 in ExecEvalFunc (fcache=0x249c660,
econtext=0x249cf70, isNull=0x7fff7610b2fc "", isDone=0x0) at
execQual.c:2366
#43 0x0000000000628250 in ExecEvalExprSwitchContext
(expression=0x249c660, econtext=0x249cf70, isNull=0x7fff7610b2fc "",
isDone=0x0) at execQual.c:4282
#44 0x00000000006e1306 in evaluate_expr (expr=0x2474e50,
result_type=16597, result_typmod=-1, result_collation=0) at
clauses.c:4404
#45 0x00000000006e073c in evaluate_function (funcid=16603,
result_type=16597, result_typmod=-1, result_collid=0, input_collid=0,
args=0x2474c88, func_tuple=0x7f8857265108, context=0x7fff7610c870) at
clauses.c:3967
#46 0x00000000006dfc4a in simplify_function (funcid=16603,
result_type=16597, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff7610b478, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610c870) at clauses.c:3610
#47 0x00000000006dd74b in eval_const_expressions_mutator
(node=0x2499328, context=0x7fff7610c870) at clauses.c:2310
#48 0x000000000066ca9e in expression_tree_mutator (node=0x24993a8,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610c870) at nodeFuncs.c:2467
#49 0x00000000006dfc0f in simplify_function (funcid=16607,
result_type=16524, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff7610bb28, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610c870) at clauses.c:3601
#50 0x00000000006dd74b in eval_const_expressions_mutator
(node=0x2499570, context=0x7fff7610c870) at clauses.c:2310
#51 0x000000000066ca9e in expression_tree_mutator (node=0x2499ab8,
mutator=0x6dd372 <eval_const_expressions_mutator>,
context=0x7fff7610c870) at nodeFuncs.c:2467
#52 0x00000000006dfc0f in simplify_function (funcid=16537,
result_type=16, result_typmod=-1, result_collid=0, input_collid=0,
args_p=0x7fff7610c1d8, process_args=1 '\001', allow_non_const=1
'\001', context=0x7fff7610c870) at clauses.c:3601
#53 0x00000000006dd8d6 in eval_const_expressions_mutator
(node=0x2499b70, context=0x7fff7610c870) at clauses.c:2356
#54 0x00000000006df8de in simplify_and_arguments (args=0x2499e98,
context=0x7fff7610c870, haveNull=0x7fff7610c574 "",
forceFalse=0x7fff7610c578 "") at clauses.c:3430
#55 0x00000000006dde5e in eval_const_expressions_mutator
(node=0x2499ef8, context=0x7fff7610c870) at clauses.c:2538
#56 0x00000000006dd31f in eval_const_expressions (root=0x24745c0,
node=0x2499ef8) at clauses.c:2202
#57 0x00000000006c60e9 in preprocess_expression (root=0x24745c0,
expr=0x2499ef8, kind=0) at planner.c:626
#58 0x00000000006c620f in preprocess_qual_conditions (root=0x24745c0,
jtnode=0x2499f30) at planner.c:688
#59 0x00000000006c5c06 in subquery_planner (glob=0x2474528,
parse=0x2498528, parent_root=0x0, hasRecursion=0 '\000',
tuple_fraction=0, subroot=0x7fff7610ca18) at planner.c:423
#60 0x00000000006c5622 in standard_planner (parse=0x2498528,
cursorOptions=0, boundParams=0x0) at planner.c:204
#61 0x00000000006c5488 in planner (parse=0x2498528, cursorOptions=0,
boundParams=0x0) at planner.c:133
#62 0x000000000075be59 in pg_plan_query (querytree=0x2498528,
cursorOptions=0, boundParams=0x0) at postgres.c:751
#63 0x000000000075bf0c in pg_plan_queries (querytrees=0x24744f0,
cursorOptions=0, boundParams=0x0) at postgres.c:810
#64 0x000000000075c212 in exec_simple_query (query_string=0x242cd68
"SELECT \"places\".* FROM \"places\" WHERE
(earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @>
ll_to_earth(coordinate[0], coordinate[1])) AND ((places.category_id IS
NULL OR places.categor"...) at postgres.c:975
#65 0x0000000000760710 in PostgresMain (argc=1, argv=0x237b418,
dbname=0x237b278 "postgres", username=0x237b258 "pg") at
postgres.c:3959
#66 0x0000000000700618 in BackendRun (port=0x239e2b0) at postmaster.c:3614
#67 0x00000000006ffca9 in BackendStartup (port=0x239e2b0) at postmaster.c:3304
#68 0x00000000006fcacb in ServerLoop () at postmaster.c:1367
#69 0x00000000006fc3c2 in PostmasterMain (argc=2, argv=0x23792a0) at
postmaster.c:1127
#70 0x00000000006676ba in main (argc=2, argv=0x23792a0) at main.c:199

These pg_stat_statements entries are appear to be wrong, because all
of the associated executor instrumentation costs (like total_time)
aren't accumulating in the "top-level" entry. Also, while I realize
that this is rather hazy, it is arguably the case that the
subquery_planner preprocessing work shown here shouldn't be
instrumented by pg_stat_statements, at least for as long as
pg_stat_statements is supposed to instrument executor costs only.

--
Peter Geoghegan