Infrastructure at your Service

Daniel Westermann

SQL Monitoring in PostgreSQL (1) – the logging system

When developing an application as well as when the application is in production there is the need to identify long running queries. In Oracle one tool you might use for that is the SQL Monitor. In this post I’ll look into what PostgreSQL provides in this area.

PostgreSQL has a very strong logging system. This system can be used to log many, many server messages as well as information about sql queries. To enable to background process that captures the server log messages and redirects them to log files you need to set the logging_collector parameter to on in a first step:

([email protected][local]:4448) [postgres] > alter system set logging_collector=on;
ALTER SYSTEM
Time: 30.390 ms
([email protected][local]:4448) [postgres] > show logging_collector;
 logging_collector 
-------------------
 on
(1 row)

Once you have this enabled you need to tell PostgreSQL where you want to log to. This is done by setting the parameter log_directory:

([email protected][local]:4448) [postgres] > show log_directory;
     log_directory      
------------------------
 /u02/pgdata/PG6/pg_log
(1 row)

In my case this is set to the pg_log directory which is located in my data directory. Additionally we can define how the log files will be named:

([email protected][local]:4448) [postgres] > show log_filename;
   log_filename    
-------------------
 postgresql-%a.log
(1 row)

The place holders which can be used are the same as in strftime. The default is:

([email protected][local]:4448) [postgres] > alter system set log_filename='postgresql-%Y-%m-%d_%H%M%S.log';
ALTER SYSTEM
Time: 45.666 ms

I recommend to set the log_rotation_age or log_rotation_size parameter so that the log-files will be rotated:

([email protected][local]:4448) [postgres] > show log_rotation_size;
 log_rotation_size 
-------------------
 10MB
(1 row)

Time: 1.015 ms
([email protected][local]:4448) [postgres] > show log_rotation_age;
 log_rotation_age 
------------------
 8d
(1 row)

As we now have the basic settings available lets check if we need to restart the server for the settings to go into effect:

([email protected][local]:4448) [postgres] > select name,pending_restart 
                                       from pg_settings 
                                      where name in ('log_filename','log_rotation_size'
                                                    ,'log_rotation_age','log_destination','logging_collector');
       name        | pending_restart 
-------------------+-----------------
 log_destination   | f
 log_filename      | f
 log_rotation_age  | f
 log_rotation_size | f
 logging_collector | f
(5 rows)

([email protected][local]:4448) [postgres] > select pg_reload_conf();
 pg_reload_conf 
----------------
 t
(1 row)

Ok, should be fine. Lets quickly check if there is a log file with some recent messages in the directory we specified:

[email protected]:/home/postgres/ [PG6] ls -altr /u02/pgdata/PG6/pg_log
total 68
drwx------. 19 postgres postgres 4096 Dec  5 11:01 ..
drwx------.  2 postgres postgres   45 Dec  5 11:01 .
-rw-------.  1 postgres postgres  384 Dec  5 11:01 postgresql-2015-12-05_100103.log

Looks fine. Back to what this post is about. How can we log sql statements? One parameter in this area is log_duration. When we set this to on:

([email protected][local]:4448) [postgres] > alter system set log_duration=on;
ALTER SYSTEM
Time: 38.978 ms
([email protected][local]:4448) [postgres] > select name,pending_restart 
                                       from pg_settings 
                                      where name in ('log_duration');
     name     | pending_restart 
--------------+-----------------
 log_duration | f
(1 row)

Time: 2.044 ms

([email protected][local]:4448) [postgres] > select pg_reload_conf();
 pg_reload_conf 
----------------
 t
(1 row)

… the duration of every statement is logged to the log file:

([email protected][local]:4448) [postgres] > create table tt ( a int );
CREATE TABLE
Time: 23.829 ms
([email protected][local]:4448) [postgres] > insert into tt (a) values (generate_series(1,1000));
INSERT 0 1000
Time: 37.333 ms
([email protected][local]:4448) [postgres] > select count(*) from tt;
 count 
-------
  1000
(1 row)

Having a look at the log file we can confirm that the duration is logged:

[email protected]:/home/postgres/ [PG6] tail /u02/pgdata/PG6/pg_log/postgresql-2015-12-05_100103.log 
2015-12-05 10:08:07.044 GMT - 4 - 4609 - [email protected] LOG:  statement: create table tt ( a int );
2015-12-05 10:08:07.067 GMT - 5 - 4609 - [email protected] LOG:  duration: 23.669 ms
2015-12-05 10:08:22.052 GMT - 6 - 4609 - [email protected] LOG:  duration: 37.163 ms
2015-12-05 10:08:25.519 GMT - 7 - 4609 - [email protected] LOG:  duration: 22.992 ms

Well, is the duration without the text of the statement very helpful? Not really and this is where the log_min_duration_statement parameter comes into the game. Setting this to any value greater than -1 logs each statement that runs longer than what you specified. If you set it to zero all statements will be logged:

([email protected][local]:4448) [postgres] > alter system set log_min_duration_statement=0;
ALTER SYSTEM

Time: 0.188 ms
([email protected][local]:4448) [postgres] > select pg_reload_conf();
 pg_reload_conf 
----------------
 t
(1 row)

([email protected][local]:4448) [postgres] > select count(*) tt;
 tt 
----
  1
(1 row)

Time: 0.680 ms

Checking the logfile again:

[email protected]:/home/postgres/ [PG6] tail -1 /u02/pgdata/PG6/pg_log/postgresql-2015-12-05_100103.log
2015-12-05 10:13:48.392 GMT - 8 - 4651 - [email protected] LOG:  duration: 0.216 ms  statement: select count(*) tt;

Much better: We have the time stamp when the statement was executed, the number of the line in the logfile where we can find the log message (8), the operating system process id and the user which executed the statement.

That’s is for now. Make yourself familiar with the various parameters of the logging system. There are plenty of things you can control and adjust.

The next post will look at another way to identify problematic statements.

Btw: The PostgreSQL version I used here is:

([email protected][local]:4448) [postgres] > select version();
                                                     version                                                      
------------------------------------------------------------------------------------------------------------------
 PostgreSQL 9.5alpha2 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.8.3 20140911 (Red Hat 4.8.3-9), 64-bit
(1 row)

Time: 0.376 ms

Leave a Reply

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

Daniel Westermann
Daniel Westermann

Principal Consultant & Technology Leader Open Infrastructure