Эта история начиналась с процесса валидации 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 ...).
Анализируем полученное и делаем далеко идущие выводы.