Monitoring bgwriter efficiency during checkpoints with pg_buffercache

Have you ever wanted to know what's happening inside your PostgreSQL buffer cache?  Is your bgwriter keeping up, or are you suffering with a lot of dirty buffers during a checkpoint?

Uncloak some of the mystery by using the pg_buffercache extension.

CREATE EXTENSION pg_buffercache;

You can then use the following query, and plot the results into your favourite graphing solution:

SELECT buffer_status, sum(count) AS count

  FROM (SELECT CASE isdirty

                 WHEN true THEN 'dirty'

                 WHEN false THEN 'clean'

                 ELSE 'empty'

               END AS buffer_status,

               count(*) AS count

          FROM pg_buffercache

          GROUP BY buffer_status

        UNION ALL

          SELECT * FROM (VALUES ('dirty', 0), ('clean', 0), ('empty', 0)) AS tab2 (buffer_status,count)) tab1

  GROUP BY buffer_status;

The output will look like this:

postgres=# SELECT buffer_status, sum(count) AS count

  FROM (SELECT CASE isdirty

                 WHEN true THEN 'dirty'

                 WHEN false THEN 'clean'

                 ELSE 'empty'

               END AS buffer_status,

               count(*) AS count

          FROM pg_buffercache

          GROUP BY buffer_status

        UNION ALL

          SELECT * FROM (VALUES ('dirty', 0), ('clean', 0), ('empty', 0)) AS tab2 (buffer_status,count)) tab1

  GROUP BY buffer_status;

 buffer_status | count

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

 clean         |    544

 dirty         |     18

 empty         | 523726

(3 rows)

And whenever there is a checkpoint, the dirty count should go to zero:

postgres=# checkpoint;

CHECKPOINT

postgres=# SELECT buffer_status, sum(count) AS count

  FROM (SELECT CASE isdirty

                 WHEN true THEN 'dirty'

                 WHEN false THEN 'clean'

                 ELSE 'empty'

               END AS buffer_status,

               count(*) AS count

          FROM pg_buffercache

          GROUP BY buffer_status

        UNION ALL

          SELECT * FROM (VALUES ('dirty', 0), ('clean', 0), ('empty', 0)) AS tab2 (buffer_status,count)) tab1

  GROUP BY buffer_status;

 buffer_status | count

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

 clean         |    562

 dirty         |      0

 empty         | 523726

(3 rows)

ACTION: If there is a large clearance of dirty blocks during the checkpoint, then you should tune bgwriter to be more aggressive.


Should you want to get the output as one per line, then you can use crosstab:

CREATE EXTENSION tablefunc;

SELECT * FROM crosstab(
  $$
    SELECT now() sample_timestamp, buffer_status, sum(buffer_count)::int AS buffer_count
          FROM (SELECT CASE isdirty
                         WHEN false THEN 'clean'
                         WHEN true THEN 'dirty'
                         ELSE 'empty'
                       END AS buffer_status,
                       count(*) AS buffer_count
                  FROM pg_buffercache
                  GROUP BY buffer_status
                UNION ALL
                  SELECT * FROM (VALUES ('clean', 0), ('dirty', 0), ('empty', 0)) AS dummy_table(buffer_status, buffer_count)
               ) outer_table
          GROUP BY buffer_status
          ORDER BY buffer_status
  $$)

AS ct(sample_timestamp timestamptz, clean int, dirty int, empty int);

The output will then look like:

       sample_timestamp        | clean | dirty | empty

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

 2018-02-02 11:38:00.915978+00 |  3108 |     0 | 521180

(1 row)

I created a test database, and ran pgbench against it whilst sampling every 10 seconds:

pgbench -i -s 100 pgbench

then

pgbench -c 32 -j 4 -P 10 -T 1200 pgbench

The database was configured with these parameters:

checkpoint_timeout = 5min

checkpoint_completion_target = 0.9

bgwriter_delay = 100ms

bgwriter_lru_maxpages = 1000

bgwriter_lru_multiplier = 3.0

The resulting graph was:

Some notable points:

1) The db_buffers is big enough to fit the entire data set, because we never run out of empty buffers (grey).

2) Work starts at #14 and the dirty buffers (orange) start to climb.

3) A checkpoint starts at #27, and dirty blocks are written to disk.  This results in clean buffers (blue) balancing out with the new dirty buffers being written.

4) This held in equilibrium until a forced manual checkpoint is done at #98.  This clears all dirty buffers to disk immediately, instead of letting bgwriter do it in a controlled fashion.

5) Things quickly get back to equilibrium.

6) The test completes at #128, and the buffers stay in their current clean/dirty/empty state.

7) Once the next timed checkpoint is triggered at #140, the dirty blocks are written to disk at the rate determined by the bgwriter parameters.

8) All dirty blocks are written to disk by #167