Thread: pg_stat_statements produces multiple entries for a single query with track = 'top'
pg_stat_statements produces multiple entries for a single query with track = 'top'
From
Peter Geoghegan
Date:
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
Re: pg_stat_statements produces multiple entries for a single query with track = 'top'
From
Tom Lane
Date:
Peter Geoghegan <pg@heroku.com> writes:
> 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").
Isn't this just the behavior we decided we wanted for SQL-language
functions? At least, if we change pg_stat_statements so it doesn't
break out SQL-language functions, I'm sure somebody's gonna complain.
regards, tom lane
Re: pg_stat_statements produces multiple entries for a single query with track = 'top'
From
Peter Geoghegan
Date:
On Sat, Aug 10, 2013 at 5:45 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Isn't this just the behavior we decided we wanted for SQL-language > functions? At least, if we change pg_stat_statements so it doesn't > break out SQL-language functions, I'm sure somebody's gonna complain. Perhaps there was some discussion of this with Takahiro Itagaki, but I have no recollection of having been involved in or having followed a discussion about pg_stat_statements behavior with regards to SQL-language functions in particular. Actually, if Itagaki-san had discussed this, there is a reasonably good chance that I'd have read it before now. I can tell you that at the very least, this behavior does not seem consistent with the documentation: "pg_stat_statements.track controls which statements are counted by the module. Specify top to track top-level statements (those issued directly by clients), all to also track nested statements (such as statements invoked within functions), or none to disable statement statistics collection. The default value is top. Only superusers can change this setting." Clearly the statement "SELECT '6378168'::float8" was not directly issued by the client here. If this is the behavior we want for SQL functions, that is something that ought to be highlighted as a special case. -- Peter Geoghegan