Эта история начиналась с процесса валидации FK на очень больших таблицах (1TB+).
Чтобы уменьшить влияние блокировок, построение внешних ключей проводилось в 2 этапа, сначала создание "NOT VALID" внешних ключей, а затем валидация внешних ключей, возможно, я напишу о некоторых проблемах с блокировками в данном процессе в другой статье.

Из своих предыдущих экспериментов я знал, что под капотом валидации (и/или создания валидных) FK Postgres выполняет вполне себе обычный SELECT.

Я решил посмотреть, каким образом выполняется данный SELECT, используя расширение pg_query_state. Данное расширение позволяет получить runtime-план выполнения запроса (и да, я использую PgPro 15, но основные выводы должны остаться неизменными и для ванильных версий Postgres).

select * from pg_query_state(1409517);


-[ RECORD 1 ]+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
pid          | 1409517
frame_number | 0
query_text   | SELECT fk."entity_id" FROM ONLY "schema1"."child_t1" fk LEFT OUTER JOIN ONLY "schema2"."parent_t1" pk ON ( pk."id" OPERATOR(pg_catalog.=) fk."entity_id") WHERE pk."id" IS NULL AND (fk."entity_id" IS NOT NULL)
plan         | Merge Anti Join (Current loop: actual rows=0, loop number=1)                                                                                                                                                                                    +
             |   Merge Cond: (fk.entity_id = pk.id)                                                                                                                                                                                                       +
             |   ->  Index Only Scan using child_t1_ix1 on child_t1 fk (Current loop: actual rows=1172306, loop number=1)                                                                                                                        +
             |         Index Cond: (entity_id IS NOT NULL)                                                                                                                                                                                                +
             |         Heap Fetches: 1172306                                                                                                                                                                                                                   +
             |   ->  Index Only Scan using parent_t1_pkey on parent_t1 pk (Current loop: actual rows=5406066, loop number=1)                                                                                                                         +
             |         Heap Fetches: 5406066
leader_pid   |

(имена реальных таблиц замаскированы)

Полученный план исполнения содержал 2 шага Index Only Scan, причём размер индексов был существенно меньше размеров таблиц. Время выполнения более 30 часов показалось мне немного неадекватным даже для таких больших сегментов.

В плане исполнения я увидел выражение Heap Fetches: "и очень большие числа здесь".
Heap Fetches согласно документации (которую я прочитал, как выяснилось, невнимательно) означает обращение к карте видимости таблицы для проверки видимости прочитанной из индекса строки ("vm" слой). Такое большое количество чтений из vm-слоя показалось мне странным, и я решил посмотреть, что происходит из "первых принципов".

Я воспользовался широко известным инструментом для Linux-систем — perf'ом. Он в достаточной степени мало инвазивен и позволяет подключиться к уже существующему процессу. Я включил трассировку событий чтения на уровне файловой системы (pread64) для соответствующего серверного процесса, примерно вот так:

perf record -e syscalls:sys_enter_pread64 -g -p <PID>

Полученный трейс содержал приблизительно следующее, полученное командой perf script:

postgres 1409517 [086] 33072155.708021: syscalls:sys_enter_pread64: fd: 0x00000068, buf: 0x7fa531af4c00, count: 0x00002000, pos: 0x1d3e6000
            7fae8e98a176 __libc_pread64+0x16 (/lib64/libpthread-2.32.so)
         11800fc00009a3a [unknown] ([unknown])

postgres 1409517 [086] 33072155.708291: syscalls:sys_enter_pread64: fd: 0x00000055, buf: 0x7fa531af6c00, count: 0x00002000, pos: 0x3380e000
            7fae8e98a176 __libc_pread64+0x16 (/lib64/libpthread-2.32.so)
         11800fc000061ef [unknown] ([unknown])

postgres 1409517 [086] 33072155.708551: syscalls:sys_enter_pread64: fd: 0x00000113, buf: 0x7fa531afcc00, count: 0x00002000, pos: 0x07050000
            7fae8e98a176 __libc_pread64+0x16 (/lib64/libpthread-2.32.so)  --- 275 DEC
         22801f00000dab1 [unknown] ([unknown])

postgres 1409517 [086] 33072155.708568: syscalls:sys_enter_pread64: fd: 0x0000005b, buf: 0x7fa531b00c00, count: 0x00002000, pos: 0x2c022000
            7fae8e98a176 __libc_pread64+0x16 (/lib64/libpthread-2.32.so)    --- 91 DEC
         11800fc00002cf7 [unknown] ([unknown])

postgres 1409517 [086] 33072155.708841: syscalls:sys_enter_pread64: fd: 0x0000009e, buf: 0x7fa531b04c00, count: 0x00002000, pos: 0x33408000
            7fae8e98a176 __libc_pread64+0x16 (/lib64/libpthread-2.32.so) --- 158 DEC
         11800fc0000a3b0 [unknown] ([unknown])

postgres 1409517 [086] 33072155.709083: syscalls:sys_enter_pread64: fd: 0x00000033, buf: 0x7fa531b0cc00, count: 0x00002000, pos: 0x0098e000
            7fae8e98a176 __libc_pread64+0x16 (/lib64/libpthread-2.32.so)  ---- 51 DEC
         22801f000007b45 [unknown] ([unknown])

Комментарии вида "51 DEC" мои: перевод из шестнадцатеричной в десятичную систему счисления.

В частности, можно увидеть, что трейс содержит fd (file descriptor). См. также описание pread64.

ssize_t pread(int fd, void *buf, size_t count, off_t offset);

В моей системе оказались установлены debug-символы для системных функций а-ля pread64, спасибо админам :) Если же debug-символов нет, то вы можете всё равно найти искомое, в $rdi регистре находится 1-ый параметр вызова функций, сошлюсь на себя любимого — ссылка.

OK, возникла следующая проблема, как "смапить" файловые дескрипторы с реальными именами файлов. К счастью, в Linux-системах это легко, идём в файловую систему /proc в директорию, соответствующую нашему серверному процессу, который занимается валидацией FK.

cd /proc/<PID>/fd
ls -ltr
lrwx------ 1 postgres postgres 64 Nov 26 09:46 90 -> /pgdata/15/data/base/1239002/1358498.44
lrwx------ 1 postgres postgres 64 Nov 26 09:46 91 -> /pgdata/15/data/base/1239002/1358498.45
lrwx------ 1 postgres postgres 64 Nov 26 09:46 92 -> /pgdata/15/data/base/1239002/1358498.46
lrwx------ 1 postgres postgres 64 Nov 26 09:46 93 -> /pgdata/15/data/base/1239002/1358498.47
lrwx------ 1 postgres postgres 64 Nov 26 09:46 94 -> /pgdata/15/data/base/1239002/1358498.48
lrwx------ 1 postgres postgres 64 Nov 26 09:46 95 -> /pgdata/15/data/base/1239002/1358498.49
lrwx------ 1 postgres postgres 64 Nov 26 09:46 96 -> /pgdata/15/data/base/1239002/1358498.50
lrwx------ 1 postgres postgres 64 Nov 26 09:46 97 -> /pgdata/15/data/base/1239002/1358498.51
lrwx------ 1 postgres postgres 64 Nov 26 09:46 98 -> /pgdata/15/data/base/1239002/1358498.52
lrwx------ 1 postgres postgres 64 Nov 26 09:46 99 -> /pgdata/15/data/base/1239002/1358498.53

Что даёт нам маппинг файловых дескрипторов на реальные имена файлов:

275 -> /pgdata/15/data/base/1239002/1358830.8
91 -> /pgdata/15/data/base/1239002/1358498.45
158 -> /pgdata/15/data/base/1239002/1358498.112
51 -> /pgdata/15/data/base/1239002/1358498.5

Далее только остаётся вычислить имена таблиц из имён файлов:

select relname,relnamespace,relkind from pg_class where relfilenode IN (1358830,1358498);

relname        |relnamespace|relkind|
---------------+------------+-------+
child_t1       |     1296292|r      |
parent_t1      |     1296291|r      |

Итак, к настоящему моменту выяснилось, что мы вычитываем из основного слоя "main" таблиц вместо карты видимости (vm-слоя).
И тут я осознал, что карта видимости для данных таблиц ещё не была построена после начального заполнения таблиц данными (вакуум/автовакуум ещё не пробегал), а в этом случае Postgres использует основной слой таблицы для проверки видимости данных, содержащихся в индексах. Эта ситуация в принципе описана в книге Егора Рогова, глава 20.2.

Тем не менее я считаю, что продемонстрированный метод имеет ценность сам по себе и может использоваться в случаях исследования проблем производительности (performance troubleshooting), предоставляя уровень детализации, схожий с Oracle Real Time SQL Monitoring (и даже немножко больше).

В заключении просуммирую проделанные манипуляции:

  • Получаем runtime-план выполнения (pg_query_state).

  • Запускаем трассировку на некоторое время (perf record -p <PID>-g -e ...).

  • Получаем отчёт perf (perf script).

  • Маппим полученные дескрипторы файлов в имена файлов (ls -ltr /proc/<PID>/fd).

  • Получаем имена таблиц из имён файлов (select * from pg_class where relfilenode IN ...).

  • Анализируем полученное и делаем далеко идущие выводы.

Комментарии (0)