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:

(postgres@[local]:4448) [postgres] > alter system set logging_collector=on;
Time: 30.390 ms
(postgres@[local]:4448) [postgres] > show logging_collector;
(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:

(postgres@[local]:4448) [postgres] > show log_directory;
(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:

(postgres@[local]:4448) [postgres] > show log_filename;
(1 row)

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

(postgres@[local]:4448) [postgres] > alter system set log_filename='postgresql-%Y-%m-%d_%H%M%S.log';
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:

(postgres@[local]:4448) [postgres] > show log_rotation_size;
(1 row)

Time: 1.015 ms
(postgres@[local]:4448) [postgres] > show log_rotation_age;
(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:

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

(postgres@[local]:4448) [postgres] > select pg_reload_conf();
(1 row)

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

postgres@oel7:/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:

(postgres@[local]:4448) [postgres] > alter system set log_duration=on;
Time: 38.978 ms
(postgres@[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

(postgres@[local]:4448) [postgres] > select pg_reload_conf();
(1 row)

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

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

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

postgres@oel7:/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 - postgres@postgres LOG:  statement: create table tt ( a int );
2015-12-05 10:08:07.067 GMT - 5 - 4609 - postgres@postgres LOG:  duration: 23.669 ms
2015-12-05 10:08:22.052 GMT - 6 - 4609 - postgres@postgres LOG:  duration: 37.163 ms
2015-12-05 10:08:25.519 GMT - 7 - 4609 - postgres@postgres 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:

(postgres@[local]:4448) [postgres] > alter system set log_min_duration_statement=0;

Time: 0.188 ms
(postgres@[local]:4448) [postgres] > select pg_reload_conf();
(1 row)

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

Time: 0.680 ms

Checking the logfile again:

postgres@oel7:/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 - postgres@postgres 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:

(postgres@[local]:4448) [postgres] > select 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

Daniel Westermann
Daniel Westermann

Senior Consultant and Technology Leader Open Infrastructure