Waiting for PostgreSQL 13 – Allow pg_stat_statements to track planning statistics.

On 2nd of April 2020, Fujii Masao committed patch:

Allow pg_stat_statements to track planning statistics.
 
This commit makes pg_stat_statements support new GUC
pg_stat_statements.track_planning. If this option is enabled,
pg_stat_statements tracks the planning statistics of the statements,
e.g., the number of times the statement was planned, the total time
spent planning the statement, etc. This feature is useful to check
the statements that it takes a long time to plan. Previously since
pg_stat_statements tracked only the execution statistics, we could
not use that for the purpose.
 
The planning and execution statistics are stored at the end of
each phase separately. So there are not always one-to-one relationship
between them. For example, if the statement is successfully planned
but fails in the execution phase, only its planning statistics are stored.
This may cause the users to be able to see different pg_stat_statements
results from the previous version. To avoid this,
pg_stat_statements.track_planning needs to be disabled.
 
This commit bumps the version of pg_stat_statements to 1.8
since it changes the definition of pg_stat_statements function.
 
Author: Julien Rouhaud, Pascal Legrand, Thomas Munro, Fujii Masao
Reviewed-by: Sergei Kornilov, Tomas Vondra, Yoshikazu Imai, Haribabu Kommi, Tom Lane
Discussion: https://postgr.es/m/CAHGQGwFx_=DO-Gu-MfPW3VQ4qC7TfVdH2zHmvZfrGv6fQ3D-Tw@mail.gmail.com
Discussion: https://postgr.es/m/CAEepm=0e59Y_6Q_YXYCTHZkqOc6H2pJ54C_Xe=VFu50Aqqp_sA@mail.gmail.com
Discussion: https://postgr.es/m/DB6PR0301MB21352F6210E3B11934B0DCC790B00@DB6PR0301MB2135.eurprd03.prod.outlook.com

This is pretty interesting addition.

In case you're not familiar with pg_stat_statements, I already wrote about it couple times, but to summarize:

pg_stat_statements is a way to gather data about queries that are being run in system, live, without parsing logs, and their frequencies, runtimes, and other interesting details.

For example, after short run of pgbench, I saw this in pg_stat_statements view:

=$ SELECT * FROM pg_stat_statements;
 userid |  dbid  |       queryid        |                                                                                                                                                                                                                                       query                                                                                                                                                                                                                                       | calls |     total_time      |       min_time       |      max_time       |       mean_time       |      stddev_time      | ROWS  | shared_blks_hit | shared_blks_read | shared_blks_dirtied | shared_blks_written | local_blks_hit | local_blks_read | local_blks_dirtied | local_blks_written | temp_blks_read | temp_blks_written |   blk_read_time   |   blk_write_time   
--------+--------+----------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-------+---------------------+----------------------+---------------------+-----------------------+-----------------------+-------+-----------------+------------------+---------------------+---------------------+----------------+-----------------+--------------------+--------------------+----------------+-------------------+-------------------+--------------------
  16384 | 213574 |  1528036498366730309 | SELECT COUNT(*) FROM pgbench_branches                                                                                                                                                                                                                                                                                                                                                                                                                                             |     1 |            0.080677 |             0.080677 |            0.080677 |              0.080677 |                     0 |     1 |               0 |                1 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |          0.045557 |                  0
  16384 | 213574 | -7810315603562552972 | END                                                                                                                                                                                                                                                                                                                                                                                                                                                                               | 75913 |  55.189817000000474 |             0.000207 |            0.200031 | 0.0007270140423906334 |  0.001036331873328551 |     0 |               0 |                0 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |                 0 |                  0
  16384 | 213574 |  5221567155341688057 | TRUNCATE pgbench_history                                                                                                                                                                                                                                                                                                                                                                                                                                                          |     1 |            0.656542 |             0.656542 |            0.656542 |              0.656542 |                     0 |     0 |              28 |                2 |                   3 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |          0.048828 |                  0
  16384 | 213574 | -7483822449832044767 | INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, $4, CURRENT_TIMESTAMP)                                                                                                                                                                                                                                                                                                                                                                              | 75913 |   746.8780199999978 |             0.003252 |            1.649139 |  0.009838604982018821 |  0.010165520038001424 | 75913 |           76948 |                3 |                 487 |                 484 |              0 |               0 |                  0 |                  0 |              0 |                 0 |          0.070479 |                  0
  16384 | 213574 | -4512096390299907748 | UPDATE pgbench_tellers SET tbalance = tbalance + $1 WHERE tid = $2                                                                                                                                                                                                                                                                                                                                                                                                                | 75913 |   2787.561809000009 |             0.006353 |   4.659622000000001 |   0.03672048014174055 |    0.1034057813045188 | 75913 |          181678 |                4 |                  11 |                  12 |              0 |               0 |                  0 |                  0 |              0 |                 0 |           0.01175 |           0.035473
  16384 | 213574 | -1614386264847048523 | UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2                                                                                                                                                                                                                                                                                                                                                                                                               | 75913 |   3391.766052000024 | 0.010485999999999999 |            1.071065 |   0.04467964712236373 |   0.03074104085931909 | 75913 |          355192 |            27373 |               26125 |                  29 |              0 |               0 |                  0 |                  0 |              0 |                 0 | 334.0887610000027 | 0.4398329999999999
  16384 | 213574 |  2397681704071010949 | BEGIN                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | 75913 |  59.050520000000425 |              0.00021 |            0.301199 | 0.0007778709838894488 | 0.0013105859739122624 |     0 |               0 |                0 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |                 0 |                  0
  16384 | 213574 |  2867466858828855328 | SELECT abalance FROM pgbench_accounts WHERE aid = $1                                                                                                                                                                                                                                                                                                                                                                                                                              | 75913 |  1162.1739000000034 |             0.005403 |            1.038759 |   0.01530928694689983 |   0.01210388702456257 | 75913 |          303787 |                0 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |                 0 |                  0
  16384 | 213574 | -8617639074358654804 | vacuum pgbench_branches                                                                                                                                                                                                                                                                                                                                                                                                                                                           |     1 |           11.318629 |            11.318629 |           11.318629 |             11.318629 |                     0 |     0 |              29 |                8 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |          0.151321 |                  0
  16384 | 213574 | -5576532180744688992 | UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2                                                                                                                                                                                                                                                                                                                                                                                                               | 75913 |   6771.785966000003 |             0.006146 |           17.274356 |   0.08920456267042602 |    0.2781169359122826 | 75913 |          296343 |                4 |                  11 |                   5 |              0 |               0 |                  0 |                  0 |              0 |                 0 |           0.01181 |                  0
  16384 | 213574 |  4805478070118328992 | SELECT * FROM pg_stat_statements  ORDER BY total_time DESC LIMIT $1                                                                                                                                                                                                                                                                                                                                                                                                               |     1 |            0.325937 |             0.325937 |            0.325937 |              0.325937 |                     0 |     1 |               3 |                0 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |                 0 |                  0
  16384 | 213574 | -7867914320238269358 | SELECT o.n, p.partstrat, pg_catalog.count(i.inhparent) FROM pg_catalog.pg_class AS c JOIN pg_catalog.pg_namespace AS n ON (n.oid = c.relnamespace) CROSS JOIN lateral (SELECT pg_catalog.array_position(pg_catalog.current_schemas($1), n.nspname)) AS o(n) LEFT JOIN pg_catalog.pg_partitioned_table AS p ON (p.partrelid = c.oid) LEFT JOIN pg_catalog.pg_inherits AS i ON (c.oid = i.inhparent) WHERE c.relname = $2 AND o.n IS NOT NULL GROUP BY 1, 2 ORDER BY 1 ASC LIMIT $3 |     1 |            0.687725 |             0.687725 |            0.687725 |              0.687725 |                     0 |     1 |              48 |                2 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |          0.057466 |                  0
  16384 | 213574 |  -659047027458955830 | vacuum pgbench_tellers                                                                                                                                                                                                                                                                                                                                                                                                                                                            |     1 |            1.503077 |             1.503077 |            1.503077 |              1.503077 |                     0 |     0 |              56 |                7 |                   6 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |          0.166706 |                  0
  16384 | 213574 | -8199151692010160372 | SELECT pg_stat_statements_reset()                                                                                                                                                                                                                                                                                                                                                                                                                                                 |     1 | 0.19463999999999998 |  0.19463999999999998 | 0.19463999999999998 |   0.19463999999999998 |                     0 |     1 |               0 |                0 |                   0 |                   0 |              0 |               0 |                  0 |                  0 |              0 |                 0 |                 0 |                  0
(14 ROWS)

That's lots of data. So, let's just see what used the most time:

=$ SELECT * FROM pg_stat_statements  ORDER BY total_time DESC LIMIT 1 \gx
-[ RECORD 1 ]-------+--------------------------------------------------------------------
userid              | 16384
dbid                | 213574
queryid             | -5576532180744688992
query               | UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
calls               | 75913
total_time          | 6771.785966000003
min_time            | 0.006146
max_time            | 17.274356
mean_time           | 0.08920456267042602
stddev_time         | 0.2781169359122826
ROWS                | 75913
shared_blks_hit     | 296343
shared_blks_read    | 4
shared_blks_dirtied | 11
shared_blks_written | 5
local_blks_hit      | 0
local_blks_read     | 0
local_blks_dirtied  | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 0.01181
blk_write_time      | 0

We can see that the most time consuming query was update to pgbench_branches. But it doesn't mean it was slow – it was run nearly 76000 times, so it means that on average it only took ~ 0.089 millisecond. Not bad.

Now, new version provides more information:

=$ SELECT * FROM pg_stat_statements ORDER BY total_exec_time + total_plan_time DESC LIMIT 1 \gx
-[ RECORD 1 ]-------+--------------------------------------------------------------------
userid              | 16384
dbid                | 213517
queryid             | -5428533950522404423
query               | UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
plans               | 76715
total_plan_time     | 2727.7960879999746
min_plan_time       | 0.013777
max_plan_time       | 0.561776
mean_plan_time      | 0.03555753226878675
stddev_plan_time    | 0.02581172109879902
calls               | 76715
total_exec_time     | 6954.284728000057
min_exec_time       | 0.006161
max_exec_time       | 16.451219
mean_exec_time      | 0.0906509121814502
stddev_exec_time    | 0.29677854996837444
ROWS                | 76715
shared_blks_hit     | 258295
shared_blks_read    | 0
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit      | 0
local_blks_read     | 0
local_blks_dirtied  | 0
local_blks_written  | 0
temp_blks_read      | 0
temp_blks_written   | 0
blk_read_time       | 0
blk_write_time      | 0

We now have separate total, min, max, mean, and stddev for planning and executing.

Interestingly – we see that pgbench planned each query – it didn't reuse plans. And that it took 2.7 second over ~ 7 seconds of execution.

This is not much, and we can live with it. But there are cases like this one, where planning took over 10 times as long as execution. So having this information will be very useful.

Thanks a lot to all involved.

Leave a Reply

Your email address will not be published.

This site uses Akismet to reduce spam. Learn how your comment data is processed.