[GENERAL] Strange checkpoint behavior - checkpoints take a long time - Mailing list pgsql-general

I have a large database, 1.3 TB, with quite a bit of write activity. The machine has, 2 cpus x 6 cores x 2 threads (2 x E5-2630 v2 @ 2.60GHz), 4 x EVO Pro 2TB SSDs in a RAID 1+0 software raid configuration, on a SATA 3 controller.

The machine has a lot of memory, 384 GB, so it doesn’t do a lot of reads, as most of the frequently accessed data is cached.

Reads are between 5-10 MB/s on each SSD, giving a total of about 20-30 MB/s for the entire RAID volume.

Each SSD writes on average 30-40 MB/s, so overall the RAID writes on 2 mirrors at 60-80 MB/s each, so 120-160 MB/s total writes.

According to AnandTech benchmarks, those SSDs should be able to do around 90 MB/s random reads and 250 MB/s random writes at 4KB block size, so in theory I shouldn’t hit I/O limits even if all I/O was random and very small.

I estimate the SSDs should be about 10% busy from the reads and 15% busy from the writes, so maybe 25% total.

However sar -d shows %util on those SSDs between 70% and 80% under the normal daily load. But with SSDs, you can’t really trust fully the %util reported by sar, because SSDs perform best at large queue sizes. Average queue size reported by sar is between 5 and 10, so I’m not entirely sure if I should trust it or not for the %util values. A queue size of 8 and larger should be enough to keep most SSDs busy, but in that case I would expect %util to be 100% all the time.

Still, based on what sar is showing, I am concerned about hitting an I/O performance wall as the activity on that database might increase in the future, and I was trying to determine the actual limits, especially for writes. While doing that, I started to investigate the checkpoint behavior.

The database is configured with:

         - the default checkpoint timeout interval of 5 minutes (not set explicitly). It’s probably not long enough, I plan to increase it to something like 30 minutes, or more.

         - checkpoint_warning with the default at 30 seconds. Not sure if that is measured between the end of the previous checkpoint and the start of the next one, or between the start times (or end times) of two consecutive checkpoints.

         - completion target of 0.85, so it should write for 4:15 minutes every 5 minutes.

         - max_wal_size = 16 GB, I plan to increase it to something like 96 GB.

         - 96 GB of shared buffers. I may increase them to something like 144 GB

         - bgwriter with 400 max pages and the default 200ms delay. That should result in 400 x 5 x 8kb pages / second max, so 16 MB/s max from the bgwriter. It’s probably too much and I should have left it to the default value of 100 pages, or even lower. In fact I’m not even sure why I even need the bgwriter process instead of using just checkpoints for writes. In any case, even with 400 pages, it should still leave some work for the checkpoint process.

         - wal_buffers of 32 MB, I had them as high as 256 MB as some point, but it seems values larger than 16MB are useless, I will reduce it to 16MB.

The log of the last checkpoints looks like this when the machine is idle in the morning:

2017-10-04 08:43:00.283 EDT [7831] LOG:  checkpoint starting: time

2017-10-04 08:47:15.887 EDT [7831] LOG:  checkpoint complete: wrote 19290 buffers (0.2%); 0 transaction log file(s) added, 4 removed, 0 recycled; write=254.787 s, sync=0.794 s, total=255.604 s; sync files=274, longest=0.033 s, average=0.002 s; distance=61864 kB, estimate=322398 kB

So it does take the 5 minutes and 0.85% seconds into account well. 300 x 0.85  = 255 seconds, and it did indeed spread the writes over 255 seconds.

However, later during the day, as the activity increases it starts to look like this:

2017-10-04 08:48:00.932 EDT [7831] LOG:  checkpoint starting: time

2017-10-04 08:55:27.179 EDT [7831] LOG:  checkpoint complete: wrote 635481 buffers (5.1%); 0 transaction log file(s) added, 4 removed, 0 recycled; write=442.133 s, sync=4.003 s, total=446.246 s; sync files=445, longest=0.118 s, average=0.008 s; distance=5227434 kB, estimate=5227434 kB

First, a checkpoint finished in 446 seconds instead of 255 seconds. 635481 buffers in 446 seconds, 1425 buffers/second, around 12 MB/second. I would say that’s not such a huge amount of I/O for the hardware. Then the next starts immediately:

2017-10-04 08:55:27.180 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 09:05:23.391 EDT [7831] LOG:  checkpoint complete: wrote 2090424 buffers (16.6%); 0 transaction log file(s) added, 319 removed, 0 recycled; write=595.690 s, sync=0.468 s, total=596.211 s; sync files=454, longest=0.020 s, average=0.001 s; distance=11415997 kB, estimate=11415997 kB

This one takes even longer 596 seconds. 2090424 buffers, 3500 buffers/second, around 29 MB/second. That should still not be such a big deal, it would mean writing at around 15 MB/s on each SSD just for checkpoints.

So, not sure what is going on here. I could understand that the checkpoint process is surprised by the sudden increase in writes at the beginning of the day, and the first 2-3 checkpoints would take more than the configured duration. But even the next checkpoints follow the same pattern of taking more than 255 seconds, and sometimes more than 300 seconds:

2017-10-04 09:05:23.392 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 09:12:54.799 EDT [7831] LOG:  checkpoint complete: wrote 1342046 buffers (10.7%); 0 transaction log file(s) added, 697 removed, 0 recycled; write=450.554 s, sync=0.791 s, total=451.406 s; sync files=706, longest=0.014 s, average=0.0

01 s; distance=8478044 kB, estimate=11122202 kB

2017-10-04 09:12:54.801 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 09:17:49.897 EDT [7831] LOG:  checkpoint complete: wrote 1220559 buffers (9.7%); 0 transaction log file(s) added, 376 removed, 141 recycled; write=292.734 s, sync=0.677 s, total=295.096 s; sync files=690, longest=0.026 s, average=0.

000 s; distance=8551073 kB, estimate=10865089 kB

2017-10-04 09:17:54.903 EDT [7831] LOG:  checkpoint starting: time

2017-10-04 09:22:19.092 EDT [7831] LOG:  checkpoint complete: wrote 864467 buffers (6.9%); 0 transaction log file(s) added, 213 removed, 309 recycled; write=258.673 s, sync=1.379 s, total=264.188 s; sync files=672, longest=0.034 s, average=0.0

02 s; distance=5986866 kB, estimate=10377266 kB

2017-10-04 09:22:54.127 EDT [7831] LOG:  checkpoint starting: time

2017-10-04 09:27:22.678 EDT [7831] LOG:  checkpoint complete: wrote 962442 buffers (7.6%); 0 transaction log file(s) added, 176 removed, 190 recycled; write=265.684 s, sync=0.603 s, total=268.550 s; sync files=689, longest=0.018 s, average=0.0

00 s; distance=6278971 kB, estimate=9967437 kB

2017-10-04 09:27:22.679 EDT [7831] LOG:  checkpoint starting: xlog

2017-10-04 09:32:08.082 EDT [7831] LOG:  checkpoint complete: wrote 1206510 buffers (9.6%); 0 transaction log file(s) added, 200 removed, 183 recycled; write=282.610 s, sync=0.622 s, total=285.402 s; sync files=683, longest=0.013 s, average=0.000 s; distance=7412886 kB, estimate=9711982 kB

2017-10-04 09:32:22.097 EDT [7831] LOG:  checkpoint starting: time

2017-10-04 09:36:51.049 EDT [7831] LOG:  checkpoint complete: wrote 977391 buffers (7.8%); 0 transaction log file(s) added, 218 removed, 234 recycled; write=264.946 s, sync=0.939 s, total=268.952 s; sync files=671, longest=0.032 s, average=0.001 s; distance=6576530 kB, estimate=9398437 kB

2017-10-04 09:37:09.023 EDT [7831] LOG:  checkpoint starting: xlog

2017-10-04 09:41:41.421 EDT [7831] LOG:  checkpoint complete: wrote 1051219 buffers (8.4%); 0 transaction log file(s) added, 245 removed, 157 recycled; write=269.147 s, sync=0.996 s, total=272.398 s; sync files=699, longest=0.026 s, average=0.001 s; distance=6699634 kB, estimate=9128556 kB

2017-10-04 09:41:41.423 EDT [7831] LOG:  checkpoint starting: xlog

2017-10-04 09:46:36.460 EDT [7831] LOG:  checkpoint complete: wrote 1238858 buffers (9.8%); 0 transaction log file(s) added, 260 removed, 149 recycled; write=292.544 s, sync=0.833 s, total=295.037 s; sync files=716, longest=0.033 s, average=0.001 s; distance=7551236 kB, estimate=8970824 kB

2017-10-04 09:46:36.462 EDT [7831] LOG:  checkpoint starting: xlog

2017-10-04 09:51:03.839 EDT [7831] LOG:  checkpoint complete: wrote 1038125 buffers (8.3%); 0 transaction log file(s) added, 177 removed, 283 recycled; write=263.307 s, sync=0.718 s, total=267.377 s; sync files=708, longest=0.027 s, average=0.001 s; distance=6799399 kB, estimate=8753682 kB

2017-10-04 09:51:36.871 EDT [7831] LOG:  checkpoint starting: time

2017-10-04 09:56:30.606 EDT [7831] LOG:  checkpoint complete: wrote 913761 buffers (7.3%); 0 transaction log file(s) added, 152 removed, 263 recycled; write=288.352 s, sync=0.933 s, total=293.735 s; sync files=697, longest=0.027 s, average=0.001 s; distance=5756934 kB, estimate=8454007 kB

2017-10-04 09:56:30.607 EDT [7831] LOG:  checkpoint starting: xlog

2017-10-04 10:02:44.340 EDT [7831] LOG:  checkpoint complete: wrote 1080696 buffers (8.6%); 0 transaction log file(s) added, 189 removed, 163 recycled; write=371.377 s, sync=0.569 s, total=373.732 s; sync files=712, longest=0.014 s, average=0.000 s; distance=6734628 kB, estimate=8282069 kB

2017-10-04 10:02:44.341 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 10:10:13.903 EDT [7831] LOG:  checkpoint complete: wrote 1200040 buffers (9.5%); 0 transaction log file(s) added, 360 removed, 51 recycled; write=448.221 s, sync=0.760 s, total=449.561 s; sync files=696, longest=0.021 s, average=0.001 s; distance=7387465 kB, estimate=8192609 kB

2017-10-04 10:10:13.905 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 10:16:33.351 EDT [7831] LOG:  checkpoint complete: wrote 1472230 buffers (11.7%); 0 transaction log file(s) added, 401 removed, 50 recycled; write=377.834 s, sync=0.979 s, total=379.445 s; sync files=700, longest=0.028 s, average=0.001 s; distance=8555349 kB, estimate=8555349 kB

2017-10-04 10:16:33.352 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 10:21:58.810 EDT [7831] LOG:  checkpoint complete: wrote 1250086 buffers (9.9%); 0 transaction log file(s) added, 378 removed, 144 recycled; write=322.737 s, sync=0.888 s, total=325.457 s; sync files=680, longest=0.031 s, average=0.001 s; distance=7402273 kB, estimate=8440041 kB

2017-10-04 10:21:58.811 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 10:27:09.544 EDT [7831] LOG:  checkpoint complete: wrote 1171682 buffers (9.3%); 0 transaction log file(s) added, 264 removed, 188 recycled; write=307.983 s, sync=0.796 s, total=310.732 s; sync files=688, longest=0.026 s, average=0.001 s; distance=7018008 kB, estimate=8297838 kB

2017-10-04 10:27:09.546 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 10:34:16.507 EDT [7831] LOG:  checkpoint complete: wrote 1088387 buffers (8.6%); 0 transaction log file(s) added, 343 removed, 85 recycled; write=425.445 s, sync=0.480 s, total=426.961 s; sync files=670, longest=0.012 s, average=0.000 s; distance=6695430 kB, estimate=8137597 kB

Then as the activity on the database increases even more, and checkpoints start to take more than 10 minutes:

2017-10-04 10:34:16.509 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 10:45:29.233 EDT [7831] LOG:  checkpoint complete: wrote 1445250 buffers (11.5%); 1 transaction log file(s) added, 409 removed, 0 recycled; write=671.755 s, sync=0.832 s, total=672.724 s; sync files=687, longest=0.039 s, average=0.001 s; distance=8688405 kB, estimate=8688405 kB

2017-10-04 10:45:29.235 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 11:04:48.081 EDT [7831] LOG:  checkpoint complete: wrote 1929827 buffers (15.3%); 1 transaction log file(s) added, 530 removed, 0 recycled; write=1156.147 s, sync=2.487 s, total=1158.846 s; sync files=704, longest=0.046 s, average=0.003 s; distance=12851319 kB, estimate=12851319 kB

Then more than 20 minutes:

2017-10-04 11:04:48.082 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 11:25:55.806 EDT [7831] LOG:  checkpoint complete: wrote 2695524 buffers (21.4%); 0 transaction log file(s) added, 784 removed, 0 recycled; write=1257.586 s, sync=10.070 s, total=1267.723 s; sync files=709, longest=0.117 s, average=0.014 s; distance=20710817 kB, estimate=20710817 kB

2017-10-04 11:25:55.807 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 11:48:08.366 EDT [7831] LOG:  checkpoint complete: wrote 2857107 buffers (22.7%); 0 transaction log file(s) added, 1264 removed, 0 recycled; write=1326.199 s, sync=6.233 s, total=1332.558 s; sync files=726, longest=0.076 s, average=0.008 s; distance=24439493 kB, estimate=24439493 kB

2017-10-04 11:48:08.368 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 12:11:39.550 EDT [7831] LOG:  checkpoint complete: wrote 3127276 buffers (24.9%); 0 transaction log file(s) added, 1492 removed, 0 recycled; write=1403.735 s, sync=7.293 s, total=1411.182 s; sync files=732, longest=0.071 s, average=0.009 s; distance=27967471 kB, estimate=27967471 kB

2017-10-04 12:11:39.552 EDT [7831] LOG:  checkpoint starting: xlog time

2017-10-04 12:32:28.853 EDT [7831] LOG:  checkpoint complete: wrote 2823207 buffers (22.4%); 0 transaction log file(s) added, 1707 removed, 0 recycled; write=1236.280 s, sync=12.828 s, total=1249.300 s; sync files=739, longest=0.133 s, average=0.017 s; distance=28321252 kB, estimate=28321252 kB

There are no “checkpoints are occurring too frequently” messages in the logs, and since a checkpoint starts as soon as the previous one ends, not in over 30 seconds as I configured the warning, in my opinion there should have been warnings, but there aren’t. Probably the warning measures start to start, or end to end, not end to start. The lack of a warning made me even more confused and made me lose a lot of time trying to figure this out, until I noticed the long durations.

In any case, I still don’t fully understand what is happening here. It looks like I’m hitting some hardware limits, but it’s not obvious. The CPU usage is around 20% user, 4% system, and Linux also reports 10-15% iowait, so the machine looks a bit stressed on the I/O side and a bit less on the CPU side, but again, I can’t be sure.

The longest checkpoint today at 11:48 AM took 1411 seconds and has written 3127276 buffers, so 2216 buffers/second. That’s just 18 MB/second, so 9 MB/second on each SSD from checkpoints. In fact earlier in the day it had a shorter checkpoint that did 29 MB/second, so I think this larger one could have completed faster.

The sar disk I/O report was looking like this during this 1411 long checkpoint:

11:55:01 AM       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util

12:05:01 PM   dev8-16   2478.72  17412.49  64107.22     32.89      7.02      2.83      0.31     77.79

12:05:01 PM    dev8-0   2139.80  10546.02  64153.14     34.91      7.16      3.34      0.35     75.27

12:05:01 PM   dev8-32   2155.46  10881.22  64075.18     34.78      6.84      3.17      0.35     75.08

12:05:01 PM   dev8-48   2497.76  17701.13  64153.14     32.77      7.90      3.16      0.31     77.52

12:05:01 PM    dev9-0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00

12:05:01 PM    dev9-1   5873.69  60126.95 126219.54     31.73      0.00      0.00      0.00      0.00

9-1 is the RAID, and 8-0, 8-16, 8-32, 8-48 the SSDs. So around 32 MB/s writes and 7 MB/s reads on each SSD. In theory the SSDs should be easily able to handle that level of I/O, so I’m suspecting something else might be slowing the checkpoints.

Could there be some inefficiency or bug in the checkpoint process making it not work as fast as it should? Or something I may have configured improperly triggering this behavior?

Thanks,

Vlad