О «залипании» процесса checkpoint и archive_timeout в Postgres

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

Недавно мы столкнулись со следующей проблемой при тестировании СУБД 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.