Troubleshooting waits in PostgreSQL

Currently when the PostgreSQL database becomes slow especially on systems with high load, it becomes difficult to find the exact reasons.  Currently one can use tools like perf, strace, dynamic tracing (http://www.postgresql.org/docs/devel/static/dynamic-trace.html), etc. to find out the reasons of slowdown, but most of the times they are quite inconvenient to use which lead to the development of the new feature to display wait events information in pg_stat_activity view.  Wait events are invented to capture the information of system blocks or waits to perform some action like waiting for another backend process to release the heavyweight or lightweight locks, waits to access data buffer when no other process can be examining the buffer, waits to read or write the data to disk, etc.  As part of initial feature, we have covered some of the common wait event types due to which there are waits in system, however it is designed such that it can be extended to capture other types of wait events as well.

I will briefly explain the wait event types covered as part of this feature and then explain with examples, how one can use this feature to find stalls or waits in the system.  First wait event type is lightweight lock which is used to protect a particular data structure in shared memory.  Second wait event type is named lightweight lock tranche, this indicates that the server process is waiting for one of a group of related lightweight locks. Third wait event type is heavyweight lock which is used to primarily protect SQL-visible objects such as tables.  Fourth type of wait event is BufferPin where the server process waits to access to a data buffer during a period when no other process can be examining that buffer.  For detail explanation, refer PostgreSQL documentation at http://www.postgresql.org/docs/devel/static/monitoring-stats.html#PG-STAT-ACTIVITY-VIEW

Now, let us try to understand with the help of simple examples, how to find waits in the system using this powerful tool.

Create table and insert data which will be used in below examples:

postgres=# create table wait_event_tbl(c1 int);

CREATE TABLE

postgres=# insert into wait_event_tbl values(1);

INSERT 0 1

wait event type - Lock (Heavyweight locks)

-------------------------------------------------

Scenario - 1

Let us try to examine the waits for a scenario where one of the session has acquired Access Exclusive Lock on a table and the other session wants to acquire Access Share Lock on the same table and is waiting for first session to complete it's transaction.

Session -1

postgres=# select pg_backend_pid();

 pg_backend_pid

----------------

           6088

(1 row)

postgres=# begin;

BEGIN

postgres=# Lock wait_event_tbl in Access Exclusive Mode;

LOCK TABLE

Session-2

postgres=# select pg_backend_pid();

 pg_backend_pid

----------------

           1152

(1 row)

postgres=# begin;

BEGIN

postgres=# Lock wait_event_tbl in Access Share Mode;

Session-3

postgres=# select pid, wait_event_type, wait_event from pg_stat_activity where wait_event is NOT NULL;

 pid  | wait_event_type | wait_event

------+-----------------+------------

 1152 | Lock            | relation

(1 row)

Here, via above statement, it is shown that session-2 is waiting for a Lock on a relation.  To know more information about relation, one can add "query" column in the above statement.

Scenario - 2

Three sessions try to update the same row, first one will be successful and the other two will be waiting.

Session -1

postgres=# select pg_backend_pid();

 pg_backend_pid

----------------

           6088

(1 row)

postgres=# begin;

BEGIN

postgres=# update wait_event_tbl set c1 = 2 where c1=1;

UPDATE 1

Session - 2

postgres=# select pg_backend_pid();

 pg_backend_pid

----------------

           1152

(1 row)

postgres=# begin;

BEGIN

postgres=# update wait_event_tbl set c1 = 3 where c1 = 1;

Session - 3

postgres=# select pg_backend_pid();

 pg_backend_pid

----------------

           5404

(1 row)

postgres=# begin;

BEGIN

postgres=# update wait_event_tbl set c1 = 4 where c1 = 1;

Session - 4

postgres=# select pid, wait_event_type, wait_event from pg_stat_activity where wait_event is NOT NULL;

 pid  | wait_event_type |  wait_event

------+-----------------+---------------

 1152 | Lock            | transactionid

 5404 | Lock            | tuple

(2 rows)

Here, above statement indicates that session-2 and session-3 are waiting.

To find detailed information about locks, you can join this table information with pg_locks as described in link:https://wiki.postgresql.org/wiki/Lock_Monitoring or some other similar way.

wait event type - LWLockName (Lightweight Locks)

----------------------------------------------------

One session trying to execute the update statement and other session is trying to execute select statement can block each other for short time.

Session - 1

postgres=# select pg_backend_pid();

 pg_backend_pid

----------------

           1152

(1 row)

postgres=# update wait_event_tbl set c1 = 2;

Session - 2

postgres=# select pg_backend_pid();

 pg_backend_pid

----------------

           6088

(1 row)

postgres=# select * from wait_event_tbl;

Session - 3

postgres=# select pid, wait_event_type, wait_event from pg_stat_activity where wait_event is NOT NULL;

 pid  | wait_event_type |  wait_event

------+-----------------+---------------

 1152 | LWLockNamed     | ProcArrayLock

(1 row)

I have created this scenario with the help of debugger, but it is quite possible to see such wait events during high load on the system.

One point to note for users who are using "waiting" column of pg_stat_activity to find blocking statements is that they need to change their queries for next version (presumably 9.6) of PostgreSQL  as waiting column is removed from pg_stat_activity.  This is an intentional decision taken by PostgreSQL community for the ease of use and or understanding of this feature especially for future versions.

This feature has been committed in PostgreSQL code.  For details, you can refer commit id - 53be0b1add7064ca5db3cd884302dfc3268d884e.  It took us approximately 9 months to complete this feature.  Thanks to all the PostgreSQL community members who have given their valuable feedback throughout the development of this feature and special thanks to Robert Haas and Ildus Kurbangaliev for giving tremendous support to me both by reviews and by helping in writing parts of code.  Also Thanks to Alexander Korotkov for review and inputs for this feature and last but not least Thanks to Thom Brown for inputs in documentation of this feature.