{"id":14410,"date":"2020-07-10T13:50:13","date_gmt":"2020-07-10T11:50:13","guid":{"rendered":"https:\/\/www.dbi-services.com\/blog\/the-log_duration-parameter-in-postgresql\/"},"modified":"2024-11-08T15:15:32","modified_gmt":"2024-11-08T14:15:32","slug":"the-log_duration-parameter-in-postgresql","status":"publish","type":"post","link":"https:\/\/www.dbi-services.com\/blog\/the-log_duration-parameter-in-postgresql\/","title":{"rendered":"The log_duration parameter in PostgreSQL"},"content":{"rendered":"

log_duration<\/a> is a useful point for finding slow running queries and to find performance issues also on the applications side using PostgreSQL as database. Another topic is finding issues with Java Applications using Hibernate after a migration to PostgreSQL. Often Hibernate<\/a> switches from lazy to eager mode and this has massive impact on the application performance.<\/p>\n

In this context I will also describe one of the most useful extensions: pg_stat_statements<\/a>.<\/p>\n

The log duration shown in the logs of PostgreSQL includes the client time, so if you have slow queries it can be also issued by network problems.<\/p>\n

For demonstaration I will start with creating my own database:<\/p>\n

postgres=# create database blog_log_duration;\n<\/pre>\n
After creating the database we leave psql with “\\q” and with psql log_log_duration as the default; we connect to our newly created database. The parameter log_duration will switch on logging of the duration for everything and than log_min_duration_statement will show the queries when exeeding the specified runtime.<\/p>\n
So both paramters settings, log_duration to on and log_min_duration_statement with a value will fill up the logfile, it makes no sense, so we use log_min_duration_statement only.<\/p>\n
postgres=# alter system set log_min_duration_statement = 10000;\nALTER SYSTEM\n<\/pre>\n
As an example to log queries runing longer than 10s, the parameter setting is in ms.<\/p>\n
postgres=# select pg_reload_conf();\npg_reload_conf\n----------------\nt\n(1 row)\n\npostgres=#\n<\/pre>\n
The new setting becomes active as global setting for all databases on this instance. Quitting the postgres connection with “\\q” and connecting to our newly created database with:<\/p>\n
psql blog_log_duration;\n\npostgres=#select pg_sleep(11);\n<\/pre>\n
In the log file we will see the following:<\/p>\n
LOG: duration: 11032.666 ms statement: select pg_sleep(11);\n<\/pre>\n
Another possibility is to change these settings for one specific database only, for this we need to revoke the global setting with:<\/p>\n
postgres=# alter system reset log_min_duration_statement;\nALTER SYSTEM\n<\/pre>\n
And reloading the configuration with:<\/p>\n
postgres=# select pg_reload_conf();\npg_reload_conf\n----------------\nt\n(1 row)\n<\/pre>\n
Checking with:<\/p>\n
postgres=# select pg_sleep(11);\n<\/pre>\n
… shows no new entry in the log file.<\/p>\n
Now we can change this parameter for our test database we created at the beginning:<\/p>\n
postgres=# alter database blog_log_duration set log_min_duration_statement = 5000;\n<\/pre>\n
Checking for the postgres database:<\/p>\n
postgres=# select pg_sleep(11);\n<\/pre>\n
… shows again no new entry in the log file.<\/p>\n
Settings on database level overruling global settings, just as notice.<\/p>\n
Disconnecting from the postgres database with:<\/p>\n
postgres=# \\q\n<\/pre>\n
Connecting to the blog_log_duration database with:<\/p>\n
psql blog_log_duration\n<\/pre>\n
And checking here with:<\/p>\n
blog_log_duration=# select pg_sleep(6);\npg_sleep\n----------\n\n(1 row)\n\nblog_log_duration=#\n<\/pre>\n
This results in the following line in the log file:<\/p>\n
LOG: duration: 6005.967 ms statement: select pg_sleep(6);\n<\/pre>\n
Extension pg_stat_statements<\/h2>\n
This Extension is one of the most useful, it shows what queries have been sent to the database, how often, average, min and max runtime.<\/p>\n
For using pg_stat_statements we need to preload libraries, the required configuration can be done with:<\/p>\n
postgres=# alter system set shared_preload_libraries = 'pg_stat_statements';\n<\/pre>\n
Than a restart is required, a pg_reload_conf(); is not enough.<\/p>\n
Then we connect again to our test database with psql blog_log_duration and create the extension with:<\/p>\n
blog_log_duration=# create extension pg_stat_statements;\nCREATE EXTENSION\nblog_log_duration=#\n\nblog_log_duration-# \\d pg_stat_statements\nView \"public.pg_stat_statements\"\nColumn | Type | Collation | Nullable | Default\n---------------------+------------------+-----------+----------+---------\nuserid | oid | | |\ndbid | oid | | |\nqueryid | bigint | | |\nquery | text | | |\ncalls | bigint | | |\ntotal_time | double precision | | |\nmin_time | double precision | | |\nmax_time | double precision | | |\nmean_time | double precision | | |\nstddev_time | double precision | | |\nrows | bigint | | |\nshared_blks_hit | bigint | | |\nshared_blks_read | bigint | | |\nshared_blks_dirtied | bigint | | |\nshared_blks_written | bigint | | |\nlocal_blks_hit | bigint | | |\nlocal_blks_read | bigint | | |\nlocal_blks_dirtied | bigint | | |\nlocal_blks_written | bigint | | |\ntemp_blks_read | bigint | | |\ntemp_blks_written | bigint | | |\nblk_read_time | double precision | | |\nblk_write_time | double precision | | |\n\nblog_log_duration-# \u00a8\n<\/pre>\n
This gives an overview over the view where we can now get the query informations we want to have. This can become very huge, so there are some parameters that can be set to make it more handable.<\/p>\n