2ndquadrant / pg_stat_plans Goto Github PK

Probably for @klando:

There's currently an issue when building pg_stat_plans with pgxs.mk from PG 9.2 - during installation the path for the pgxs .control file gets resolved wrong, as seen in http://nopaste.narf.at/show/2330/.

I discussed a similar breakage with pgfincore in #postgresql-apt, no resolution yet.

When faced with a query_string that contains doubled/escaped single quotes these will be replaced with additional '?' placeholder characters. This causes issues when trying to identify identical query classes across stats resets.

 plantest=# select * from foo where data = 'bla';
 id | data 
----+------
(0 rows)

plantest=# select normalized_query, calls from pg_stat_plans_queries where dbid=152414;
                            normalized_query                             | calls 
-------------------------------------------------------------------------+-------
 select * from foo where data = ?;                                       |     1
 select pg_stat_plans_reset();                                           |     1
(3 rows)

plantest=# select pg_stat_plans_reset();
 pg_stat_plans_reset 
---------------------

(1 row)

plantest=# select * from foo where data = 'bl''a';
 id | data 
----+------
(0 rows)

plantest=# select normalized_query, calls from pg_stat_plans_queries where dbid=152414;
          normalized_query          | calls 
------------------------------------+-------
 select * from foo where data = ??; |     1
 select pg_stat_plans_reset();      |     1
(2 rows)

plantest=# select pg_stat_plans_reset();
 pg_stat_plans_reset 
---------------------

(1 row)

plantest=# select * from foo where data = 'b''l''a';
 id | data 
----+------
(0 rows)

plantest=# select normalized_query, calls from pg_stat_plans_queries where dbid=152414;
          normalized_query           | calls 
-------------------------------------+-------
 select * from foo where data = ???; |     1
 select pg_stat_plans_reset();       |     1
(2 rows)

plantest=# 

I surmise that it would be useful to add Debian build infrastructure for the pg_find_plans module, to match pg_stat_plans itself, but I myself don't feel capable of managing that process as a non-Debian user. Could you take a look at this? Thanks.

the current inclusion of pg_find_plans into pg_stat_plans is not helpful for packaging.

What about the following layout ?
├── debian
├── Makefile
├── pg_find_plans
│   └── Makefile
└── pg_stat_plans
└── Makefile

The top Makefile allows to builld with options like that :
make PG_STAT_PLANS=1 PG_FIND_PLANS=1 # (the default)
and each sub-Makefile works as usual.

Even if we don't want to keep the debian/ (and a rpm/ ?) I do prefer this layout.

OK ?

Hi,

we're pulling stats out of pg_stat_plans regularly and noticed that the query we use for collecting the data is very plan-heavy:

expl                | Function Scan on pg_stat_plans  (cost=2.50..20.00 rows=1 width=150)
                    |   Filter: ((planid = 3489937752::oid) AND (userid = 16395::oid) AND (dbid = 16397::oid))
userid              | 16395
dbid                | 16397
planid              | 4076277587
query               | SELECT *, query, pg_stat_plans_explain(planid, userid, dbid) AS explain
                    |                 FROM pg_stat_plans
                    |                 WHERE planid = 3489937752 AND userid = 16395 AND dbid = 16397
had_our_search_path | t
query_valid         | t
calls               | 1
total_time          | 1.258
rows                | 1
[..]

userid              | 16395
dbid                | 16397
plan_ids            | {4146301069,2169880341,3489937752,1911581122,4190361391,2097931610,1590027875,2924187966,23654543,240461192,4076277587}
calls_histogram     | {5,7,3,5,1,3,5,7,1,3,1}
avg_time_histogram  | {0.5406,0.241142857142857,0.814666666666667,0.482,0.498,0.928333333333333,0.3376,0.192142857142857,0.549,0.386333333333333,1.258}
normalize_query     | SELECT *, query, pg_stat_plans_explain(planid, userid, dbid) AS explain FROM pg_stat_plans WHERE planid = ? AND userid = ? AND dbid = ?
calls               | 41
total_time          | 18.527
[..]

Apparently pg_stat_plans generates a separate plan for each query - is this expected behaviour or something which you want to look into?

all the best,
Michael

I'm running pg_stat_plans fdbc2b3 against a Debian Postgres 9.1

9.1.6-1~bpo60+1 - from Debian backports

and I'm seeing this error:

FATAL:  unrecognized configuration parameter "pg_stat_plans.max"

Removing all pg_stat_plans configuration statements removes those errors and the extension seems to work fine otherwise.

Using Postgres 9.2 on a different server doesn't show this behaviour and works as expected.

I'm trying to build a deb package from git sources on a Debian 6.0.7 box and got the following error:

$ git reflog
6a94960 HEAD@{0}: clone: from https://github.com/2ndQuadrant/pg_stat_plans
$ make deb
Makefile:54: warning: overriding commands for target `install'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:129: warning: ignoring old commands for target `install'
Makefile:59: warning: overriding commands for target `installcontrol'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:137: warning: ignoring old commands for target `installcontrol'
Makefile:64: warning: overriding commands for target `installdata'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:142: warning: ignoring old commands for target `installdata'
Makefile:70: warning: overriding commands for target `installdocs'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:153: warning: ignoring old commands for target `installdocs'
Makefile:81: warning: overriding commands for target `installdirs'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:169: warning: ignoring old commands for target `installdirs'
make clean
make[1]: Entering directory `/var/tmp/pg_stat_plans/pg_stat_plans'
Makefile:54: warning: overriding commands for target `install'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:129: warning: ignoring old commands for target `install'
Makefile:59: warning: overriding commands for target `installcontrol'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:137: warning: ignoring old commands for target `installcontrol'
Makefile:64: warning: overriding commands for target `installdata'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:142: warning: ignoring old commands for target `installdata'
Makefile:70: warning: overriding commands for target `installdocs'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:153: warning: ignoring old commands for target `installdocs'
Makefile:81: warning: overriding commands for target `installdirs'
/usr/lib/postgresql/9.3/lib/pgxs/src/makefiles/pgxs.mk:169: warning: ignoring old commands for target `installdirs'
rm -f pg_stat_plans.so pg_stat_plans.o
rm -f pg_stat_plans--1.0.sql pg_stat_plans--unpackaged--1.0.sql
rm -rf pg_stat_plans.control
rm -rf results/ regression.diffs regression.out tmp_check/ log/
make[1]: Leaving directory `/var/tmp/pg_stat_plans/pg_stat_plans'
make -f debian/rules debian/control
make[1]: Entering directory `/var/tmp/pg_stat_plans/pg_stat_plans'
(set -e; \
    VERSIONS=`pg_buildext supported-versions /var/tmp/pg_stat_plans/pg_stat_plans` || exit $?; \
    grep-dctrl -vP PGVERSION debian/control.in > debian/control.pgxs_tmp; \
    for v in $VERSIONS; \
        do                                         \
        grep -q "^$v" debian/pgversions   \
        && grep-dctrl -P PGVERSION debian/control.in      \
        | sed -e "s:PGVERSION:$v:" >> debian/control.pgxs_tmp; \
    done; \
    mv debian/control.pgxs_tmp debian/control) || (rm -f debian/control.pgxs_tmp; exit 1)
make[1]: Leaving directory `/var/tmp/pg_stat_plans/pg_stat_plans'
dh clean
dh: No packages to build.
make -f debian/rules orig
make[1]: Entering directory `/var/tmp/pg_stat_plans/pg_stat_plans'
dh clean
dh: No packages to build.
git archive --prefix=pgstatplans-1.1/ -o ../pgstatplans_1.1.orig.tar.gz HEAD
make[1]: Leaving directory `/var/tmp/pg_stat_plans/pg_stat_plans'
debuild -us -uc -sa
 dpkg-buildpackage -rfakeroot -D -us -uc -sa
dpkg-buildpackage: warning: using a gain-root-command while being root
dpkg-buildpackage: source package pgstatplans
dpkg-buildpackage: source version 1.1
dpkg-buildpackage: source changed by Cédric Villemain <[email protected]>
 dpkg-source --before-build pg_stat_plans
dpkg-buildpackage: host architecture amd64
dpkg-source: error: pg_stat_plans/debian/control doesn't list any binary package
dpkg-buildpackage: error: dpkg-source --before-build pg_stat_plans gave error exit status 255
debuild: fatal error at line 1357:
dpkg-buildpackage -rfakeroot -D -us -uc -sa failed
make: *** [deb] Error 29

I've noticed these errors in a production environment which seem rather odd given the fact that the user doesn't handle/change the query string anywhere.

So far I haven't been able to reproduce it by hand, will give more input as soon as I've got more.

planid              | 238997
userid              | 16403
dbid                | 25450
query               | 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))
had_our_search_path | t
from_our_database   | t


atlas=# select pg_stat_plans_explain(238997,16403, 25450);
ERROR:  syntax error at end of input
LINE 1: ...ND ((places.category_id IS NULL OR places.category_id != 15)
                                                                      ^
QUERY:  EXPLAIN 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)

I fail to install pg_stat_plans, not sure how to proceed or if something's amiss:
Debian 6.0.7
PostgreSQL 9.3.2(Via official Postgresql-Repo)

root@host:~/pg_stat_plans-REL1_0_STABLE# make
cp pg_stat_plans.sql pg_stat_plans--1.0.sql
sed 's/DROP /ALTER EXTENSION pg_stat_plans ADD /' uninstall_pg_stat_plans.sql > pg_stat_plans--unpackaged--1.0.sql
gcc -g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat -Werror=format-security -fPIC -pie -I/usr/include/mit-krb5 -DLINUX_OOM_ADJ=0 -Wall -Wmissing-prototypes -Wpointer-arith -Wdeclaration-after-statement -Wendif-labels -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv -g -fpic -I. -I./ -I/usr/include/postgresql/9.3/server -I/usr/include/postgresql/internal -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE -I/usr/include/libxml2  -I/usr/include/tcl8.5  -c -o pg_stat_plans.o pg_stat_plans.c
pg_stat_plans.c: In function '_PG_init':
pg_stat_plans.c:444: warning: assignment from incompatible pointer type
pg_stat_plans.c: In function 'pgsp_ProcessUtility':
pg_stat_plans.c:905: error: incompatible type for argument 3 of 'prev_ProcessUtility'
pg_stat_plans.c:905: note: expected 'ProcessUtilityContext' but argument is of type 'ParamListInfo'
pg_stat_plans.c:905: warning: passing argument 4 of 'prev_ProcessUtility' from incompatible pointer type
pg_stat_plans.c:905: note: expected 'ParamListInfo' but argument is of type 'struct DestReceiver *'
pg_stat_plans.c:905: warning: passing argument 5 of 'prev_ProcessUtility' from incompatible pointer type
pg_stat_plans.c:905: note: expected 'struct DestReceiver *' but argument is of type 'char *'
pg_stat_plans.c:905: error: incompatible type for argument 6 of 'prev_ProcessUtility'
pg_stat_plans.c:905: note: expected 'char *' but argument is of type 'ProcessUtilityContext'
pg_stat_plans.c:908: error: incompatible type for argument 3 of 'standard_ProcessUtility'
/usr/include/postgresql/9.3/server/tcop/utility.h:36: note: expected 'ProcessUtilityContext' but argument is of type 'ParamListInfo'
pg_stat_plans.c:908: warning: passing argument 4 of 'standard_ProcessUtility' from incompatible pointer type
/usr/include/postgresql/9.3/server/tcop/utility.h:36: note: expected 'ParamListInfo' but argument is of type 'struct DestReceiver *'
pg_stat_plans.c:908: warning: passing argument 5 of 'standard_ProcessUtility' from incompatible pointer type
/usr/include/postgresql/9.3/server/tcop/utility.h:36: note: expected 'struct DestReceiver *' but argument is of type 'char *'
pg_stat_plans.c:908: error: incompatible type for argument 6 of 'standard_ProcessUtility'
/usr/include/postgresql/9.3/server/tcop/utility.h:36: note: expected 'char *' but argument is of type 'ProcessUtilityContext'
make: *** [pg_stat_plans.o] Error 1

the current Makefile and README filename produce an anonym filename (README.rst) thus after 'make install' stage, it is not possible to know that this file is relative to pg_stat_plans without viewing its content.

i.e. an 'ls -1' in the postgresql extension directory produces:

./README.rst
./pgchess-QUICKSTART.md
....

3 options at least:

• use MODULEDIR and update the Makefile
• rename filename during 'make'
• rename filename

Hello,
Clearly i am doing something incorrect. I copied the pg_stat_plans folder structure under contrib of my PostgreSQL 9.2.3 instance, which i have built from source.

I tried to make from the pg_stat_plans folder. Got error related to pg_config not being present (or not on path). So i installed yum install postgresql-devel.

Now on make i get lost of compiler errors like

pg_stat_plans.c:186: error: expected ‘=’, ‘,’, ‘;’, ‘asm’ or ‘attribute’ before ‘prev_ProcessUtility’
pg_stat_plans.c:210: error: ‘EXPLAIN_FORMAT_TEXT’ undeclared here (not in a function)
pg_stat_plans.c:211: error: ‘EXPLAIN_FORMAT_XML’ undeclared here (not in a function)
pg_stat_plans.c:212: error: ‘EXPLAIN_FORMAT_JSON’ undeclared here (not in a function)
pg_stat_plans.c:213: error: ‘EXPLAIN_FORMAT_YAML’ undeclared here (not in a function)

What am i doing wrong? Is it the wrong version of postgresql-devel being installed (i can see its 8.4.13

I am using Centos 6.2

regards
Sameer

Are we planning on updating this for 9.5 and 9.6?

(Or merging into pg_stat_statements) ?

We noticed that many applications generate variable-sized lists for bulk modification of result sets which can lead to many separate normalized_queries although they belong to the same statement (class).

 DELETE FROM "post_taggings" WHERE post_id = ? AND tag_id IN (?)
 DELETE FROM "post_taggings" WHERE post_id = ? AND tag_id IN (?,?)
 DELETE FROM "post_taggings" WHERE post_id = ? AND tag_id IN (?,?,?)
 DELETE FROM "post_taggings" WHERE post_id = ? AND tag_id IN (?,?,?,?)
[..31 total variations of this query were recorded..]

A quick test showed that this seems to be related to the fact that the cases "has one list member" and "has many list members" are hashed to different plans though the normalized_query is recorded for the exact number of elements the first "has many list members" query used. This causes problems on databases where pg_stat_plans are reset on a regular basis.

plantest=# select normalized_query, calls from pg_stat_plans_queries where dbid=152414 and normalized_query like 'select id%';
 normalized_query | calls 
------------------+-------
(0 rows)

plantest=# select id from foo where id in (10, 100, 1000, 10000, 10000, 43, 543, 62, 745, 124);
  id   
-------
    10
    43
    62
   100
   124
   543
   745
  1000
 10000
(9 rows)

plantest=# select id from foo where id in (10, 100);
 id  
-----
  10
 100
(2 rows)

plantest=# select id from foo where id in (10, 100, 1000);
  id  
------
   10
  100
 1000
(3 rows)

plantest=# select id from foo where id in (10, 100);
 id  
-----
  10
 100
(2 rows)

plantest=# select id from foo where id in (10, 100, 1000);
  id  
------
   10
  100
 1000
(3 rows)

plantest=# select id from foo where id in (10);
 id 
----
 10
(1 row)


plantest=# select normalized_query, calls from pg_stat_plans_queries where dbid=152414 and normalized_query like 'select id%';
                        normalized_query                        | calls 
----------------------------------------------------------------+-------
 select id from foo where id in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?); |     5
 select id from foo where id in (?);                            |     1
(2 rows)

plantest=# select pg_stat_plans_reset();
 pg_stat_plans_reset 
---------------------

(1 row)

plantest=# select normalized_query, calls from pg_stat_plans_queries where dbid=152414 and normalized_query like 'select id%';
 normalized_query | calls 
------------------+-------
(0 rows)

plantest=# select id from foo where id in (10, 100);
 id  
-----
  10
 100
(2 rows)

plantest=# select id from foo where id in (10, 100, 1000);
  id  
------
   10
  100
 1000
(3 rows)

plantest=# select id from foo where id in (10, 100, 1000, 10000);
  id   
-------
    10
   100
  1000
 10000
(4 rows)

plantest=# select id from foo where id in (10, 100, 1000, 10000, 10000, 43, 543, 62, 745, 124);
  id   
-------
    10
    43
    62
   100
   124
   543
   745
  1000
 10000
(9 rows)

plantest=# select id from foo where id in (10);
 id 
----
 10
(1 row)

plantest=# select id from foo where id in (10);
 id 
----
 10
(1 row)

plantest=# select normalized_query, calls from pg_stat_plans_queries where dbid=152414 and normalized_query like 'select id%';
            normalized_query            | calls 
----------------------------------------+-------
 select id from foo where id in (?, ?); |     4
 select id from foo where id in (?);    |     2
(2 rows)

plantest=# 

Would it be feasible to compact lists with more than two placeholders to just two in the normalized_query?

If not, it'd be a good if we could add this to a "Limitations" section in the documentation.

Hello,
I was comparing pg_stat_plans with oracle’s statspack which provides plan statistics (at level 6). Does pg_stat_plans provide plan node level statistics like statspack? Explain analyze already has statistics like estimated startup cost, estimated total cost, estimated number of rows retrieved, actual startup time, actual total time, total runtime and actual number of rows retrieved , per node. Would this be useful for pg_stat_plans to have in its view?
Regards
Sameer

Hi,

I'd like to install your contribution on my Postgres 9.6 which runs on Windows X.64 but it seems not to be detailed in your readme.

Could you help me please ?

Best regards.

Hello,
I have read with interest informations about pg_stat_plans.

pg_stat_statements needs improvments to be plan aware, and be able to catch initial constants and parameters (per plan).

What would you think about adding pg_stat_plans planid into the key of pg_stat_statements that would become:
dbid,
userid,
queryid,
+planid
function JumblePlan could be reused (I will try to do it, but I'm just dba not developer).

A GUC plan_tracking = none: would disable this feature, for those afraid of collecting too much informations.

Doing this would permit later, to collect constants and parameters as proposed in
http://www.postgresql-archive.org/Sample-values-for-pg-stat-statements-td5998728.html#none
on a per queryid/planid basis.

All informations needed to rebuild the explain command would be available again (on a query/plan basis ;o)

Patch proposed in http://www.postgresql-archive.org/FEATURE-PATCH-pg-stat-statements-with-plans-td5940964.html could even be simplified to collect one plan per line ...

More info in http://www.postgresql-archive.org/pg-stat-statements-HLD-for-futur-developments-td6012381.html

Expecting your feedback.
Regards
PAscal

It seems as if queries using the earthdistance extension can't be explained by pg_stat_plans.

Test data set: https://gist.github.com/4665854

Tested on PostgreSQL 9.1.7 with pg_stat_plans REL1_0_STABLE

test=# SELECT * FROM test  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1]));
 id |      coordinate       
----+-----------------------
  3 | (46.5854,14.7956)
  4 | (46.586926,14.796106)
(2 rows)

test=# \x
Expanded display is on.
test=# select * from pg_stat_plans where query like 'SELECT % FROM test%';
-[ RECORD 1 ]-------+------------------------------------------------------------------------------------------------------------------------------------------
planid              | 2039753839
userid              | 16384
dbid                | 17743
query               | SELECT * FROM test  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1]));
had_our_search_path | t
from_our_database   | t
query_explainable   | t
calls               | 7
total_time          | 4.798
rows                | 10
shared_blks_hit     | 45
shared_blks_read    | 0
shared_blks_written | 0
local_blks_hit      | 0
local_blks_read     | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 
blk_write_time      | 
last_startup_cost   | 0
last_total_cost     | 437.875

test=# select * from pg_stat_plans_explain(2039753839,  16384, 17743);
WARNING:  Existing pg_stat_plans entry planid (2039753839) differs from new plan for query (3608718488).
-[ RECORD 1 ]---------+-
pg_stat_plans_explain | 

test=# \x
Expanded display is off.
test=# SELECT * FROM test  WHERE (earth_box(ll_to_earth(46.5845336914063, 14.7958154678345), 300) @> ll_to_earth(coordinate[0], coordinate[1]));
NOTICE:  updated pg_stat_plans query string of entry 2039753839
 id |      coordinate       
----+-----------------------
  3 | (46.5854,14.7956)
  4 | (46.586926,14.796106)
(2 rows)

test=#  

The new maintainer for life of pg_stat_plans' Debian infrastructure, Cédric Villemain, didn't include an appropriate doc patch along with his earlier pull request.

While rolling out pg_stat_plans on more databases I noticed problems with queries containing dropped relations:

bacula=# select * from pg_stat_plans where planid = 1305572066;
-[ RECORD 1 ]-------+---------------------------------------------------------------------------------
planid              | 1305572066
userid              | 16384
dbid                | 16386
query               | SELECT DISTINCT DelCandidates.JobId,DelCandidates.PurgedFiles FROM DelCandidates
had_our_search_path | t
from_our_database   | t
query_explainable   | t
calls               | 1
total_time          | 0.013
rows                | 2
shared_blks_hit     | 0
shared_blks_read    | 0
shared_blks_written | 0
local_blks_hit      | 1
local_blks_read     | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 
blk_write_time      | 
last_startup_cost   | 34.9
last_total_cost     | 36.9

bacula=# \d DelCandidates
Did not find any relation named "DelCandidates".
bacula=# select pg_stat_plans_explain(1305572066, 16384, 16386);
ERROR:  relation "delcandidates" does not exist
LINE 1: ...elCandidates.JobId,DelCandidates.PurgedFiles FROM DelCandida...
                                                             ^
QUERY:  EXPLAIN SELECT DISTINCT DelCandidates.JobId,DelCandidates.PurgedFiles FROM DelCandidates
bacula=# 

Is it possible to set query_explainable to false for queries where one of the needed relations doesn't exist anymore/at the moment?

During testing I saw plans from foreign DBs leak into pg_stat_plans, e.g. when running the following query:

SELECT pg_stat_plans_explain(planid, userid, dbid) AS expl, * FROM pg_stat_plans WHERE query NOT ILIKE 'EXPLAIN%' AND query NOT ILIKE 'copy%';

I got a

ERROR: pg_stat_plans cannot explain query from another database

Limiting the query to the OID of the current database was a sufficient band-aid but this is probably something that should be fixed in the module ;)

I discovered a problem with pg_stat_plans_explain(planid).

The explain clause has the same plan as the original clause.
That's as expected.
So sometimes using pg_stat_plans_explain(planid) results in a substitution
of the sample query by the corresponding explain clause (when
revalidating/updating the query).

That's surprising, but the problem is, that you can no longer use
pg_stat_plans_explain on that entry, because it results in
an explain explain error.

This unwanted behaviour should be fixed by

• not updating or revalidating a plan with an explain query

or at least

• simply truncating the "explain" prefix when inserting the statement into the column.

or

• teaching pg_stat_plans_explain to truncate the explain prefix when evaluating

The actual behaviour has also to be called a BUG, because there are corner
cases
(see example below ) in which this behaviour leads to a syntax error of pg_stat_plans.

database1=# SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS
VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE,
AGGREGATE.AUTORELATIONID
FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE,
AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID,
BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM
AUTOREL_AREA_HAS_PUBL_NAVIGATE,
BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION =
BNF_PUBLICATION.ID AND BNF_PUBLICATION.C_STATUS_VISIBLE=TRUE ) AGGREGATE
ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS
LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 OFFSET 0;

database1=# select *,pg_stat_plans_explain(planid) from pg_stat_plans where
query like 'SELECT D%';
-[ RECORD 1
]---------+----------------------------------------------------------------------------------------------------------------------------------------------------------------
planid | 2936400263
userid | 10
dbid | 16385
query | SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE, AGGREGATE.AUTORELATIONID
| FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE,
| AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID, BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM AUTOREL_AREA_HAS_PUBL_NAVIGATE,
| BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION = BNF_PUBLICATION.ID AND BNF_PUBLICATION.C_STATUS_VISIBLE=TRUE ) AGGREGATE
| ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 OFFSET 0;
had_our_search_path | t
from_our_database | t
query_explainable | t
calls | 5
total_time | 0.735
rows | 30
shared_blks_hit | 234
shared_blks_read | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
last_startup_cost | 0
last_total_cost | 10.6211277959583
pg_stat_plans_explain | Limit (cost=0.00..10.62 rows=10 width=12)
| -> Unique (cost=0.00..62964.17 rows=59282 width=12)
| -> Nested Loop (cost=0.00..62418.30 rows=109173 width=12)
| -> Index Scan using arns_bnf_pub_2_idx on bnf_publication (cost=0.00..36002.73 rows=59282 width=8)
| Filter: c_status_visible
| -> Index Scan using idx_autorel_area_has_publ_navigate_bnf_publication on autorel_area_has_publ_navigate (cost=0.00..0.41 rows=2 width=8)
| Index Cond: (bnf_publication = bnf_publication.id)

database1=# set enable_indexscan=false;
SET
database1=# SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE, AGGREGATE.AUTORELATIONID
FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE, AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID,
BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM
AUTOREL_AREA_HAS_PUBL_NAVIGATE, BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION = BNF_PUBLICATION.ID AND BNF_PUBLICATION.C_STATUS_VISIBLE=TRUE ) AGGREGATE
ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS
LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 OFFSET 0;

database1=# select *,pg_stat_plans_explain(planid) from pg_stat_plans where
query like 'SELECT D%';
WARNING: Existing pg_stat_plans entry planid (2936400263) differs from new
plan for query (1373001957).
-[ RECORD 1
]---------+----------------------------------------------------------------------------------------------------------------------------------------------------------------
planid | 1373001957
userid | 10
dbid | 16385
query | SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE, AGGREGATE.AUTORELATIONID
| FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE,
| AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID, BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM AUTOREL_AREA_HAS_PUBL_NAVIGATE,
| BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION = BNF_PUBLICATION.ID AND BNF_PUBLICATION.C_STATUS_VISIBLE=TRUE ) AGGREGATE
| ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 OFFSET 0;
had_our_search_path | t
from_our_database | t
query_explainable | t
calls | 1
total_time | 1677.555
rows | 10
shared_blks_hit | 9534
shared_blks_read | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_written | 0
temp_blks_read | 217
temp_blks_written | 860
blk_read_time | 0
blk_write_time | 0
last_startup_cost | 27218.575446009
last_total_cost | 27218.7135650839
pg_stat_plans_explain | Limit (cost=27218.58..27218.71 rows=10 width=12)
| -> Unique (cost=27218.58..28037.37 rows=59282 width=12)
| -> Sort (cost=27218.58..27491.51 rows=109173 width=12)
| Sort Key: (upper(((bnf_publication.publication_year)::character varying(4000))::text)), bnf_publication.id
| -> Hash Join (cost=9922.33..16213.84 rows=109173 width=12)
| Hash Cond: (autorel_area_has_publ_navigate.bnf_publication = bnf_publication.id)
| -> Seq Scan on autorel_area_has_publ_navigate (cost=0.00..2524.55 rows=140755 width=8)
| -> Hash (cost=9181.31..9181.31 rows=59282 width=8)
| -> Seq Scan on bnf_publication (cost=0.00..9181.31 rows=59282 width=8)
| Filter: c_status_visible
-[ RECORD 2
]---------+----------------------------------------------------------------------------------------------------------------------------------------------------------------
planid | 2936400263
userid | 10
dbid | 16385
query | SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE, AGGREGATE.AUTORELATIONID
| FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE,
| AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID, BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM AUTOREL_AREA_HAS_PUBL_NAVIGATE,
| BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION = BNF_PUBLICATION.ID AND BNF_PUBLICATION.C_STATUS_VISIBLE=TRUE ) AGGREGATE
| ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 OFFSET 0;
had_our_search_path | t
from_our_database | t
query_explainable | t
calls | 6
total_time | 0.735
rows | 30
shared_blks_hit | 234
shared_blks_read | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
last_startup_cost | 0
last_total_cost | 10.6211277959583
pg_stat_plans_explain |

database1=# set enable_indexscan=true;
SET
database1=# select *,pg_stat_plans_explain(planid) from pg_stat_plans where
query like 'SELECT D%';
NOTICE: updated pg_stat_plans query string of entry 2936400263
CONTEXT: SQL statement "EXPLAIN SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE, AGGREGATE.AUTORELATIONI
FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE, AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID,
BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM AUTOREL_AREA_HAS_PUBL_NAVIGATE, BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION = BNF_PUBLIC
ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 OFFSET 0;"
WARNING: Existing pg_stat_plans entry planid (1373001957) differs from new plan for query (2936400263).
ERROR: syntax error at or near "EXPLAIN"
LINE 1: EXPLAIN EXPLAIN SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PU...
^
QUERY: EXPLAIN EXPLAIN SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE, AGGREGATE.AUTORELATIONID
FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE, AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID,
BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM AUTOREL_AREA_HAS_PUBL_NAVIGATE,
BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION = BNF_PUBLICATION.ID AND BNF_PUBLICATION.C_STATUS_VISIBLE=TRUE ) AGGREGATE
ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS
LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 O
database1=# select *,pg_stat_plans_explain(planid) from pg_stat_plans where
query like 'SELECT D%';
-[ RECORD 1
]---------+----------------------------------------------------------------------------------------------------------------------------------------------------------------
planid | 1373001957
userid | 10
dbid | 16385
query | SELECT DISTINCT ON (UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) ,AGGREGATE.INFOOBJECT2ID) AGGREGATE.AUTORELATIONTYPE, AGGREGATE.AUTORELATIONID
| FROM (SELECT 'AUTOREL_AREA_HAS_PUBL_NAVIGATE'::TEXT AS AUTORELATIONTYPE,
| AUTOREL_AREA_HAS_PUBL_NAVIGATE.ID AS AUTORELATIONID, BNF_PUBLICATION.PUBLICATION_YEAR, BNF_PUBLICATION.ID AS INFOOBJECT2ID FROM AUTOREL_AREA_HAS_PUBL_NAVIGATE,
| BNF_PUBLICATION WHERE AUTOREL_AREA_HAS_PUBL_NAVIGATE.BNF_PUBLICATION = BNF_PUBLICATION.ID AND BNF_PUBLICATION.C_STATUS_VISIBLE=TRUE ) AGGREGATE
| ORDER BY UPPER(CAST (AGGREGATE.PUBLICATION_YEAR AS VARCHAR(4000))) DESC NULLS LAST , AGGREGATE.INFOOBJECT2ID LIMIT 10 OFFSET 0;
had_our_search_path | t
from_our_database | t
query_explainable | f
calls | 3
total_time | 1677.555
rows | 10
shared_blks_hit | 9534
shared_blks_read | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_written | 0
temp_blks_read | 217
temp_blks_written | 860
blk_read_time | 0
blk_write_time | 0
last_startup_cost | 27218.575446009
last_total_cost | 27218.7135650839
pg_stat_plans_explain |

This query got flagged as explainable where it actually isn't:

rblwatch=# select * from pg_stat_plans where planid = 3358764821;
-[ RECORD 1 ]-------+------------------------------------------------------------------------------
userid              | 16391
dbid                | 16401
planid              | 3358764821
query               | INSERT INTO sessions (a_session,id)  SELECT $1, $2 
                    |                 WHERE NOT EXISTS (SELECT 1 FROM sessions WHERE id=$3 LIMIT 1)
had_our_search_path | t
from_our_database   | t
query_explainable   | t
calls               | 1
total_time          | 0.231
rows                | 1
shared_blks_hit     | 2
shared_blks_read    | 5
shared_blks_written | 0
local_blks_hit      | 0
local_blks_read     | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 
blk_write_time      | 
last_startup_cost   | 8.26818
last_total_cost     | 8.29068

rblwatch=# select pg_stat_plans_explain(3358764821, 16391, 16401);
NOTICE:  Cannot explain prepared query (planid: 3358764821)
-[ RECORD 1 ]---------+-
pg_stat_plans_explain | 

rblwatch=# 

Example:

foo=# select * from pg_stat_plans where planid = 4291451842;
-[ RECORD 1 ]-------+-------------------------------------------------------------------
planid              | 4291451842
userid              | 16384
dbid                | 126346
query               | insert into test(foo) values(7); insert into test(foo) values(11);
had_our_search_path | t
from_our_database   | t
query_explainable   | t
calls               | 12
total_time          | 0.532
rows                | 12
shared_blks_hit     | 65
shared_blks_read    | 1
shared_blks_written | 0
local_blks_hit      | 0
local_blks_read     | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 0
blk_write_time      | 0
last_startup_cost   | 0
last_total_cost     | 0.015

foo=# truncate table test;
TRUNCATE TABLE
foo=# select * from test;
(No rows)
foo=# select pg_stat_plans_explain(4291451842, 16384, 126346);
-[ RECORD 1 ]---------+-------------------------------------------------
pg_stat_plans_explain | Insert on test  (cost=0.00..0.01 rows=1 width=0)
                      |   ->  Result  (cost=0.00..0.01 rows=1 width=0)

foo=# select * from test;
-[ RECORD 1 ]
id  | 82
foo | 11

To reproduce:

Generate a multi-statement entry in pg_stat_plans, e.g. with python/psycopg2. Doesn't seem to work from within psql.

#!/usr/bin/env python
import psycopg2

conn = psycopg2.connect("dbname='foo'")
curs = conn.cursor()

query = 'insert into test(foo) values(7); insert into test(foo) values(11);'
curs.execute(query)
conn.commit()

pg_stat_plans_explain will execute everything after the first semicolon/query literal.