← Back to the Blog

Enable wait events in PostgreSQL

Intro

Wait events and associated dynamic views (v$session_wait , v$session_event and v$system_event)  are very well known among DBAs who used to work with Oracle Database Server. These views are being used to monitor database performance in a real time and watch for the actual sessions in the system, which are waiting for a resources (e.g. CPU/Memory/Network, Disk I/O, Logical Reads, internal locks and latches, etc. ( read more about Oracle wait events) 

Reading and understanding top wait events is and is a key apsect of a database performance tunning, as it helps in troubleshooting of various  performance issues (like long running and hanging sessions in database). 

Now wait events and related dynamic views are becoming available in PostgreSQL as a plugable extension, 

In this article, we are going to  

  1.  install and enable *pg_stat_wait* extension from source 
  2.  query-up new performance views for a top waiting events and top waiting sessions, 
  3.  enable session tracing for these event in Posgresql database

 


Installation

 

  • Extension is not yet a part of a core PostgreSQL, so`we'll have to recompile postgresql and need extensions from source otherwise will see following:

     postgres=# \dxS+ pg_stat_wait
     Did not find any extension named "pg_stat_wait".
    

 

 

  • Once compilation completed, we'll need to add following options to postgresql.conf:

     shared_preload_libraries = 'pg_stat_wait'
     waits_monitoring = on # - to enable functionality on
     pg_stat_wait.history = on # - to keep history of wait events, 
     pg_stat_wait.history_size = 1000000 # - number of last events to keep in history,
     pg_stat_wait.history_period = 1000 # - how often should wait events be stored in history (ms).
    

 

  • Then restart PostgreSQL and say

     CREATE EXTENSION pg_stat_wait;
    


Congrats, now you have pg_stat_wait interface up and available


Performance views functionality

 

So let's have a look, what's inside of a new extension:

postgres # \dxS+ pg_stat_wait
        Objects in extension "pg_stat_wait"
        Object Description                 
----------------------------------------------------
 function pg_is_in_trace(integer)
 function pg_start_trace(integer,cstring)
 function pg_stat_wait_get_current(integer)
 function pg_stat_wait_get_history()
 function pg_stat_wait_get_profile(integer,boolean)
 function pg_stat_wait_reset_profile()
 function pg_stop_trace(integer)
 function pg_wait_class_list()
 function pg_wait_event_list()
 view pg_stat_wait_current
 view pg_stat_wait_history
 view pg_stat_wait_profile
 view pg_wait_class
 view pg_wait_event
 view pg_wait_events
(15 rows)


New event classes available for monitoring:

SELECT class_name, count(event_name) FROM pg_wait_events GROUP BY 1 ORDER BY 2 DESC;

 class_name | count 
------------+-------
 LWLocks    |    51
 Storage    |     9
 Locks      |     9
 Network    |     3
 Latch      |     1
 CPU        |     1
(6 rows)


Storage wait events:

SELECT * FROM pg_wait_events WHERE class_id = 3;

 class_id | class_name | event_id | event_name
----------+------------+----------+------------
        3 | Storage    |        0 | SMGR_READ
        3 | Storage    |        1 | SMGR_WRITE
        3 | Storage    |        2 | SMGR_FSYNC
        3 | Storage    |        3 | XLOG_READ
        3 | Storage    |        4 | XLOG_WRITE
        3 | Storage    |        5 | XLOG_FSYNC
        3 | Storage    |        6 | SLRU_READ
        3 | Storage    |        7 | SLRU_WRITE
        3 | Storage    |        8 | SLRU_FSYNC
(9 rows)


Ok great, we have all these events available for monitoring, now we need to understand top wait events for our DB sessions and OS process
most DBAs want to know in a real-time:

  • What process or session is waiting for right now and for how long
  • How many wait events happening per process and how long does it take per event
  • What was this process waiting for some time in past

To answer above questions we'll need to do a SELECT from

pg_stat_wait_current, pg_stat_wait_profile, pg_stat_wait_history


Performance views in PostgreSQL by example:

 

pg_stat_wait_current view:

 

SELECT pid, class_name, event_name, wait_time FROM pg_stat_wait_current 
WHERE class_id NOT IN (4, 5) ORDER BY wait_time DESC;

  pid  | class_name |  event_name   | wait_time
-------+------------+---------------+-----------
 23510 | LWLocks    | BufferLWLocks |     17184
 23537 | LWLocks    | BufferLWLocks |      9367
 23628 | LWLocks    | BufferLWLocks |      9366
 23502 | LWLocks    | BufferLWLocks |      3215
 23504 | LWLocks    | BufferLWLocks |      2846
 23533 | LWLocks    | BufferLWLocks |      2788
 23514 | LWLocks    | BufferLWLocks |      2658
 23517 | LWLocks    | BufferLWLocks |      2658
 23532 | LWLocks    | BufferLWLocks |      2641
 23527 | LWLocks    | BufferLWLocks |      2507
 23952 | Storage    | SMGR_READ     |      2502
 23518 | Storage    | XLOG_FSYNC    |      1576
 23524 | LWLocks    | WALWriteLock  |      1027
(13 rows)

'Network' and 'Latch' wait classes were excluded from query above,
Another example.

    SELECT * FROM pg_stat_wait_current;
      pid  |           sample_ts           | class_id | class_name | event_id | event_name | wait_time | p1 | p2 | p3 | p4 | p5 
    -------+-------------------------------+----------+------------+----------+------------+-----------+----+----+----+----+----
     88051 | 2015-12-10 01:02:02.037526-05 |        4 | Latch      |        0 | Latch      |  42625126 |  0 |  0 |  0 |  0 |  0
     88053 | 2015-12-10 01:02:02.037526-05 |        4 | Latch      |        0 | Latch      |    171529 |  0 |  0 |  0 |  0 |  0
     88048 | 2015-12-10 01:02:02.037526-05 |        4 | Latch      |        0 | Latch      | 141192791 |  0 |  0 |  0 |  0 |  0
     88049 | 2015-12-10 01:02:02.037526-05 |        4 | Latch      |        0 | Latch      |    778019 |  0 |  0 |  0 |  0 |  0
     88050 | 2015-12-10 01:02:02.037526-05 |        4 | Latch      |        0 | Latch      |   1351474 |  0 |  0 |  0 |  0 |  0


Note that, values returned in p1-p5 fields are wait class dependent, for example, for disk I/O waits, these fields have database, relation and actual blockID which we're waiting on while reading.

SELECT * FROM pg_stat_wait_current
WHERE class_id IN (2, 3) LIMIT 2;
-[ RECORD 1 ]-----------------------------
pid        | 12107
sample_ts  | 2015-11-16 10:36:59.598562+03
class_id   | 2
class_name | Locks
event_id   | 4
event_name | Transaction
wait_time  | 24334
p1         | 5
p2         | 255593733
p3         | 0
p4         | 0
p5         | 0
-[ RECORD 2 ]-----------------------------
pid        | 1266
sample_ts  | 2015-11-16 10:36:59.598562+03
class_id   | 3
class_name | Storage
event_id   | 0
event_name | SMGR_READ
wait_time  | 1710
p1         | 1663
p2         | 16400
p3         | 20508
p4         | 0
p5         | 220036

 

pg_stat_wait_profile view:


now let's check top wait events in the database:

SELECT class_name, sum(wait_time) AS wait_time,
sum(wait_count) AS wait_count FROM pg_stat_wait_profile
GROUP BY class_name ORDER BY wait_time DESC;

 class_name |  wait_time  | wait_count 
------------+-------------+------------
 Latch      | 17962153852 |       5333
 Network    |   118582109 |          5
 CPU        |       10435 |      14730
(3 rows)


Now let's query top Light Weight LWLocks in the system:

SELECT event_name, sum(wait_time) AS wait_time,
sum(wait_count) AS wait_count FROM pg_stat_wait_profile
WHERE class_id = 1 AND wait_time != 0 AND wait_count != 0
GROUP BY event_name ORDER BY wait_time DESC;

      event_name      | wait_time  | wait_count
----------------------+------------+------------
 LockMgrLWLocks       | 1873294341 |    3870685
 WALWriteLock         | 1039279117 |     859101
 BufferLWLocks        |  299153931 |    7356555
 BufFreelistLock      |    7466923 |      75484
 ProcArrayLock        |    2321769 |      34355
 CLogControlLock      |     778148 |      21286
 WALInsertLocks       |     456224 |       7451
 BufferMgrLocks       |     107374 |       8447
 XidGenLock           |      84914 |       2506
 UserDefinedLocks     |       1875 |          7
 CLogBufferLocks      |        868 |         80
 SInvalWriteLock      |         11 |          3
 CheckpointerCommLock |          1 |          1
(13 rows)

Time: 29.388 ms

Top waiting time may be not be always correlated with events count.

pg_stat_wait_history view:


This view shows history of a wait events for a process. Storage depth and sampling interval can be configured as shown above.

SELECT sample_ts, class_name, event_name, wait_time
FROM pg_stat_wait_history WHERE pid =87918 ORDER BY sample_ts DESC LIMIT 10;

           sample_ts           | class_name | event_name | wait_time 
-------------------------------+------------+------------+-----------
 2015-12-10 01:27:26.978715-05 | Latch      | Latch      |   1000096
 2015-12-10 01:27:25.978615-05 | Latch      | Latch      |   1000090
 2015-12-10 01:27:24.978523-05 | Latch      | Latch      |   1000091
 2015-12-10 01:27:23.978434-05 | Latch      | Latch      |   1000068
 2015-12-10 01:27:22.978359-05 | Latch      | Latch      |   1000101
 2015-12-10 01:27:21.97826-05  | Latch      | Latch      |   1000063

 


Enable session trace in PosgtgreSQL:



Above views were designed to be always turned on, their performance overhead is minimal. Sometimes however, sample rate of pg_stat_wait.history_period is not enough we'll need to check waits for a particular process, trace functions will help us here:

pg_start_trace pg_stop_trace

 

SELECT pg_backend_pid();
 pg_backend_pid 
----------------
          15724
(1 row)

SELECT pg_start_trace(15724, '/tmp/15724.trace');
INFO:  00000: Trace was started to: /tmp/15724.trace
LOCATION:  StartWait, wait.c:259
 pg_start_trace
----------------

(1 row)

SELECT pg_is_in_trace(15724);
 pg_is_in_trace
----------------
 t
(1 row)

-- some activity

SELECT pg_stop_trace(15724);
INFO:  00000: Trace was stopped
LOCATION:  StartWait, wait.c:265
 pg_stop_trace
---------------
(1 row)

Plain text trace file will be created in defined location, file contains two lines per each wait event, for example:

start 2015-12-10 01:44:53.360166-05 CPU MemAllocation 0 0 0 0 0
start 2015-12-10 01:44:53.360181-05 CPU MemAllocation 0 0 0 0 0
stop 2015-12-10 01:44:53.360191-05 CPU
stop 2015-12-10 01:44:53.360178-05 CPU
start 2015-12-10 01:44:53.360225-05 Network WRITE 0 0 0 0 0
stop 2015-12-10 01:44:53.360243-05 Network

 


Conclusion


Wait interface is a long-awaited feature in PostgreSQL that allows significantly improve visibility of a database performance.Extension is easily plugable and usage is very straight forwards (especially for DBA who already familiar with wait event views in Oracle Database)     

This functionality is being merged into core PostgreSQL Development branch and will become available as a part of PostgreSQL 9.6 Release



external links and references:

original article
shortly before Ildus submitted his implementation on pgsql-hackers@ Robert Haas proposed the same idea and lots of people supported this idea. To become it true a couple of preparatory patches have already been commited, for example Refactoring of LWLock tranches.

Be the first to reply