If you are doing a very detailed Performance Diagnostics \/ Forensics then we strongly recommend you to understand the Data Access Path of underlying queries, cost of query execution, wait events \/ locks and system resource usage by PostgreSQL infrastructure operations. MinervaDB Performance Engineering Team measures performance by “Response Time<\/strong>” , So finding slow queries in PostgreSQL will be the most appropriate point to start this blog. PostgreSQL Server is highly configurable to collect details on query performance: slow query log, auditing execution plans with auto_explain<\/em> and querying pg_stat_statements\u00a0<\/em><\/strong>\u00a0.\u00a0<\/span><\/p>\n Step 1<\/strong> – Open\u00a0postgresql.conf<\/strong> file in your favorite text editor ( In Ubuntu, postgreaql.conf is available on \/etc\/postgresql\/ ) and update configuration parameter log_min_duration_statement , <\/em>By\u00a0default configuration the slow query log is not active, To enable the slow query log on globally, you can change postgresql.conf:<\/p>\n In the above configuration, PostgreSQL will log queries, which take longer than 2 seconds.<\/p>\n Step 2<\/strong> – A “reload” (by\u00a0simply calling the SQL function) is sufficient, there is no need for a PostgreSQL server restart and Don\u2019t worry, it won\u2019t interrupt any active connections<\/em>:<\/p>\n Note: It’s often too heavy for PostgreSQL infrastructure if you change slow query log settings in postgresql.conf , Therefore it makes more sensible to change only for a selected database or user:<\/em><\/p>\n To complete the detailed performance forensics \/ diagnostics of high latency queries you can use aut0_explain , We have explained same below for queries exceeding certain threshold in PostgreSQL to send plan to the log file:<\/p>\n You can also enable auto explain in postgresql.conf with the settings below:<\/p>\n Note: Please do not forget to call pg_reload_conf() after the change made to postgresql.conf<\/em><\/p>\n More examples on PostgreSQL auto explain is copied below:<\/p>\n We can use pg_stat_statements to group the identical PostgreSQL queries by latency, To enable pg_stat_statements you have to add the following line to postgresql.conf and restart PostgreSQL server:<\/p>\n Run \u201cCREATE EXTENSION pg_stat_statements\u201d in your database so that PostgreSQL will create a view for you:<\/p>\n pg_stat_statements <\/strong>view\u00a0columns explained (Source: https:\/\/www.postgresql.org\/docs\/12\/pgstatstatements.html<\/a><\/span>)<\/p>\n You can list queries by latency \/ Response Time in PostgreSQL \u00a0by querying\u00a0pg_stat_statements<\/em>:<\/p>\n If you already know the epicenter of the bottleneck is a particular query or event \/ time, you can reset statistics just before query \/ event to monitor the problematic components in the PostgreSQL performance, You can do that by just calling pg_stat_statements_reset() <\/em>as copied\u00a0below:<\/p>\n Performance tuning<\/b> is the process of optimizing PostgreSQL\u00a0performance <\/strong>by streamlining the execution of multiple SQL statements. In other words, performance tuning\u00a0<\/b>simplifies the process of accessing and altering information contained by the database with the intention of improving query response times and database application operations.<\/p>\n <\/a><\/p>\n <\/p>\n","protected":false},"excerpt":{"rendered":" PostgreSQL Performance Troubleshooting with Slow Queries Introduction \u00a0 If you are doing a very detailed Performance Diagnostics \/ Forensics then we strongly recommend you to understand the Data Access Path of underlying queries, cost of […]<\/a><\/p>\n<\/div>","protected":false},"author":10,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[2309,6476,2368],"tags":[2292,6477,2293],"yoast_head":"\nUsing PostgreSQL slow query log to troubleshoot the performance<\/h4>\n
log_min_duration_statement = 2000<\/pre>\n
postgres=# SELECT pg_reload_conf();\r\n pg_reload_conf \r\n----------------\r\n t \r\n(1 row)<\/pre>\n
postgres=# ALTER DATABASE minervadb SET log_min_duration_statement = 2000;\r\nALTER DATABASE<\/pre>\n
postgres=# LOAD 'auto_explain';\r\nLOAD\r\npostgres=# SET auto_explain.log_analyze TO on;\r\nSET\r\npostgres=# SET auto_explain.log_min_duration TO 2000;\r\nSET<\/pre>\n
session_preload_libraries = 'auto_explain';<\/pre>\n
postgres=# CREATE TABLE minervdb_bench AS\r\npostgres-# SELECT * FROM generate_series(1, 10000000) AS id;\r\nSELECT 10000000\r\npostgres=# CREATE INDEX idx_id ON minervadb_bench(id);\r\n\r\npostgres=# CREATE INDEX idx_id ON minervdb_bench(id);\r\nCREATE INDEX\r\npostgres=# ANALYZE;\r\nANALYZE\r\n\r\npostgres=# LOAD 'auto_explain';\r\nLOAD\r\npostgres=# SET auto_explain.log_analyze TO on;\r\nSET\r\npostgres=# SET auto_explain.log_min_duration TO 200;\r\nSET\r\n\r\npostgres=# explain SELECT * FROM minervdb_bench WHERE id < 5000;\r\n QUERY PLAN \r\n---------------------------------------------------------------------------------------\r\n Index Only Scan using idx_id on minervdb_bench (cost=0.43..159.25 rows=4732 width=4)\r\n Index Cond: (id < 5000)\r\n(2 rows)\r\n\r\npostgres=# explain SELECT * FROM minervdb_bench WHERE id < 200000;\r\n QUERY PLAN \r\n------------------------------------------------------------------------------------------\r\n Index Only Scan using idx_id on minervdb_bench (cost=0.43..6550.25 rows=198961 width=4)\r\n Index Cond: (id < 200000)\r\n(2 rows)\r\n\r\npostgres=# explain SELECT count(*) FROM minervdb_bench GROUP BY id % 2;\r\n QUERY PLAN \r\n-------------------------------------------------------------------------------------\r\n GroupAggregate (cost=1605360.71..1805360.25 rows=9999977 width=12)\r\n Group Key: ((id % 2))\r\n -> Sort (cost=1605360.71..1630360.65 rows=9999977 width=4)\r\n Sort Key: ((id % 2))\r\n -> Seq Scan on minervdb_bench (cost=0.00..169247.71 rows=9999977 width=4)\r\n JIT:\r\n Functions: 6\r\n Options: Inlining true, Optimization true, Expressions true, Deforming true\r\n(8 rows)\r\n<\/pre>\n
Using pg_stat_statements<\/h3>\n
# postgresql.conf\r\nshared_preload_libraries = 'pg_stat_statements'\r\n\r\npg_stat_statements.max = 10000\r\npg_stat_statements.track = all<\/pre>\n
postgres=# CREATE EXTENSION pg_stat_statements;\r\nCREATE EXTENSION\r\n\r\npostgres=# \\d pg_stat_statements\r\n View \"public.pg_stat_statements\"\r\n Column | Type | Collation | Nullable | Default \r\n---------------------+------------------+-----------+----------+---------\r\n userid | oid | | | \r\n dbid | oid | | | \r\n queryid | bigint | | | \r\n query | text | | | \r\n calls | bigint | | | \r\n total_time | double precision | | | \r\n min_time | double precision | | | \r\n max_time | double precision | | | \r\n mean_time | double precision | | | \r\n stddev_time | double precision | | | \r\n rows | bigint | | | \r\n shared_blks_hit | bigint | | | \r\n shared_blks_read | bigint | | | \r\n shared_blks_dirtied | bigint | | | \r\n shared_blks_written | bigint | | | \r\n local_blks_hit | bigint | | | \r\n local_blks_read | bigint | | | \r\n local_blks_dirtied | bigint | | | \r\n local_blks_written | bigint | | | \r\n temp_blks_read | bigint | | | \r\n temp_blks_written | bigint | | | \r\n blk_read_time | double precision | | | \r\n blk_write_time | double precision | | | \r\n\r\npostgres=#<\/pre>\n
\n
\n \nName<\/th>\n Type<\/th>\n References<\/th>\n Description<\/th>\n<\/tr>\n<\/thead>\n \n userid<\/td>\n oid<\/td>\n pg_authid.oid<\/td>\n OID of user who executed the statement<\/td>\n<\/tr>\n \n dbid<\/td>\n oid<\/td>\n pg_database.oid<\/td>\n OID of database in which the statement was executed<\/td>\n<\/tr>\n \n queryid<\/td>\n bigint<\/td>\n <\/td>\n Internal hash code, computed from the statement’s parse tree<\/td>\n<\/tr>\n \n query<\/td>\n text<\/td>\n <\/td>\n Text of a representative statement<\/td>\n<\/tr>\n \n calls<\/td>\n bigint<\/td>\n <\/td>\n Number of times executed<\/td>\n<\/tr>\n \n total_time<\/td>\n double precision<\/td>\n <\/td>\n Total time spent in the statement, in milliseconds<\/td>\n<\/tr>\n \n min_time<\/td>\n double precision<\/td>\n <\/td>\n Minimum time spent in the statement, in milliseconds<\/td>\n<\/tr>\n \n max_time<\/td>\n double precision<\/td>\n <\/td>\n Maximum time spent in the statement, in milliseconds<\/td>\n<\/tr>\n \n mean_time<\/td>\n double precision<\/td>\n <\/td>\n Mean time spent in the statement, in milliseconds<\/td>\n<\/tr>\n \n stddev_time<\/td>\n double precision<\/td>\n <\/td>\n Population standard deviation of time spent in the statement, in milliseconds<\/td>\n<\/tr>\n \n rows<\/td>\n bigint<\/td>\n <\/td>\n Total number of rows retrieved or affected by the statement<\/td>\n<\/tr>\n \n shared_blks_hit<\/td>\n bigint<\/td>\n <\/td>\n Total number of shared block cache hits by the statement<\/td>\n<\/tr>\n \n shared_blks_read<\/td>\n bigint<\/td>\n <\/td>\n Total number of shared blocks read by the statement<\/td>\n<\/tr>\n \n shared_blks_dirtied<\/td>\n bigint<\/td>\n <\/td>\n Total number of shared blocks dirtied by the statement<\/td>\n<\/tr>\n \n shared_blks_written<\/td>\n bigint<\/td>\n <\/td>\n Total number of shared blocks written by the statement<\/td>\n<\/tr>\n \n local_blks_hit<\/td>\n bigint<\/td>\n <\/td>\n Total number of local block cache hits by the statement<\/td>\n<\/tr>\n \n local_blks_read<\/td>\n bigint<\/td>\n <\/td>\n Total number of local blocks read by the statement<\/td>\n<\/tr>\n \n local_blks_dirtied<\/td>\n bigint<\/td>\n <\/td>\n Total number of local blocks dirtied by the statement<\/td>\n<\/tr>\n \n local_blks_written<\/td>\n bigint<\/td>\n <\/td>\n Total number of local blocks written by the statement<\/td>\n<\/tr>\n \n temp_blks_read<\/td>\n bigint<\/td>\n <\/td>\n Total number of temp blocks read by the statement<\/td>\n<\/tr>\n \n temp_blks_written<\/td>\n bigint<\/td>\n <\/td>\n Total number of temp blocks written by the statement<\/td>\n<\/tr>\n \n blk_read_time<\/td>\n double precision<\/td>\n <\/td>\n Total time the statement spent reading blocks, in milliseconds (if track_io_timing is enabled, otherwise zero)<\/td>\n<\/tr>\n \n blk_write_time<\/td>\n double precision<\/td>\n <\/td>\n Total time the statement spent writing blocks, in milliseconds (if track_io_timing is enabled, otherwise zero)<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n<\/div>\n postgres=# \\x\r\nExpanded display is on.\r\n\r\nselect query,calls,total_time,min_time,max_time,mean_time,stddev_time,rows from pg_stat_statements order by mean_time desc;\r\n\r\n-[ RECORD 1 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------\r\nquery | SELECT count(*) FROM minervdb_bench GROUP BY id % $1\r\ncalls | 6\r\ntotal_time | 33010.533078\r\nmin_time | 4197.876021\r\nmax_time | 6485.33594\r\nmean_time | 5501.755512999999\r\nstddev_time | 826.3716429081501\r\nrows | 72\r\n-[ RECORD 2 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------\r\nquery | CREATE INDEX idx_id ON minervdb_bench(id)\r\ncalls | 1\r\ntotal_time | 4560.808456\r\nmin_time | 4560.808456\r\nmax_time | 4560.808456\r\nmean_time | 4560.808456\r\nstddev_time | 0\r\nrows | 0\r\n-[ RECORD 3 ]---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------\r\nquery | ANALYZE\r\ncalls | 1\r\ntotal_time | 441.725223\r\nmin_time | 441.725223\r\nmax_time | 441.725223\r\nmean_time | 441.725223\r\nstddev_time | 0\r\nrows | 0\r\n\r\n-[ RECORD 4 ]--------------------------------------------------------------------------------------------------------------------------------------------------------------------------\r\n------------------------------------------------------------------------------------------------------------------------------------------------\r\nquery | SELECT a.attname, \r\n +\r\n | pg_catalog.format_type(a.atttypid, a.atttypmod), \r\n +\r\n | (SELECT substring(pg_catalog.pg_get_expr(d.adbin, d.adrelid, $1) for $2) +\r\n | FROM pg_catalog.pg_attrdef d +\r\n | WHERE d.adrelid = a.attrelid AND d.adnum = a.attnum AND a.atthasdef), +\r\n | a.attnotnull, +\r\n | (SELECT c.collname FROM pg_catalog.pg_collation c, pg_catalog.pg_type t +\r\n | WHERE c.oid = a.attcollation AND t.oid = a.atttypid AND a.attcollation <> t.typcollation) AS attcollation, +\r\n | a.attidentity, +\r\n | a.attgenerated +\r\n | FROM pg_catalog.pg_attribute a +\r\n | WHERE a.attrelid = $3 AND a.attnum > $4 AND NOT a.attisdropped +\r\n | ORDER BY a.attnum\r\ncalls | 4\r\ntotal_time | 1.053107\r\nmin_time | 0.081565\r\nmax_time | 0.721785\r\nmean_time | 0.26327675000000006\r\nstddev_time | 0.2658756938743884\r\nrows | 86\r\n<\/pre>\n
postgres= SELECT pg_stat_statements_reset();<\/pre>\n
Conclusion<\/b><\/h2>\n