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
