Эта публикация — перевод второй статьи известного специалиста в области Oracle Фрица Хугланда на заданную тему (первую статью я перевёл ранее см. Использование bpftrace для трассировки выполнения запросов в postgres)
Это то, чего не существует в PostgreSQL на момент написания статьи. Однако добавить это (timed wait events) чрезвычайно просто, причем с незначительными накладными расходами. Накладные расходы — это классическая причина, по которой PostgreSQL не добавляет "Timed wait events".
Мы можем косвенно добавить эти времена ожидания, добавив пробу (probe) к функциям запуска и завершения события ожидания (функции pgstat_report_wait_start() и pgstat_report_wait_end()), перед компиляцией и линковкой исходного кода. Имея такую пробу, мы можем использовать bpftrace (или SystemTap), чтобы отслеживать события начала и окончания ожидания, а также просматривать и засекать время событий ожидания.
Добавить такие пробы просто. Необходимо добавить всего 5 линий кода в исходный код PostgreSQL, чтобы появились 2 новые пробы: начала события ожидания и окончания события ожидания (wait event start and wait event end).
Добавьте пробы в файл, который содержит функции pgstat_report_wait_start() and pgstat_report_wait_end(); (это файл — src/include/utils/wait_event.h)
diff --git a/src/include/utils/wait_event.h b/src/include/utils/wait_event.h
index 009b03a520..f3b06113e9 100644
--- a/src/include/utils/wait_event.h
+++ b/src/include/utils/wait_event.h
@@ -28,6 +28,9 @@
/* enums for wait events */
#include "utils/wait_event_types.h"
+/* pg_trace for TRACE_POSTGRESQL macros */
+#include "pg_trace.h"
+
extern const char *pgstat_get_wait_event(uint32 wait_event_info);
extern const char *pgstat_get_wait_event_type(uint32 wait_event_info);
static inline void pgstat_report_wait_start(uint32 wait_event_info);
@@ -87,6 +90,7 @@ extern char **GetWaitEventExtensionNames(int *nwaitevents);
static inline void
pgstat_report_wait_start(uint32 wait_event_info)
{
+ TRACE_POSTGRESQL_WAIT_EVENT_START(wait_event_info);
/*
* Since this is a four-byte field which is always read and written as
* four-bytes, updates are atomic.
@@ -103,6 +107,7 @@ pgstat_report_wait_start(uint32 wait_event_info)
static inline void
pgstat_report_wait_end(void)
{
+ TRACE_POSTGRESQL_WAIT_EVENT_END();
/* see pgstat_report_wait_start() */
*(volatile uint32 *) my_wait_event_info = 0;
}
Добавьте эти пробы в список проб в файле src/backend/utils/probes.d:
diff --git a/src/backend/utils/probes.d b/src/backend/utils/probes.d
index 0af275587b..a1e53e8e24 100644
--- a/src/backend/utils/probes.d
+++ b/src/backend/utils/probes.d
@@ -91,4 +91,8 @@ provider postgresql {
probe wal__switch();
probe wal__buffer__write__dirty__start();
probe wal__buffer__write__dirty__done();
+
+ probe wait__event__start(uint32);
+ probe wait__event__end();
+
};
Далее необходимо добавить опцию(ключ) для включения dtrace при компиляции (прим. переводчика configure --enable-dtrace ...), а также скомпилировать и слинковать исходный код PostgreSQL.
Чтобы подтвердить добавление новых проб, вы можете использовать команду bpftrace -l для вывода списка проб:
bpftrace -l 'usdt:/usr/local/pgsql/bin/postgres:wait*'
usdt:/usr/local/pgsql/bin/postgres:postgresql:wait__event__end
usdt:/usr/local/pgsql/bin/postgres:postgresql:wait__event__start
Вот они!
Я расширил скрипт query-analyzer.bt с помощью событий ожидания и получил: query-analyzer-waits.bt.
Теперь я могу использовать bpftrace и пробы, чтобы увидеть, на что расходуется время, включая события ожидания:
root@84fe326249c0:/postgres-bpftrace# ./query-analyzer-waits.bt -p 18183
Attaching 200 probes...
PostgreSQL statement execution analyzer.
Time in microseconds (us).
pid :Phase :time to phase :time in phase : query
------|-----------|--------------|--------------|------
[21964] WAIT : ( ) : 3878097701: .
[21964]Query start: : : select now();
[21964] parse : ( 113) : 318: select now();
[21964] rewrite : ( 199) : 302: select now();
[21964] plan : ( 102) : 488: select now();
[21964] execute : ( 647) : 294: select now();
[21964]Query done : ( 505) : 2972: select now();
Я выполнил select now(); в psql, мы можем видеть, что используется simple query protocol (Query start/Query done). Выполнение завершилось ожиданием, но поскольку информация о классе ожидания и имени доступна только при запуске ожидания, я не могу увидеть это здесь. Это client.CLIENT_READ ожидание.
Для такого небольшого, простого запроса вообще не возникает событие ожидания. Это немного странно. Я уверен, что результат выполнения отправляется обратно моему клиенту (psql). Получается, что эта отправка не посчитана?
Я почти уверен, что это сделано намеренно, потому что если я отправлю клиенту много данных, можно сгенерировать client.CLIENT_WRITE ожидание. Событие клиент.CLIENT_WRITE, по-видимому, является событием, которое показывает время, затраченное на отправку данных клиенту (для этого отключите пейджинг в psql: \pset pager off):
[21964] WAIT : ( ) : 22160788: client.CLIENT_READ
[21964]Query start: : : select repeat('x',1000000);
[21964] parse : ( 90) : 49: select repeat('x',1000000);
[21964] rewrite : ( 422) : 48: select repeat('x',1000000);
[21964] plan : ( 669) : 5788: select repeat('x',1000000);
[21964] WAIT : ( ) : 444: client.CLIENT_WRITE
[21964] WAIT : ( ) : 119: client.CLIENT_WRITE
[21964] WAIT : ( ) : 266: client.CLIENT_WRITE
[21964] execute : ( 98) : 1776: select repeat('x',1000000);
[21964]Query done : ( 166) : 9109: select repeat('x',1000000);
Также интересно: когда я создаю таблицу, вызов WAL write(io.WAL_WRITE) и fsync() (io.WAL_SYNC) происходит, когда фаза выполнения завершена (фаза выполнения [execute] сообщает о своем времени до io.WAL_WRITE и io.WAL_SYNC):
[21964] WAIT : ( ) : 11254040: client.CLIENT_READ
[21964]Query start: : : create table t(id int, f1 text);
[21964] parse : ( 71) : 83: create table t(id int, f1 text);
[21964] rewrite : ( 283) : 8: create table t(id int, f1 text);
[21964] WAIT : ( ) : 292: io.DATA_FILE_EXTEND
[21964] WAIT : ( ) : 116: io.DATA_FILE_EXTEND
[21964] WAIT : ( ) : 4512: io.DATA_FILE_IMMEDIATE_SYNC
[21964] execute : ( 0) : 12127: create table t(id int, f1 text);
[21964] WAIT : ( ) : 67: io.WAL_WRITE
[21964] WAIT : ( ) : 1778: io.WAL_SYNC
[21964]Query done : ( 2425) : 15252: create table t(id int, f1 text);
И если я вставляю данные, функция fsync() также выполняется вне фазы выполнения:
[21964] WAIT : ( ) : 45872174: client.CLIENT_READ
[21964]Query start: : : insert into t select id, repeat('x',10) from generate_series(1,
[21964] parse : ( 361) : 645: insert into t select id, repeat('x',10) from generate_series(1,
[21964] rewrite : ( 935) : 1296: insert into t select id, repeat('x',10) from generate_series(1,
[21964] plan : ( 97) : 2486: insert into t select id, repeat('x',10) from generate_series(1,
[21964] WAIT : ( ) : 638: io.DATA_FILE_EXTEND
[21964] execute : ( 0) : 1969: insert into t select id, repeat('x',10) from generate_series(1,
[21964] execute : ( 0) : 2131: insert into t select id, repeat('x',10) from generate_series(1,
[21964] WAIT : ( ) : 98: io.WAL_WRITE
[21964] WAIT : ( ) : 2448: io.WAL_SYNC
[21964]Query done : ( 3401) : 11518: insert into t select id, repeat('x',10) from generate_series(1,
А вот как выглядит использование TEMP'a:
[21964] WAIT : ( ) : 5325897: client.CLIENT_READ
[21964]Query start: : : select count(*) from generate_series(1,85_350);
[21964] parse : ( 94) : 41: select count(*) from generate_series(1,85_350);
[21964] rewrite : ( 115) : 58: select count(*) from generate_series(1,85_350);
[21964] plan : ( 49) : 62: select count(*) from generate_series(1,85_350);
[21964] WAIT : ( ) : 33: io.BUFFILE_WRITE
[21964] WAIT : ( ) : 8: io.BUFFILE_WRITE
[21964] WAIT : ( ) : 12: io.BUFFILE_WRITE
[21964] WAIT : ( ) : 12: io.BUFFILE_WRITE
[21964] WAIT : ( ) : 7: io.BUFFILE_WRITE
...many more io.BUFFILE_WRITEs...
[21964] WAIT : ( ) : 10: io.BUFFILE_READ
[21964] WAIT : ( ) : 6: io.BUFFILE_READ
[21964] WAIT : ( ) : 6: io.BUFFILE_READ
[21964] WAIT : ( ) : 4: io.BUFFILE_READ
[21964] WAIT : ( ) : 4: io.BUFFILE_READ
...many more io.BUFFILE_READs...
[21964] execute : ( 67) : 35538: select count(*) from generate_series(1,85_350);
[21964]Query done : ( 275) : 36303: select count(*) from generate_series(1,85_350);
Почти такое же количество Temp IO можно увидеть с помощью explain analyse (buffers).
Первый сеанс для входа в базу данных должен (повторно) создать relcache. Это делается до того, как сеанс начнет что-либо выполнять. Вот как это выглядит в моей базе данных:
[14454] WAIT : ( ) : 32: io.RELATION_MAP_READ
[14454] WAIT : ( ) : 66: io.DATA_FILE_READ
[14454] WAIT : ( ) : 10: io.RELATION_MAP_READ
[14454] WAIT : ( ) : 68: io.DATA_FILE_READ
[14454] WAIT : ( ) : 45: io.DATA_FILE_READ
[14454] WAIT : ( ) : 21: io.DATA_FILE_READ
[14454] WAIT : ( ) : 42: io.DATA_FILE_READ
[14454] WAIT : ( ) : 77: io.DATA_FILE_READ
[14454] WAIT : ( ) : 39: io.DATA_FILE_READ
[14454] WAIT : ( ) : 19: io.DATA_FILE_READ
[14454] WAIT : ( ) : 49: io.DATA_FILE_READ
[14454] WAIT : ( ) : 14: io.DATA_FILE_READ
[14454] WAIT : ( ) : 120: io.DATA_FILE_READ
[14454] WAIT : ( ) : 16: io.DATA_FILE_READ
...more io.DATA_FILE_READs
В моей базе данных без пользовательских таблиц это генерирует 2 события io.RELATION_MAP_READ и 71 событие io.DATA_FILE_READ. Они кешируются в операционной системе, и поэтому у них указанная выше мизерная задержка (задержка указана в микросекундах!).
Вполне вероятно, что это происходит не только при первом входе в систему, но и при изменении таблиц, требующем обновления relcaches, которые являются файлами. Скорее всего, они находятся за пределами фазы выполнения и, следовательно, эти события потенциально трудно обнаружить.
Фактически, операции чтения relcache также записывают init-файлы relcache при первом обращении к базе данных. Однако нет события io.RELATION_MAP_WRITE. Мне было интересно, есть ли какой-то механизм для проверки того, что существующие файлы все еще действительны, но быстрое исследование при помощи strace -fp показывает, что файлы инициализации relcache записываются, только незаметно (из-за отсутствия io.RELATION_MAP_WRITE).
Когда я выполняю первый запрос, серверная часть должна заполнить свой каталог, который также генерирует некоторые события io.DATA_FILE_READ:
[14454]Query start: : : select now();
[14454] parse : ( 316) : 811: select now();
[14454] WAIT : ( ) : 200: io.DATA_FILE_READ
[14454] WAIT : ( ) : 105: io.DATA_FILE_READ
[14454] WAIT : ( ) : 95: io.DATA_FILE_READ
[14454] WAIT : ( ) : 42: io.DATA_FILE_READ
[14454] WAIT : ( ) : 57: io.DATA_FILE_READ
[14454] WAIT : ( ) : 140: io.DATA_FILE_READ
[14454] WAIT : ( ) : 46: io.DATA_FILE_READ
[14454] WAIT : ( ) : 60: io.DATA_FILE_READ
[14454] WAIT : ( ) : 36: io.DATA_FILE_READ
[14454] WAIT : ( ) : 57: io.DATA_FILE_READ
[14454] WAIT : ( ) : 65: io.DATA_FILE_READ
[14454] WAIT : ( ) : 66: io.DATA_FILE_READ
[14454] WAIT : ( ) : 30: io.DATA_FILE_READ
[14454] WAIT : ( ) : 89: io.DATA_FILE_READ
[14454] rewrite : ( 510) : 7532: select now();
[14454] plan : ( 502) : 612: select now();
[14454] execute : ( 453) : 134: select now();
[14454]Query done : ( 322) : 11197: select now();
Важно, что они выполняются на этапе rewrite. Следовательно, фаза rewrite занимает больше времени. Эта фаза в основном не попадает в отчёты по производительности и не видна в pg_stat_statements.
drema201 Автор
Я планирую попробовать воспроизвести этот результат используя "динамические" bpf пробы (uprobe/uretprobe), но в этот раз это будет существенно сложнее потому что соответствующие функции "инлайнятся", см.
static inline void pgstat_report_wait_start(uint32 wait_event_info)