Добрый день, коллеги!

Недавно мы столкнулись со следующей проблемой при тестировании СУБД PostgresPro под высокой нагрузкой: процесс представлял собой массированную многопоточную заливку данных на протяжении многих часов,а данных было около 20 ТБ, потоков — 75.

В процессе загрузки наблюдалось следующее явление: через некоторое время процесс checkpointer переставал делать контрольные точки в зависимости от других параметров БД либо сразу, либо через 2-3 часа.
NB. checkpointer — процесс «контрольной точки», один из важнейших процессов в СУБД, который занимается сбрасыванием «грязных» дата‑блоков на дисковую подсистему, а так же некоторыми другими вещами, например, в режиме archive_mode off он «подчищает» уже ненужные WAL журналы.
Подробнее о процессе контрольной точки можно прочитать в учебных материалах pgPro, см. источник , в особенности слайд частота контрольных точек.

Поведение checkpointer'a отслеживали через

select checkpoints_req , checkpoints_timed from pg_catalog.pg_stat_bgwriter;

где:
checkpoints_timed — количество контрольных точек, сделанных по расписанию (превышение времени checkpoint_timeout).
checkpoints_req — количество контрольных точек, сделанных в результате превышения размера "сгенерённых" WAL (превышение размера max_wal_size).

В результате через 2-3 часа переполнялась файловая система, выделенная под WAL, и система "вставала".

Была проведена диагностика системы под руководством вендора, и выдана рекомендация выставить параметр archive_timeout=0.

На первый взгляд рекомендация показалась странной, т.к. на период массовой загрузки у нас выставлено archive_mode=off (т.е. WAL файлы не архивируются).

Однако профилирование perf'ом отдельно процесса checkpointer'a

perf record -F 299 -p <PID-checkpoitera> --call-graph=dwarf -a sleep 300

показало картинку ниже:

postgres 814802/814802 2409584.728453: cycles: 
                ffffffffac07c5a6 native_write_msr ([kernel.kallsyms])
                ffffffffac010656 __intel_pmu_enable_all.constprop.0 ([kernel.kallsyms])
                ffffffffac24aa90 __perf_event_task_sched_in ([kernel.kallsyms])
                ffffffffac0d6b0a finish_task_switch.isra.0 ([kernel.kallsyms])
                ffffffffacb09eb4 __schedule ([kernel.kallsyms])
                ffffffffacb0adda schedule ([kernel.kallsyms])
                ffffffffac162710 futex_wait_queue ([kernel.kallsyms])
                ffffffffac162d73 futex_wait ([kernel.kallsyms])
                ffffffffac15f876 do_futex ([kernel.kallsyms])
                ffffffffac15fd11 __x64_sys_futex ([kernel.kallsyms])
                ffffffffacafc154 do_syscall_64 ([kernel.kallsyms])
                ffffffffacc00126 entry_SYSCALL_64_after_hwframe ([kernel.kallsyms])
                           11994 futex_abstimed_wait_cancelable (inlined)
                           11994 do_futex_wait (inlined)
                           11a97 __new_sem_wait_slow (inlined)
                          438031 PGSemaphoreLock (/opt/pgpro/ent-16/bin/postgres)
                          4cb3db LWLockAcquire (/opt/pgpro/ent-16/bin/postgres)
                          203ef1 GetLastSegSwitchData (/opt/pgpro/ent-16/bin/postgres) <-------
                          43dd47 CheckArchiveTimeout (/opt/pgpro/ent-16/bin/postgres)
                          43e301 CheckpointerMain (/opt/pgpro/ent-16/bin/postgres)
                          43c551 AuxiliaryProcessMain (/opt/pgpro/ent-16/bin/postgres)
                          443921 StartChildProcess (/opt/pgpro/ent-16/bin/postgres)
                          443989 StartupSequence (/opt/pgpro/ent-16/bin/postgres)
                          448915 PostmasterMain (/opt/pgpro/ent-16/bin/postgres)
                          16525d main (/opt/pgpro/ent-16/bin/postgres)
                           27efc __libc_start_main (/lib64/libc-2.32.so)
                          1658b9 _start (/opt/pgpro/ent-16/bin/postgres)

postgres 814802/814802 2409584.728458: cycles: 
                ffffffffac07c5a6 native_write_msr ([kernel.kallsyms])
                ffffffffac010656 __intel_pmu_enable_all.constprop.0 ([kernel.kallsyms])
                ffffffffac24aa90 __perf_event_task_sched_in ([kernel.kallsyms])
                ffffffffac0d6b0a finish_task_switch.isra.0 ([kernel.kallsyms])
                ffffffffacb09eb4 __schedule ([kernel.kallsyms])
                ffffffffacb0adda schedule ([kernel.kallsyms])
                ffffffffac162710 futex_wait_queue ([kernel.kallsyms])
                ffffffffac162d73 futex_wait ([kernel.kallsyms])
                ffffffffac15f876 do_futex ([kernel.kallsyms])
                ffffffffac15fd11 __x64_sys_futex ([kernel.kallsyms])
                ffffffffacafc154 do_syscall_64 ([kernel.kallsyms])
                ffffffffacc00126 entry_SYSCALL_64_after_hwframe ([kernel.kallsyms])
                           11994 futex_abstimed_wait_cancelable (inlined)
                           11994 do_futex_wait (inlined)
                           11a97 __new_sem_wait_slow (inlined)
                          438031 PGSemaphoreLock (/opt/pgpro/ent-16/bin/postgres)
                          4cb3db LWLockAcquire (/opt/pgpro/ent-16/bin/postgres)
                          203ef1 GetLastSegSwitchData (/opt/pgpro/ent-16/bin/postgres) <------
                          43dd47 CheckArchiveTimeout (/opt/pgpro/ent-16/bin/postgres)
                          43e301 CheckpointerMain (/opt/pgpro/ent-16/bin/postgres)
                          43c551 AuxiliaryProcessMain (/opt/pgpro/ent-16/bin/postgres)
                          443921 StartChildProcess (/opt/pgpro/ent-16/bin/postgres)
                          443989 StartupSequence (/opt/pgpro/ent-16/bin/postgres)
                          448915 PostmasterMain (/opt/pgpro/ent-16/bin/postgres)
                          16525d main (/opt/pgpro/ent-16/bin/postgres)
                           27efc __libc_start_main (/lib64/libc-2.32.so)
                          1658b9 _start (/opt/pgpro/ent-16/bin/postgres)

и ещё множество стэк-трейсов подобного вида.

Т.е. мы запрашиваем LW блокировку по вот такому пути CheckArchiveTimeout -> GetLastSegSwitchData -> LWLockAcquire и безнадёжно (видимо, из-за высокой нагрузки на подсистему WAL) ждём её.

Еcли посмотреть на исходный код Postgres, то можно увидеть, что (см. ссылку)

static void
CheckArchiveTimeout(void)
{
                pg_time_t          now;
                pg_time_t          last_time;
                XLogRecPtr         last_switch_lsn;

                if (XLogArchiveTimeout <= 0 || RecoveryInProgress()) --проверка archive_timeout
                               return;

                now = (pg_time_t) time(NULL);

                /* First we do a quick check using possibly-stale local state. */
                if ((int) (now - last_xlog_switch_time) < XLogArchiveTimeout)
                               return;

                /*
                * Update local state ... note that last_xlog_switch_time is the last time
                * a switch was performed *or requested*.
                */
                last_time = GetLastSegSwitchData(&last_switch_lsn); -- ПРОБЛЕМНАЯ БЛОКИРОВКА

                last_xlog_switch_time = Max(last_xlog_switch_time, last_time);

при выставлении параметра archive_timeout в значение <=0, проблемная ветка кода выключается.

Мы попробовали выставить archive_timeout=0 и проблема действительно ушла.

Итого:

1. Параметр archive_timeout влияет на поведение системы даже при выключенной архивации WAL

2. Checkpointer при высокой нагрузке может "залипать" на получении (разделяемой) блокировки.

3. Выключение параметра archive_timeout может помочь при высокой нагрузке на подсистему WAL.