Re: Handing off SLRU fsyncs to the checkpointer

Hi Thomas, hackers,

>> > To move these writes out of recovery's way, we should probably just
>> > run the bgwriter process during crash recovery.  I'm going to look
>> > into that.
>>
>> Sounds awesome.
>
>I wrote a quick and dirty experimental patch to try that.  I can't see
>any benefit from it on pgbench with default shared buffers, but maybe
>it would do better with your append test due to locality, especially
>if you can figure out how to tune bgwriter to pace itself optimally.
>https://github.com/macdice/postgres/tree/bgwriter-in-crash-recovery

OK, so I've quickly tested those two PoCs patches together, in the conditions like below:
- similar append-only workload by pgbench (to eliminate other already known different WAL bottlenecks: e.g. sorting),
- 4.3GB of WAL to be applied (mostly Btree/INSERT_LEAF)
- on same system as last time (ext4 on NVMe, 1s8c16, 4.14 kernel) 
- 14master already with SLRU fsync to checkpointer/pg_qgsort patches applied

TEST bgwriterPOC1:
- in severe dirty memory conditions (artificially simulated via small s_b here) --> so for workloads with very high FlushBuffer activity in StartupXLOG
- with fsync=off/fpw=off by default and on NVMe (e.g. scenario:  I want to perform some PITR as fast as I can to see how production data looked like in the past, before some user deleted some data)

baseline s_b@128MB: 140.404, 0.123 (2nd small as there is small region to checkpoint)

    22.49%  postgres  [kernel.kallsyms]   [k] copy_user_enhanced_fast_string
            ---copy_user_enhanced_fast_string
               |--14.72%--copyin
               |          __pwrite_nocancel
               |          FileWrite
               |          mdwrite
               |          FlushBuffer
               |          ReadBuffer_common
               |           --14.52%--btree_xlog_insert
                --7.77%--copyout
                          __pread_nocancel
                           --7.57%--FileRead
                                     mdread
                                     ReadBuffer_common
     6.13%  postgres  [kernel.kallsyms]   [k] do_syscall_64
               |--1.64%--__pwrite_nocancel
                --1.23%--__pread_nocancel
     3.68%  postgres  postgres            [.] hash_search_with_hash_value
            ---hash_search_with_hash_value
               |--1.02%--smgropen

After applying:
patch -p1 < ../0001-Run-checkpointer-and-bgworker-in-crash-recovery.patch
patch -p1 < ../0002-Optionally-don-t-wait-for-end-of-recovery-checkpoint.patch

0001+0002 s_b@128MB: similar result to above
0001+0002 s_b@128MB: 108.871, 0.114 , bgwriter_delay = 10ms/bgwriter_lru_maxpages = 1000
0001+0002 s_b@128MB: 85.392, 0.103 , bgwriter_delay = 10ms/bgwriter_lru_maxpages = 50000 #~390MB max?

    18.40%  postgres  [kernel.kallsyms]   [k] copy_user_enhanced_fast_string
            ---copy_user_enhanced_fast_string
               |--17.79%--copyout
               |          __pread_nocancel
               |          |--16.56%--FileRead
               |          |          mdread
               |          |          ReadBuffer_common
                --0.61%--copyin // WOW
                          __pwrite_nocancel
                          FileWrite
                          mdwrite
                          FlushBuffer
                          ReadBuffer_common
     9.20%  postgres  postgres            [.] hash_search_with_hash_value
            ---hash_search_with_hash_value
               |--4.70%--smgropen

of course there is another WOW moment during recovery ("61.9%")

USER        PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
postgres 120935  0.9  0.0 866052  3824 ?        Ss   09:47   0:00 postgres: checkpointer
postgres 120936 61.9  0.0 865796  3824 ?        Rs   09:47   0:22 postgres: background writer
postgres 120937 97.4  0.0 865940  5228 ?        Rs   09:47   0:36 postgres: startup recovering 000000010000000000000089

speedup of 1.647x when dirty memory is in way. When it's not:

baseline  s_b@24000MB: 39.199, 1.448 (2x patches off)
0001+0002 s_b@24000MB: 39.383, 1.442 , bgwriter_delay = 10ms/bgwriter_lru_maxpages = 50000 #~390MB/s max, yay

there's no regression. I have only one comment about those 2 WIP patches, bgwriter_lru_maxpages should be maybe called standby_bgwriter_lru_maxpages in this scenario or even more preferred there shouldn't be a maximum set during closed DB recovery scenario.

TEST bgwriterPOC2a to showcase the 2nd patch which opens the DB for read-write users before the final checkpoint finishes after redo recovery. The DBA may make the decision via this parameter end_of_recovery_checkpoint_wait=off.
- on slow storage (xvda, fsync=on) and even with high memory:

s_b@24000MB: 39.043, 15.639 -- even with WAL recovery being 100% CPU bound(mostly on hash_search_with_hash_value() for Buffers/__memmove_ssse3_back), it took additional 15s to perform checkpoint before DB was open for users (it had to write 269462 buffers =~ 2GB =~ 140MB/s which is close to the xvda device speed): the complete output looks in 14master looks similar to this:

1598609928.620 startup 22543 LOG:  redo done at 1/12201C88
1598609928.624 checkpointer 22541 LOG:  checkpoint starting: end-of-recovery immediate wait
1598609944.908 checkpointer 22541 LOG:  checkpoint complete: wrote 269462 buffers (8.6%); 0 WAL file(s) added, 0 removed, 273 recycled; write=15.145 s, sync=0.138 s, total=16.285 s; sync files=11, longest=0.133 s, average=0.012 s; distance=4468855 kB, estimate=4468855 kB
1598609944.912 postmaster 22538 LOG:  database system is ready to accept connections

s_b@24000MB: 39.96, 0 , with end_of_recovery_checkpoint_wait = off, before DB is open 15s faster 

1598610331.556 startup 29499 LOG:  redo done at 1/12201C88
1598610331.559 checkpointer 29497 LOG:  checkpoint starting: immediate force
1598610331.562 postmaster 29473 LOG:  database system is ready to accept connections
1598610347.202 checkpointer 29497 LOG:  checkpoint complete: wrote 269462 buffers (8.6%); 0 WAL file(s) added, 0 removed, 273 recycled; write=15.092 s, sync=0.149 s, total=15.643 s; sync files=12, longest=0.142 s, average=0.012 s; distance=4468855 kB, estimate=4468855 kB

I suppose a checkpoint for large shared_buffers (hundredths of GB) might take a lot of time and this 0002 patch bypasses that. I would find it quite useful in some scenarios (e.g. testing backups, PITR recoveries, opening DB from storage snapshots / storage replication, maybe with DWH-after-crash too).

TEST bgwriterPOC2b: FYI, I was also testing the the hot_standby code path -- to test if it would reduce time of starting / opening a fresh standby for read-only queries, but this parameter doesn't seem to influence that in my tests. As I've learned it's apparently much more complex to reproduce what I'm after and involves a lot of reading about LogStandbySnapshot() / standby recovery points on my side.

Now, back to smgropen() hash_search_by_values() reproducer...

-Jakub Wartak.