Эта статья перевод статьи известного специалиста в области Oracle (но про Postgres) — Фрица Хугланда — https://databaseperformance.hashnode.dev/using-bpftrace-for-postgres-query-execution-tracing.

Понимание, на что тратится время запроса в PostgreSQL, немного запутанно и сбивает с толку. Чтобы понять, что я подразумеваю под "запутанно", нужно понимать фундаментальную концепцию разных фаз исполнения запросов в PostgreSQL, это:

• Parse
• Rewrite
• Plan
• Execute

Эти фазы[1] должны быть выполнены в порядке очерёдности до того, как финальная фаза (Execute) сможет выполнить фактически посланный запрос.

pg_stat_statements

Во многих случаях pg_stat_statements используется для просмотра времени, затраченного на выполнение запроса, используя столбец total_time (до версии PostgreSQL 12) или total_exec_time (версия PostgreSQL 13 или выше). Оба столбца показывают время, затраченное только на этапе “Execute”.

С добавлением в pg_stat_statement в PostgreSQL версии 13 столбца total_plan_time, тот факт, что total_time(total_exec_time) — это неполная картина, становится несколько более очевидным. Становится понятно, что total_exec_time нуждается в большей детализации. Однако при этом по-прежнему не учитываются этапы Plan и Parse.

log_min_duration_statement

log_min_duration_statement
Насколько я вижу, большинство утилит для работы с базами данных PostgreSQL не учитывают общее время выполнения, которое включает все этапы за единственным исключением log_min_duration_statement(!). Когда значение log_min_duration_statement установлено больше 0 и время выполнения запроса превышает это значение, то PostgreSQL регистрирует текст запроса и продолжительность (time) для фактического общего времени для «simple query protocol» или разделяет время исполнения на parse (состоящий из фазы Parse и фазы Rewrite), bind (включает фазу Plan) и execute (включает/состоит из фазы Execute) для «extended query protocol» — https://www.postgresql.org/docs/current/protocol-overview.html#PROTOCOL-QUERY-CONCEPTS.

Логирование происходит в центральном файле журнала PostgreSQL и эти измерения пытаются дать картину времени исполнения, так как оно видно со стороны клиента базы данных, но это не является точной регистрацией фактических фаз выполнения на стороне сервера.

bpftrace: query-analyzer.bt

Что делать, если вы хотите внимательно отслеживать происходящее с точки зрения этапов выполнения на стороне сервера? Это как раз то, что делает query-analyzer.bt: отслеживает основные фазы выполнения parse, rewrite, plan and execute и подсчитывает их время. В настоящее время он предназначен для «трейсинга» или отладки одной или нескольких сессий. Доступно через: github.com/FritsHoogland/postgres-bpftrace…
Примечание: похоже, что исполняемые файлы postgres, доступные в Docker и в форматах deb и rpm уже имеют необходимые «пробы» (USDT probes). Что позволяет query-analyzer.bt использовать эти «пробы».
Вот как это выглядит:

root@d3afc158acbe:/# ./postgres-bpftrace/query-analyzer.bt
Attaching 19 probes...
PostgreSQL statement execution analyzer.
Time in microseconds (us).
pid   :Phase      :time to phase :time in phase : query
------|-----------|--------------|--------------|------
[13432]Query start:              :              : select '1';
[13432] parse     : (       667) :            66: select '1';
[13432] rewrite   : (        58) :            51: select '1';
[13432] plan      : (        43) :           175: select '1';
[13432] execute   : (       430) :          1230: select '1';
[13432]Query done : (      1791) :          4515: select '1';

simple query protocol execution

Это запрос select '1';, выполненный из psql. Утилита/клиент psql в настоящее время всегда использует протокол simple query protocol. “simple query protocol” выполняет все шаги исполнения (parse … execute), но все они отправляются на сервер базы данных одним куском, с токеном Q.

Начало этого единого шага исполнения маркируется как Query start и окончание как Query done.

Как только запрос запущен, он должен быть синтаксически проанализирован, что и выполняется на этапе Parse. Время “time to phase” показывает, сколько реального (астрономического) времени затрачивается на переход в фазу с предыдущей фазы. Для “parse” это означает время между стартом серверного процесса PostgreSQL выполняющего запрос и до старта фазы синтаксического разбора.

Следующий шаг фаза “rewrite”. Фаза “rewrite” выполняет 2 задачи: выполняет семантический разбор (такой как: существует ли эта таблица и есть ли к ней доступ у текущего пользователя) и собственно шаг перезаписи/трансформации, если необходимо (например, представления требуют перезаписи в фактический запрос).

Обе фазы “parse” и “rewrite” работают, используя дерево синтаксического анализа, и это дерево используется далее планировщиком, который создаёт дерево исполнения для последнего шага(фазы), executor’a. Задача планировщика вычислить наиболее эффективный способ выполнения с учетом опций, которые допускают задействованные объекты базы данных (например, использование индекса или выполнение последовательного сканирования).
Все это приводит к фазе исполнения, которая берет дерево исполнения и выполняет фактическую работу по получению результата с учетом дерева выполнения, которое было получено из предоставленного выражения.

extended query protocol execution

Если то же выражение берется и выполняется с использованием протокола расширенного запроса, это выглядит следующим образом:

[13444] parse     : (         0) :           173: select '1'
[13444] rewrite   : (        77) :           171: select '1'
[13444] plan      : (       943) :           198: select '1'
[13444] execute   : (       103) :            36: select '1'

Это такие же шаги, но мы теряем общее время запроса. У этого есть очень веская причина: используя протокол расширенных запросов, клиент запрашивает выполнение отдельных шагов независимо друг от друга вместо использования одного шага, включающего все эти шаги, которые мы видели выше в протоколе простых запросов.

Протокол расширенных запросов позволяет отправлять несколько фаз в одном запросе, отправляемом на сервер базы данных, либо индивидуальные фазы по раздельности. Наиболее распространенными вызовами протокола расширенных запросов являются:
• Синтаксический анализ (Parse): который содержит как фазы синтаксического анализа на стороне сервера, так и фазы перезаписи.
• Привязка (Bind): которая содержит фазу планирования на стороне сервера.
• Выполнение (Execute): который содержит фазу выполнения на стороне сервера.

Пробы (usdt probes), которые использует query-analyzer.bt расположены внутри индивидуальных фаз – parse, rewrite, plan and execute, вот почему анализатор может показывать эти фазы как для “simple query protocol” так и для “extended query protocol”, несмотря на разные протоколы, они выполняют одни и те же базовые фазы обработки.

not-so-strict phases

С помощью query-analyzer.bt вы можете видеть, что происходит при обработке запроса. Это также позволяет проверить рекомендации, которые я выполнял в прошлом по использованию prepared statements, и должен ли PostgreSQL всегда выполнять все эти этапы, несмотря ни на что.
Посмотрим на очень простой пример:

[13432]Query start:              :              : set log_min_duration_statement=-1;
[13432] parse     : (       273) :           366: set log_min_duration_statement=-1;
[13432] rewrite   : (       117) :            89: set log_min_duration_statement=-1;
[13432] execute   : (       698) :           246: set log_min_duration_statement=-1;
[13432]Query done : (       181) :          1973: set log_min_duration_statement=-1;

Вы заметили эту странность? Фаза plan исчезла! Для этого есть очень веская причина: серверная часть выполняет работу, которая не является SQL, и, следовательно, она не нуждается в планировании; она может выполнить запрошенную задачу установки переменной (сеанса) напрямую; следовательно, execute выполняется не с использованием дерева выполнения, а выполняет изменение переменной напрямую.

Давайте рассмотрим другой пример:

[13432]Query start:              :              : prepare t as select now();
[13432] parse     : (       770) :           787: prepare t as select now();
[13432] rewrite   : (       396) :           112: prepare t as select now();
[13432] rewrite   : (      1194) :          1897: prepare t as select now();
[13432] execute   : (       851) :          2405: prepare t as select now();
[13432]Query done : (       117) :          5441: prepare t as select now();

Здесь есть 2 фазы rewrite, вполне вероятно, первая из-за фактического исполнения, а вторая для того, чтобы сделать prepare этого выражения, которое должно стать «prepared statement». Также здесь отсутствует фаза планирования(plan).

Как вы могли бы предположить, выполнение «prepared statement» в psql также приведет к нестандартной последовательности:

[13501]Query start:              :              : execute t;
[13501] parse     : (        47) :            27: execute t;
[13501] rewrite   : (        44) :             9: execute t;
[13501] plan      : (       173) :            42: execute t;
[13501] execute   : (         0) :            50: execute t;
[13501] execute   : (       124) :           444: execute t;
[13501]Query done : (        86) :           783: execute t;

Обработка запроса сначала проходит ожидаемые этапы, а затем требуется дополнительное выполнение для execute t.
Однако я предполагаю, что использование prepared statement в psql в большинстве ситуаций будет исключением. Вот как выглядит выполнение prepared statement, когда оно выполняется с помощью протокола расширенных запросов:

[13523] parse     : (         0) :           146: select $1
[13523] rewrite   : (        46) :           103: select $1
[13523] plan      : (       957) :           122: select $1
[13523] execute   : (       102) :            41: select $1
[13523] plan      : (       470) :            12: select $1
[13523] execute   : (        82) :             4: select $1

Это полностью (как я и ожидал): выполнение инструкции сначала проходит фазы синтаксического анализа, перезаписи, планирования и выполнения, когда prepared statement выполняется первый раз, а второе выполнение, которое явно использует prepared statement, может пропустить фазы синтаксического анализа и перезаписи. Prepared statement сохраняет результат шагов parse и rewrite, так что их не нужно выполнять повторно.

Когда я попытался придумать как можно более простой пример, я выполнил описанное выше без переменной, и используемые фазы выглядели следующим образом:

[13522] parse     : (         0) :           290: select '1'
[13522] rewrite   : (       144) :           260: select '1'
[13522] plan      : (      1173) :           364: select '1'
[13522] execute   : (       161) :           209: select '1'
[13522] execute   : (       831) :             4: select '1'

Если выражение не имеет фильтров, то нет переменных, которые могли бы изменить план, и, таким образом, выполнение подготовленного оператора может пропустить фазу планирования и выполнить только фазу выполнения. Это требует, чтобы логика присутствовала и в клиенте, который в конечном счете является тем, кто запрашивает эти шаги/фазы.
Еще одна конструкция, которая выполняет что-то, что противоречит общему шаблону:

insert into select:
[13501]Query start:              :              : insert into t select id, repeat('x',10) from generate_series(1,
[13501] parse     : (        72) :            57: insert into t select id, repeat('x',10) from generate_series(1,
[13501] rewrite   : (        44) :           693: insert into t select id, repeat('x',10) from generate_series(1,
[13501] plan      : (       418) :           165: insert into t select id, repeat('x',10) from generate_series(1,
[13501] execute   : (         0) :           814: insert into t select id, repeat('x',10) from generate_series(1,
[13501] execute   : (        62) :           892: insert into t select id, repeat('x',10) from generate_series(1,
[13501]Query done : (      1908) :          4314: insert into t select id, repeat('x',10) from generate_series(1,

Я почти уверен, что это работает с несколькими «порталами» (см. определение портала https://www.programmersought.com/article/29581586522/) на этапе выполнения, где первым «порталом» является insert, и он обнаруживает, что ему необходимо выполнить select на втором «портале», чтобы получить результаты, которые затем используются для выполнения insert.
Наконец, то, что довольно радикально может изменить последовательность этапов, — это конвейерная обработка выполнения:

[13530] parse     : (         0) :           207: select 'one'
[13530] rewrite   : (        81) :           161: select 'one'
[13530] parse     : (         0) :            15: select 'two'
[13530] rewrite   : (        11) :             4: select 'two'
[13530] parse     : (         0) :             3: select 'three'
[13530] rewrite   : (        63) :             5: select 'three'
[13530] plan      : (       856) :           214: select 'one'
[13530] execute   : (       215) :            55: select 'one'
[13530] plan      : (       149) :             9: select 'two'
[13530] execute   : (        30) :             4: select 'two'
[13530] plan      : (        36) :             4: select 'three'
[13530] execute   : (        19) :             3: select 'three'

Каждый из трех операторов анализируется, а затем выполняется.
Анализатор запросов: github.com/FritsHoogland/postgres-bpftrace

[1] Эти 4 фазы должны быть выполнены: я постарался объяснить общий подход к задаче, но в некоторых случаях эти шаги могут быть пропущены.