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.