PostgreSQL: Quickly Detecting Slow Queries

Preamble

Installing pg_stat_statements in PostgreSQL

As mentioned above, pg_stat_statements comes as part of PostgreSQL. To get the most out of this very useful extension, all you have to do is turn it on.

The first thing you have to do is change shared_preload_libraries in postgresql.conf:

shared_preload_libraries = ‘pg_stat_statements’

Then restart PostgreSQL.
Finally, you can enable the module in the database of your choice:

 test=# CREATE EXTENSION pg_stat_statements; CREATE EXTENSION

The last step will be to deploy a view—we will need to inspect the data collected by the pg_stat_statements machinery.

Taking a look at pg_stat_statements

pg_stat_statementsoffers a wealth of insightful information. According to PostgreSQL 13, this is what a view is. Note that the view has been growing over the years and more and more vital information is added as PostgreSQL is steadily extended:

 test=# \d pg_stat_statements View "public.pg_stat_statements" Column | Type | Collation | Nullable | Default ---------------------+------------------+-----------+----------+--------- userid | oid | | | dbid | oid | | | queryid | bigint | | | query | text | | | plans | bigint | | | total_plan_time | double precision | | | min_plan_time | double precision | | | max_plan_time | double precision | | | mean_plan_time | double precision | | | stddev_plan_time | double precision | | | calls | bigint | | | total_exec_time | double precision | | | min_exec_time | double precision | | | max_exec_time | double precision | | | mean_exec_time | double precision | | | stddev_exec_time | double precision | | | rows | bigint | | | shared_blks_hit | bigint | | | shared_blks_read | bigint | | | shared_blks_dirtied | bigint | | | shared_blks_written | bigint | | | local_blks_hit | bigint | | | local_blks_read | bigint | | | local_blks_dirtied | bigint | | | local_blks_written | bigint | | | temp_blks_read | bigint | | | temp_blks_written | bigint | | | blk_read_time | double precision | | | blk_write_time | double precision | | | wal_records | bigint | | | wal_fpi | bigint | | | wal_bytes | numeric | | | ...

The danger here is that people get lost in the sheer volume of information. It makes sense to process this data a little bit in order to extract useful information.

Making use of the data

To make it easier for our readers to extract as much information as possible from pg_stat_statements, we have compiled a couple of queries that we have found useful over the years.

The most important one is used to find out which operations are the most time-consuming. Here is the query:

 test=# SELECT substring (query, 1, 30, AS query, calls, round(total_exec_time::numeric, 2) AS total_time, round(mean_exec_time::numeric, 2) AS mean_time, round((100 * total_exec_time / sum(total_exec_time) OVER ())::numeric, 2) AS percentage FROM pg_stat_statements ORDER BY total_exec_time DESC LIMIT 10; query | calls | total_time | mean_time | percentage --------------------------------+-------+------------+-----------+------------ UPDATE pgbench_tellers SET tba | 97609 | 102212.40 | 1.05 | 51.94 UPDATE pgbench_branches SET bb | 97609 | 88689.63 | 0.91 | 45.07 UPDATE pgbench_accounts SET ab | 97609 | 3183.96 | 0.03 | 1.62 SELECT abalance FROM pgbench_a | 97609 | 1126.53 | 0.01 | 0.57 INSERT INTO pgbench_history (t | 97609 | 703.98 | 0.01 | 0.36 copy pgbench_accounts from std | 1 | 240.15 | 240.15 | 0.12 alter table pgbench_accounts a | 1 | 61.18 | 61.18 | 0.03 CREATE EXTENSION pg_stat_state | 2 | 52.61 | 26.30 | 0.03 SELECT pg_catalog.quote_ident( | 3 | 51.81 | 17.27 | 0.03 vacuum analyze pgbench_account | 1 | 49.31 | 49.31 | 0.03 (10 rows)

The overall execution time in milliseconds is displayed here. Additionally, how frequently a specific type of query has been run. Finally, we provide context for the data. We calculated how much of the total runtime was devoted to each sort of query. Also, note that I have used substring to make the query shorter. To make it simpler for the data to be displayed on the website, that was done. You typically want to see the entire query in real life.
My example shows that 97% of the total runtime is taken up by the first two queries. In other words, everything else is completely unimportant. Additionally, it is clear that the loading process, which is by far the slowest query, has no bearing on the bigger picture. This query’s real strength is that it allows us to quickly identify the lengthy operations.

However, sometimes it is not only about runtime—often I/O is the real issue.pg_stat_statements can aid you in that endeavor as well. Let’s first clarify the view’s content, though:

 test=# SELECT pg_stat_statements_reset(); pg_stat_statements_reset -------------------------- (1 row)

I/O time measurement is easy to do. Thetrack_io_timing parameter can be adjusted to measure this vital KPI. You can turn it on in postgresql.conf for the entire server or simply adjust things on the database level if you want more fine-grained data:

 test=# ALTER DATABASE test SET track_io_timing = on; ALTER DATABASE

In this example, the parameter has been set for this particular database, and we can run the following tests once more to generate more data:

 iMac:~ hs$ pgbench -c 10 -j 10 -T 30 test starting vacuum...end. transaction type: "built-in: TPC-B (sort of)" scaling factor: 1 query mode: simple number of clients: 10 number of threads: 10 duration: 30 s number of transactions actually processed: 125744 latency average = 2.387 ms tps = 4189.758792 (including connections establishing) tps = 4191.299887 (excluding connections establishing) iMac:~ hs$ pgbench -c 10 -j 10 -T 30 -S test starting vacuum...end. transaction type: "built-in: select only" scaling factor: 1 query mode: simple number of clients: 10 number of threads: 10 duration: 30 s number of transactions actually processed: 1239972 latency average = 0.242 ms tps = 41323.638554 (including connections establishing) tps = 41337.620153 (excluding connections establishing)

These two tests can then be checked using one more query:

 test=# SELECT substring (query, 1, 30, AS query, calls, round(total_exec_time::numeric, 2) AS total_time, round(blk_read_time::numeric, 2) AS io_read_time, round (blk_write_time::numeric, 2) AS io_write_time, round((100 * total_exec_time / sum(total_exec_time) OVER ())::numeric, 2) AS percentage FROM pg_stat_statements ORDER BY blk_read_time + blk_write_time DESC LIMIT 10; query | calls | total_time | io_read_time | io_write_time | percentage --------------------------------+---------+------------+--------------+---------------+------------ INSERT INTO pgbench_history (t | 125744 | 847.02 | 0.04 | 0.00 | 0.44 END | 125744 | 50.11 | 0.00 | 0.00 | 0.03 truncate pgbench_history | 2 | 1.29 | 0.00 | 0.00 | 0.00 select count(*) from pgbench_b | 2 | 0.37 | 0.00 | 0.00 | 0.00 ALTER DATABASE test SET track_ | 1 | 0.24 | 0.00 | 0.00 | 0.00 SELECT abalance FROM pgbench_a | 1365716 | 16740.08 | 0.00 | 0.00 | 8.69 UPDATE pgbench_tellers SET tba | 125744 | 103813.51 | 0.00 | 0.00 | 53.92 UPDATE pgbench_accounts SET ab | 125744 | 5795.74 | 0.00 | 0.00 | 3.01 SELECT substring(query, $1, $ | 1 | 0.16 | 0.00 | 0.00 | 0.00 SELECT substring(query, $1, $ | 1 | 0.37 | 0.00 | 0.00 | 0.00 (10 rows)

blk_read_timeis the amount of time spent on reading data from the operating system.blk_write_time tells us about the time needed to send data to the OS. The important observation here is that I/O is not really an issue. A fraction of a second is needed, which is basically nothing compared to the overall execution time. In other words, spending a ton of money on additional I/O capacity (disks, cloud services) does not really pay off in this case. However, many people pay for hardware or services BEFORE realizing they are useless.

If you are looking for good performance, it makes sense to consider temporary I/O as a potential factor.temp_blks_read andtemp_blks_written are the important parameters here. But keep in mind that simply throwing work_mem at temporary I/O is not usually the solution. In situations involving routine daily operations, a missing index is frequently the real issue.

Finally…

pg_stat_statements is a crucial subject, but it is frequently ignored. However, if you want to find out more about performance, we have tons of useful content for you. Maybe you want to check out our post about checkpoints and checkpoint performance in PostgreSQL.

About Enteros

​​​​Enteros offers a patented database performance management SaaS platform. It finds the root causes of complex database scalability and performance problems that affect business across a growing number of cloud, RDBMS, NoSQL, and machine learning database platforms.