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 -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs