Трассировка сессий
Функциональность доступна только для редакций Enterprise и Enterprise для ERP-систем.
Описание
СУБД Pangolin предоставляет механизм трассировки, позволяющий включать и выключать отладочную печать с различными уровнями детализации. Суперпользователь может использовать этот механизм для любой сессии, в рамках которой действие не запрещено правилами защиты от действий привилегированного пользователя.
Трассировка записывается на сервере СУБД в файл, путь к которому указывается в значении параметра сервера. Имя файла формируется по умолчанию из PID серверного процесса и уникального идентификатора, либо задается перед включением трассировки параметром на уровне сессии.
Файл трассировки представляет собой бинарный файл, содержащий записи с информацией о запросах и ожиданиях, происходивших в сессии с момента включения трассировки (включая запрос, во время выполнения которого включена трассировка).
Содержание файла трассировки:
- заголовок;
- строка-описание для каждого из запросов;
- строка-описание для каждой из фаз жизненного цикла запроса;
- переменные привязки;
- ожидания (по каждому из одиночных событий ожидания, в том числе блокировок, при соответствующем уровне трассировки);
- предварительный план по операциям (переносится в файл во время полного закрытия курсора успехом или ошибкой);
- реальный план выполнения по операциям (переносится в файл во время полного закрытия курсора успехом или ошибкой);
- ошибка при разборе или выполнении запроса;
- диагностика и стек вызовов для исключений
PL/pgSQL.
По умолчанию файл трассировки имеет имя вида: <PID>_<YYYYMMDDHHMISS>, где PID - pid процесса сессии, YYYYMMDDHHMISS - временная метка начала формирования файла трассировки во временной зоне сервера СУБД (с точностью до секунд).
Файл трассировки параллельных процессов, порождаемых трассируемой сессией, имеет формат имени <SESSION_FILE_NAME>_parallel, где SESSION_FILE_NAME - имя файла родительской трассировки для данных процессов. Все трассировки параллельных процессов сохраняются в один файл, но в процессе их формирования для каждого из процессов будет создаваться свой файл с именем <SESSION_FILE_NAME>_<WORKER_PID>_<WORKER_YYYYMMDDHHMISS>, где SESSION_FILE_NAME - имя файла родительской трассировки, WORKER_PID - PID параллельного процесса, WORKER_YYYYMMDDHHMISS - временная метка начала формирования файла трассировки параллельного процесса во временной зоне сервера СУБД (с точностью до секунд).
Виды запросов, для которых фиксируется вышеуказанная информация:
- одинарные запросы;
PL/pgSQL-запросы;- многострочные запросы;
- динамические запросы, выполняемые через
PL/pgSQL; - подготовленные запросы, выполняемые через SQL-инструкции
PREPARE,EXECUTE,DECLARE CURSORиFETCH; - подготовленные запросы, выполняемые через расширенный протокол;
- запросы, выполняемые расширениями и триггерами через
SPI; - многострочные запросы с конструкциями
SAVEPOINTиCOMMIT/ROLLBACK TO SAVEPOINT; - иерархически организованные запросы (например, запросы, выполняемые функциями расширений в процессе выполнения запросов, или динамические запросы из
PL/pgSQL). Запросы организуются в иерархическую структуру, позволяющую определить их взаимное отношение.
Уровни трассировки
Поддерживаются следующие уровни трассировки, комбинируемые через логическое ИЛИ:
NONE- значение 0, отсутствие трассировки сессии;BASE- значение 1, базовая трассировка;BIND- значение 2, добавляет вывод переменных привязки;LOCK- значение 4, добавляет вывод информации о блокировках, как LWLock, так и Lock;RESOURCE- значение 8, добавляет вывод информации о потребляемых всеми операциями ресурсах.
Чтобы изменить уровень трассировки для сессии с установленным уровнем трассировки, необходимо остановить существующую трассировку сессии (установить уровень трассировки NONE), а затем включить трассировку с обновленным уровнем. Это необходимо для явного разделения файлов трассировки по уровням. При указании того же имени файла, которое использовалось ранее, будет возвращено сообщение об ошибке, так как файл уже существует.
Настройка
Параметры настройки
| Имя параметра | Тип | Значение по умолчанию | Допустимые значения | Комментарий |
|---|---|---|---|---|
session_tracing_enable | bool | false | false/true | При включении параметра начинается накопление информации по текущему выполняемому запросу, в том числе при отсутствии включенной для сессии трассировки. Это необходимо для ее последующего сброса при включении трассировки в середине выполнения запроса. При выключении исключается влияние функциональности на производительность |
session_tracing_default_level | integer | 0 | 0..15 | Уровень трассировки по умолчанию, работает в комбинации с параметром session_tracing_roles. Комбинация уровней трассировки через логическое ИЛИ. При изменении параметра session_tracing_default_level другим пользователем с соответствующими правами, запись в файл трассировки сессии прекращается и создается новый файл, соответствующий заданному уровню |
session_tracing_file_limit | integer | -1 | -1..2147483647 | Максимальный размер файлов трассировки (в КБ). При значении -1 ограничения нет. При достижении файлом трассировки заданного лимита трассировка соответствующей сессии прекращается с выводом в лог сообщения: Session tracing file for process <PID> going to exceed size limit: <current size>/<limit>. The session's tracing will be stopped |
session_tracing_default_path | string | NULL | Строковое значение пути без ограничений | Путь к директории по умолчанию для сохранения файлов трассировки. При значении NULL используется директория $PGDATA/tracing. Значение параметра не валидируется при задании, только при попытке использования для формирования файлов трассировки |
session_tracing_roles | string | NULL | Строковое значение пути без ограничений | Список имен пользователей, через запятую, для сессий которых автоматически должна устанавливаться трассировка с уровнем session_tracing_default_level, при уровне 0 трассировка выключается |
Изменять приведенные выше параметры может только роль с правами суперпользователя. После внесения изменения требуется перезапуск СУБД.
Включение функциональности выполняется только через изменение параметра session_tracing_enable. Это обусловлено необходимостью выделения ресурсов общей памяти для обслуживания функциональности.
Включение функциональности трассировки сессий через установку настроечного параметра session_tracing_enable в значение on может привести к снижению производительности запросов. Это связано с необходимостью предварительной подготовки и накопления трассировочной информации по выполняемым запросам при включении трассировки сессии в процесс их выполнения.
Объекты
Функции API
start_session_tracing- включает трассировку для сессии с указаннымPID, уровнем трассировки, и, опционально, именем файла;stop_session_tracing- выключает трассировку для сессии с указаннымPID;psql_session_tracing- выводит список сессий с указанием их уровня трассировки и путей к файлам трассировки.
Функции API описаны в разделе «Функции трассировки сессии» документа «Справочная информация».
Управление
Утилита генерации отчета trace_decode
Утилита размещается в директории $PGHOME/bin/ и имеет следующие ключи запуска:
-h, --help
Аргумент без значений. Вывод подсказки по работе утилиты.
: -a
Аргумент без значений. Формирование агрегированного отчета.
-f
Принимает text или html. Ключ может быть не указан, в таком случае будет использоваться формат HTML.
: -p <path_to_file>
Принимает путь к файлу трассировки. Для корректного формирования отчета, при наличии соответствующего файла трассировки параллельных процессов сессии он должен размещаться в той же директории, что и файл трассировки сессии.
Отчет выводится в консоль. Для его вывода в файл необходимо перенаправить вывод stdout в файл с требуемым именем.
Структура отчета
Основные блоки не агрегированного HTML-отчета:
- Заголовок отчета с информацией о процессе (в том числе о
postmaster-процессе), времени запуска и версии продукта СУБД. - Уровень трассировки.
- Значения всех GUC-переменных.
- Блоки выполнения запросов.
- Информация о незавершенном запросе (при его наличии).
- Информация о незавершенном ожидании поступления запроса (при его наличии).
- Суммарная информация о содержимом файла трассировки.
В агрегированном отчете каждый уникальный запрос указывается один раз. Блок запроса содержит обобщенную информацию о выполнении запроса и его потреблении ресурсов за все время трассировки. Сортировка запросов в агрегированном отчете выполняется в порядке убывания суммарной длительности выполнения запроса. При равной длительности - в порядке убывания количества выполнений запроса.
В неагрегированном отчете запросы указываются каждый раз, когда происходило их выполнение. Блок запроса содержит агрегированную информацию о выполнении запроса и о потреблении им ресурсов за одну команду. Сортировка запросов в не агрегированном отчете выполняется в порядке их выполнения.
Далее будет подробно рассмотрен состав каждого из блоков отчета.
Блок информации о запросе
Подблоки:
-
Заголовок запроса, включая
queryId, текст запроса, значения параметровsession_user,current_role,search_pathиcurrent_schema. Также содержит временные метки начала и окончания выполнения запроса. При наличии в файле трассировки незавершенных запросов поле времени окончания запроса будет содержать значениеNot finished. -
Ошибка выполнения запроса. Опциональный, присутствует только при наличии ошибки. Содержит текст сообщения об ошибке и ее код.
-
Общая статистика выполнения запроса. Содержит информацию по количеству успешных выполнений запроса, откатов и ошибок. Также содержит информацию по количеству фаз выполнения запроса:
- общее количество вызовов запроса извне;
- обработка;
- анализ;
- перезапись;
- планирование;
- кеширование плана;
- связывание переменных;
- выполнение.
-
Информация о шагах выполнения. Для каждого шага приводится статистика по длительности его выполнения, и, при уровне трассировки
RESOURCE- о потреблении ресурсов. В агрегированном отчете приводится информация о минимальных, максимальных и суммарных временах выполнения фазы запроса, и потребленных ресурсах (при уровне трассировкиRESOURCE). -
Информация о легковесных блокировках (
LWLock). Отображается при уровне трассировкиLOCKи наличии таких блокировок во время выполнения запроса. Содержит агрегированную информацию о легковесных блокировках в порядке убывания суммарной длительности их ожидания и их количества. При уровне трассировкиRESOURCEпомимо длительности, содержит информацию о минимальном, максимальном и суммарном потреблении ресурсов процессом при ожидании блокировки. -
Информация о блокировках (
Locks). Отображается при уровне трассировкиLOCKи наличии таких блокировок во время выполнения запроса. Содержит агрегированную информацию о блокировках в порядке убывания суммарной длительности их ожидания и количества. -
Информация о порожденных запросах – содержит список всех запросов, для которых выполнялась хотя бы одна фаза в ходе выполнения текущего запроса. Формат идентичен формату описываемого блока запроса. Такие запросы могут возникать в ходе работы расширений,
PL/pgSQLблоков, триггеров. -
Информация о выполнении запроса. Детально описывает этап выполнения плана запроса.
Блок информации о потреблении ресурсов
Раздел системных ресурсов включает в себя все показатели, которые выводятся только на уровне RESOURCE (кроме Duration):
-
Duration- длительность ожидания или операции (мс). -
Mem- память:ixrss- объем общей памяти;idrss- объем данных не в общей памяти;isrss- размер стека;minflt- ошибки программной страницы (soft page faults);majflt- ошибки страницы на диске (hard page faults).
-
IO- ввод/вывод:swap- не используется в Linux;inblock- количество операций ввода;outblock- количество операций вывода.
-
IPC- межпроцессные взаимодействия (не используются в Linux):msgsnd;msgrcv;nsignals.
-
CTX- переключения контекста:nvcsw- количество переключений контекста до истечения выделенного на процесс временного промежутка (например, при ожидании ресурса);nivcsw- количество переключений контекста по истечении процессного времени или количество переключений, осуществляемых процессом с более высоким приоритетом.
-
CPU- потребление CPU:user- в пользовательском режиме (мс);system- в режиме ядра (мс).
Раздел утилизации shared buffers:
shared buffer hits- число попаданий;shared disk blocks read- число прочитанных блоков;shared blocks dirtied- число измененных блоков;shared disk blocks written- число блоков, записанных изshared buffer;local buffer hits- число попаданий в локальный кеш блоков;local disk blocks read- число чтений локальных блоков;local blocks dirtied- число измененных локальных блоков;local disk blocks written- число записей локальных блоков;temp blocks read- число чтений временных блоков;temp blocks written- число записей временных блоков;time spent reading- время, потраченное на чтение блоков (мс);time spent writing- время, потраченное на запись блоков (мс).
Раздел утилизации WAL:
Records produced- количество созданных WAL-записей;Full page images produced- количествоfull page image-записей в WAL;Size of WAL records produced- общий объем памяти созданных WAL-записей.
Блок информации о легковесных блокировках
Включает в себя подблок информации о последней легковесной блокировке (служит для определения длительности ожидания блокировки для незавершенного запроса):
Begin of latest lwlock- время начала ожидания;End of latest lwlock- время окончания ожидания;LWLock tranche Id- идентификатор потока, в состав которого входит блокировка (транш);LWLock tranche name- имя транша блокировки;LWLock mode- имя режима блокировки,LW_SHAREDилиLW_EXCLUSIVE.
Подблок, включающий в себе список всех легковесных блокировок в порядке убывания суммарной длительности ожидания:
LWLock tranche Id- идентификатор транша блокировки;LWLock tranche name- имя транша блокировки;LWLock mode- имя режима блокировки -LW_SHAREDилиLW_EXCLUSIVE;LWLock count- количество ожиданий блокировки;LWLock minimum resources- минимальные ресурсы ожидания блокировки, не включают информацию поshared buffersи WAL;LWLock maximum resources- максимальные ресурсы ожидания блокировки, не включают информацию поshared buffersи WAL;LWLock summary resources- суммарные ресурсы ожидания блокировки, не включают информацию поshared buffersи WAL.
Блок информации о блокировках
Включает в себя подблок информации о последней легковесной блокировке (служит для определения длительности ожидания блокировки для незавершенного запроса):
Begin of latest lock- время начала ожидания;End of latest lock- время окончания ожидания;Lock type name- имя типа блокировки (соответствуют типам СУБД);Lock mode- имя режима блокировки (соответствуют типам СУБД);- Описание объекта блокировки, в зависимости от типа (соответствуют типам СУБД).
Подблок списка блокировок в порядке убывания суммарной длительности ожидания включает в себя информацию по каждой из блокировок:
Lock type name- имя типа блокировки (соответствуют типам СУБД);Lock mode- имя режима блокировки (соответствуют типам СУБД);Lock count- количество ожиданий блокировки;- Описание объекта блокировки, в зависимости от типа (соответствуют типам СУБД).
Блок выполнений запроса
Включает в себя подблоки:
Query and environment- текст запроса, а также значения параметровsearch_path,current_schema,current_role,session_user.Error- сообщение об ошибке и код ошибки при ее возникновении в ходе выполнения плана запроса.Plan- план запроса. Может быть как предварительный, без детальной информации по шагам выполнения и их ресурсам (в случае незавершенного выполнения плана, то есть при длительном выполнении), так и окончательный, с детальной информацией по шагам выполнения и их ресурсам, в том числе при завершении с ошибкой.Common stats- статистика по количеству успешных, отмененных и завершенных с ошибкой выполнений.Binds- порядок, типы, флаги и значения связанных переменных. Только на уровне трассировкиBINDи при наличии связанных переменных. При включенномmasking_mode=fullна сервере все значения замаскированы.Resources- информация об утилизации ресурсов выполнения плана.LWLocks- информация о легковесных блокировках выполнения плана.Locks- информация о блокировках выполнения плана.Parallels- информация о параллельных процессах плана, включаяPIDпроцесса, блокировки и утилизацию ресурсов.
Блок информации об ожидании запроса
Заголовок включает поля:
Times- количество ожиданий запросов;Laststarted - время последнего начала ожидания поступления запроса;Lastfinished - время последнего окончания ожидания поступления запроса (для незавершенных ожиданий будет отображатьсяNot finished).
Также в блок включена информация об утилизированных ресурсах. Для агрегированного запроса – минимальных, максимальных и суммарных.
Блок сводной статистики
Подблок статистики ожиданий запросов включает:
- количество ожиданий запросов;
- дату и время начала первого ожидания;
- дату и время окончания последнего ожидания;
- минимальные, максимальные и суммарные потребления времени, а при уровне трассировки
RESOURCE- и ресурсов на ожидание запросов (включая статистику по утилизации буферов и WAL).
Подблок статистики по запросам включает:
- количество вызовов выполнения запросов;
- количество подтвержденных транзакций;
- количество отмененных транзакций;
- количество ошибок;
- минимальные, максимальные и суммарные потребления времени, а при уровне трассировки
RESOURCE- и ресурсов на выполнение запросов (включая статистику по утилизации буферов и WAL).
Также блок содержит информацию о порожденных параллельных процессах.
Диагностика
| Тип сообщения | Сообщение | Расшифровка |
|---|---|---|
ERROR | Session tracing isn't enabled. | Отсутствие возможности включить трассировку сессии при отключении функциональности |
ERROR | permission denied for function start_session_tracing | Недоступна функция включения трассировки пользователю без прав суперпользователя и/или роли pg_tracing |
ERROR | permission denied for function start_session_tracing | Недоступна функция выключения трассировки пользователю без прав суперпользователя и/или роли pg_tracing |
Сценарии использования
Включение трассировки для сессии
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя postgres. Выполните запрос:
SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
Откройте вторую сессию от имени пользователя postgres. Выполните запрос:
SELECT start_session_tracing(<pid>, 1, '');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 1 for filename "<path to trace file>" -
Во второй сессии выполните запрос:
SELECT * FROM psql_session_tracing(<pid>);Ожидаемый результат:
backend_pid | level | filename
------------+-------+----------------------------------------------
<pid> | BASE | <path to trace file>
(1 row)
Выключение трассировки для сессии
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
В ранее открытой сессии от имени пользователя postgres с включенной трассировкой выполните запрос:
SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
Откройте вторую сессию от имени пользователя postgres. Выполните запрос:
SELECT stop_session_tracing(<pid>);Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to OFF -
Во второй сессии выполните запрос:
SELECT * FROM psql_session_tracing(<pid>);Ожидаемый результат:
backend_pid | level | filename
------------+-------+----------
<pid> | NONE |
(1 row)
Ограничения на включение и выключение трассировки для сессии
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя postgres. Выполните запрос:
SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
Откройте вторую сессию от имени пользователя
user1. Выполните запрос:SELECT start_session_tracing(<pid>, 1, '');Вывод возвращаемого сообщения:
Current user cannot start session tracing for process with PID <> -
Откройте третью сессию от имени пользователя
user2. Выполните запрос:SELECT start_session_tracing(<pid>, 1, '');Вывод возвращаемого сообщения:
INFO: Process <pid 1> is signaled tracing to ON with level 1 for filename "<path to trace file 1>" -
Закройте все сессии.
-
Откройте сессию от имени пользователя
user1. В ней выполните:SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
Откройте вторую сессию от имени пользователя
user1. Выполните запрос:SELECT start_session_tracing(<pid>, 15, 'qqqqq');Вывод возвращаемого сообщения:
INFO: Process <pid 2> is signaled tracing to ON with level 15 for filename "<path to trace file 2>"
Просмотр статуса трассировки сессии
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя postgres. Выполните запрос:
SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
Откройте сессию от имени пользователя
user1. Выполните запрос:SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
Откройте вторую сессию от имени пользователя postgres. Выполните команды:
SELECT start_session_tracing(<pid 1>, 1, '');
SELECT start_session_tracing(<pid 2>, 15, 'qqqqqqq');Вывод возвращаемых сообщений:
INFO: Process <pid 1> is signaled tracing to ON with level 1 for filename "<path to trace file 1>"
INFO: Process <pid 2> is signaled tracing to ON with level 15 for filename "<path to trace file 2>" -
Во второй сессии postgres выполните команды:
SELECT * FROM psql_session_tracing(<pid 1>);
SELECT * FROM psql_session_tracing(NULL);Ожидаемый результат:
-
Вывод первой команды:
backend_pid | level | filename
------------+-------+----------------------------------------------
<pid 1> | BASE | <path to trace file 1>
(1 row) -
Вывод второй команды:
backend_pid | level | filename
------------+-------------------------------+----------------------------------------------
<pid 1> | BASE | <path to trace file 1>
<pid 2> | BASE | BIND | LOCK | RESOURCE | <path to trace file 2>
<pid ВС> | NONE |
(3 rows)Где:
<path to trace file 2>- путь до файла, который начинается с директории/home/postgres;<pid ВС>- pid второй сессии postgres.
-
-
Откройте вторую сессию от имени пользователя
user1. Выполните запрос:SELECT * FROM psql_session_tracing(<pid 1>);Ожидаемый результат:
backend_pid | level | filename
-------------+-------+----------------------------------------------
(0 rows) -
Во второй сессии
user1выполните команды:SELECT * FROM psql_session_tracing(<pid 2>);
SELECT * FROM psql_session_tracing(NULL);Ожидаемый результат:
-
Вывод первой команды:
backend_pid | level | filename
------------+-------------------------------+----------------------------------------------
<pid 2> | BASE | BIND | LOCK | RESOURCE | <path to trace file 2>
(1 row)Значение
<path to trace file 2>- - путь до файла, который начинается с директории/home/postgres. -
Вывод второй команды:
backend_pid | level | filename
------------+-------------------------------+----------------------------------
<pid 2> | BASE | BIND | LOCK | RESOURCE | <path to trace file 2>
<pid ВС> | NONE |
(2 rows)Где:
<path to trace file 2>- путь до файла, который начинается с директории/home/postgres;<pid ВС>- pid второй сессии postgres.
-
Включение трассировки сессий для заданных ролей
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя postgres. Выполните команды:
ALTER SYSTEM SET session_tracing_default_level=15;
ALTER SYSTEM SET session_tracing_roles='user1';
SELECT pg_reload_conf();Ожидаемый результат:
ALTER SYSTEM
ALTER SYSTEM
pg_reload_conf
----------------
t
(1 row) -
Откройте сессию от имени пользователя
user1. Выполните запрос:SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
В сессии пользователя postgres выполните запрос:
SELECT * FROM psql_session_tracing(<pid>);Ожидаемый результат:
backend_pid | level | filename
------------+-------------------------------+----------------------------------------------
<pid> | BASE | BIND | LOCK | RESOURCE | <path to trace file>
(1 row)
Настройка путей сохранения файлов трассировки
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя postgres. Выполните команды:
ALTER SYSTEM SET session_tracing_default_path='/home/postgres';
ALTER SYSTEM SET session_tracing_roles='user1';
ALTER SYSTEM SET session_tracing_default_level=15;
SELECT pg_reload_conf();Ожидаемый результат:
ALTER SYSTEM
ALTER SYSTEM
ALTER SYSTEM
pg_reload_conf
----------------
t
(1 row) -
Откройте сессию от имени пользователя
user1. Выполните запрос:SELECT pg_backend_pid();Запомните полученный
pid, сессию оставьте открытой. -
Выполните запрос в сессии пользователя postgres:
SELECT * FROM psql_session_tracing(<pid>);Ожидаемый результат:
backend_pid | level | filename
------------+-------------------------------+----------------------------------------------
<pid> | BASE | BIND | LOCK | RESOURCE | <path to trace file>
(1 row)Значение
<path to trace file>начинается с директории/home/postgres.
Трассировки для диагностики длительно выполняющегося запроса
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя
user1. Выполните запрос:SELECT pg_backend_pid(); -
Выполните запрос в сессии пользователя
user1:SELECT pg_sleep(1000);Запомните полученный
pid, сессию оставьте открытой. -
Откройте сессию от имени пользователя postgres. Выполните запрос:
SELECT start_session_tracing(<pid>, 15, '');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 15 for filename "<path to trace file>" -
Выполните запрос в сессии от имени пользователя postgres:
SELECT psql_session_tracing(<pid>);Ожидаемый результат:
backend_pid | level | filename
------------+-------------------------------+----------------------------------------------
<pid> | BASE | BIND | LOCK | RESOURCE | <path to trace file>
(1 row) -
Убедитесь в появлении файла трассировки в пути, заданном параметром
session_tracing_default_path, с именем, содержащимpidпроцесса и метку времени включения трассировки:ls -al /home/postgres | grep <pid> -
Вызовите утилиту
trace_decodeи просмотрите содержимое файла трассировки:trace_decode -p /home/postgres/<file name>Ожидаемый результат:
-
Отчет содержит информацию о фазе выполнения запроса EXEC:
Begin of exec | <Date and time of the start of the plan execution step>
End of exec | Not finished -
Отчет содержит информацию о планировавшемся порядке выполнения не завершенного запроса:
Result (cost=0.00..0.01 rows=1 width=4)
-
Ограничение размера файлов трассировки
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя postgres. Выполните команды:
ALTER SYSTEM SET session_tracing_file_limit='128kB';
SELECT pg_reload_conf();Ожидаемый результат:
ALTER SYSTEM
pg_reload_conf
----------------
t
(1 row) -
Откройте сессию от имени пользователя
user1. Выполните запрос:SELECT pg_backend_pid(); -
В сессии от имени пользователя postgres выполните запрос:
SELECT start_session_tracing(<pid>, 15, '');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 15 for filename "<path to trace file>" -
В сессии от имени пользователя
user1выполните запрос:DO $$DECLARE c integer;
BEGIN
FOR c IN 1..200 LOOP
EXECUTE 'SELECT $1'
INTO c
USING c;
END LOOP;
END$$; -
Убедитесь в появлении файла трассировки в пути, заданном параметром
session_tracing_default_path, с именем, содержащимpidпроцесса и метку времени включения трассировки.ls -al /home/postgres | grep <pid>Убедитесь, что размер файла не превышает заданное ограничение.
-
В сессии от имени пользователя postgres выполните запрос:
SELECT * FROM psql_session_tracing(<pid>);Ожидаемый результат:
backend_pid | level | filename
-------------+-------+----------
<pid> | NONE |
(1 row) -
В логе СУБД находим сообщение об отключении трассировки:
Tracing thread: Session tracing file for process <pid> going to exceed size limit: 128/128. The session's tracing will be stopped. Time: <date and time of the start of the plan execution step>
Сохранение файлов трассировки при задании имени файла
При включенном значении параметра session_tracing_enable выполните следующие действия:
-
Откройте сессию от имени пользователя postgres, в ней выполните запрос:
SELECT start_session_tracing(pg_backend_pid(), 15, 'file1');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 15 for filename "<path to trace file>" -
Выполните команду:
ls -al <trace file directory> | grep file1Убедитесь в наличии файла.
-
В сессии от имени пользователя postgres выполните запрос:
SELECT stop_session_tracing(pg_backend_pid());Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to OFF -
В сессии от имени пользователя postgres выполните запрос:
SELECT start_session_tracing(pg_backend_pid(), 15, 'file1');Вывод возвращаемого сообщения:
ERROR: Session tracing file "<path to trace file>" already exists
Отчет базовой трассировки простых запросов
-
Включите базовую трассировку на сессию пользователя postgres:
SELECT start_session_tracing(pg_backend_pid(), 1, 'postgres_1');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 1 for filename "<path to trace file>" -
В сессии пользователя postgres выполните команды:
CREATE SCHEMA schema1;
SELECT 1;
BEGIN;
SELECT 1;
SELECT 2;
COMMIT;
BEGIN;
SELECT 1;
SELECT 2;
ROLLBACK;
CREATE TABLE schema1.table1 (id int, f1 int, f2 int);
INSERT INTO schema1.table1 SELECT generate_series(1,10000) AS id;
SELECT * FROM pg_cass;
DO $$DECLARE r record; BEGIN FOR r IN SELECT table_schema, table_name FROM information_schema.tables WHERE table_type = 'VIEW' AND table_schema = 'public' LOOP EXECUTE 'GRANT ALL ON ' || quote_ident(r.table_schema) || '.' || quote_ident(r.table_name) || ' TO $test_user'; END LOOP; END$$;
EXPLAIN ANALYZE /*+ Parallel(t1 2 hard) */ SELECT * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002, 1003,1004,1005,1006,1007,1008,1009,1010)) t1;
SELECT /*+ Parallel(t1 2 soft) */ * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002,1003,1004,1005, 1006,1007,1008,1009,1010)) t1;
DROP TABLE schema1.table1;
CREATE TABLE schema1.t1 (f1 int);
CREATE UNIQUE INDEX t1_idx ON schema1.t1 (f1);
insert into schema1.t1 (f1) values (1);
insert into schema1.t1 (f1) values (1);
insert into schema1.t1 (f1) values (2);
insert into schema1.t1 (f1) values (3);
insert into schema1.t1 (f1) values (4);
insert into schema1.t1 (f1) values (5);
SELECT * FROM schema1.t1 WHERE t1.f1 = 5;
set enable_indexscan = false;
SELECT * FROM schema1.t1 WHERE t1.f1 = 5;
set enable_indexscan = true;
PREPARE s1 (char) AS SELECT count(1) FROM pg_class WHERE relkind = $1;
EXECUTE s1 ('r');
EXECUTE s1 ('i');
CREATE user u1 WITH PASSWORD '<password>';
DROP user u1;
DEALLOCATE s1;
DROP TABLE schema1.t1;
DROP SCHEMA schema1; -
Сформируйте отчет по созданному файлу трассировки:
trace_decode -p <path to trace file> > postgres_1.htmlФайл отчета содержит информацию:
- по процессу
postmasterи трассируемому процессу бэкенда - в разделеProcess info; - по GUC переменным конфигурации - в разделе
GUC variables; - по уровню трассировки - в разделе
Session tracing level; - по всем запросам, выполненным в пункте, включая информацию об успешности, ошибочности или откате транзакции - в разделах
STATEMENT; - по всем запросам и фазам выполнения запросов о длительности выполнения - в подразделах
... RESOURCES, в полеDuration; - по всем ошибочным запросам содержится текст ошибки и код ошибки - в разделах
STATEMENTи в подразделахEXECUTION, в подпунктахError; - по всем запросам, имевшим план выполнения содержится фактически выполненный план выполнения запросов с указанием потребленных ресурсов - в подразделах
EXECUTION, подпунктеPlan; - по последнему ожиданию поступления запроса — время начала ожидания - в разделе
NETWORK; - по запросам, в ходе выполнения которых порождались и выполнялись параллельные рабочие процессы — информация по каждому такому запросу, включая длительность его выполнения и PID - в подразделах
EXECUTION, подпунктеParallel workers; - суммарную информацию по количеству обработанных запросов, минимальной, максимальной и суммарной длительности, количестве успешных, ошибочных и откаченных запросов - в разделах
STATEMENT, пунктCommon stats; - суммарную информацию по количеству ожиданий поступления запросов, их минимальной, максимальной и суммарной длительности - в разделе
SUMMARY; - пароли в запросах задания или изменения паролей замаскированы - в разделах
STATEMENTи в подразделахEXECUTION, в полеquery; - информация о запросах упорядочена в порядке их выполнения.
Отчет не содержит информацию:
- о блокировках и легковесных блокировках;
- по всем запросам и фазам выполнения запросов о потреблении ресурсов на их выполнении;
- по подготовленным запросам не содержится информация о
bind-переменных.
- по процессу
Отчет базовой трассировки с bind переменными
-
Включите базовую трассировку на сессию пользователя postgres.
SELECT start_session_tracing(pg_backend_pid(), 3, 'postgres_2');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 3 for filename "<path to trace file>" -
Выполните команды в сессии пользователя postgres:
PREPARE s1 (char) AS SELECT count(1) FROM pg_class where relkind = $1;
EXECUTE s1 ('r');
EXECUTE s1 ('i');
deallocate s1; -
Сформируйте отчет по созданному файлу трассировки:
trace_decode -p <path to trace file> > postgres_2.htmlОтчет соответствует отчету базовой трассировки простых запросов и дополнительно содержит значения
bind-переменных подготовленных запросов - в подразделахEXECUTION, подпунктеBind params.
Отчет базовой трассировки с блокировками
-
Включите базовую трассировку на сессию пользователя postgres:
SELECT start_session_tracing(pg_backend_pid(), 5, 'postgres_3');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 5 for filename "<path to trace file>" -
Выполните команды в сессии пользователя postgres:
CREATE SCHEMA schema1;
SELECT 1;
BEGIN;
SELECT 1;
SELECT 2;
COMMIT;
BEGIN;
SELECT 1;
SELECT 2;
ROLLBACK;
CREATE TABLE schema1.table1 (id int, f1 int, f2 int);
INSERT INTO schema1.table1 SELECT generate_series(1,10000) AS id;
SELECT * FROM pg_cass;
DO $$DECLARE r record; BEGIN FOR r IN SELECT table_schema, table_name FROM information_schema.tables WHERE table_type = 'VIEW' AND table_schema = 'public' LOOP EXECUTE 'GRANT ALL ON ' || quote_ident(r.table_schema) || '.' || quote_ident(r.table_name) || ' TO $test_user'; END LOOP; END$$;
EXPLAIN ANALYZE /*+ Parallel(t1 2 hard) */ SELECT * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002, 1003,1004,1005,1006,1007,1008,1009,1010)) t1;
SELECT /*+ Parallel(t1 2 soft) */ * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002,1003,1004,1005, 1006,1007,1008,1009,1010)) t1;
DROP TABLE schema1.table1;
CREATE TABLE schema1.t1 (f1 int);
CREATE UNIQUE INDEX t1_idx ON schema1.t1 (f1);
INSERT INTO schema1.t1 (f1) VALUES (1);
INSERT INTO schema1.t1 (f1) VALUES (1);
INSERT INTO schema1.t1 (f1) VALUES (2);
INSERT INTO schema1.t1 (f1) VALUES (3);
INSERT INTO schema1.t1 (f1) VALUES (4);
INSERT INTO schema1.t1 (f1) VALUES (5);
SELECT * FROM schema1.t1 WHERE t1.f1 = 5;
SET enable_indexscan = false;
SELECT * FROM schema1.t1 WHERE t1.f1 = 5;
SET enable_indexscan = true;
PREPARE s1 (char) AS SELECT count(1) FROM pg_class WHERE relkind = $1;
EXECUTE s1 ('r');
EXECUTE s1 ('i');
CREATE user u1 WITH PASSWORD '<password>';
DROP user u1;
DEALLOCATE s1;
DROP TABLE schema1.t1;
DROP SCHEMA schema1; -
Сформируйте отчет по созданному файлу трассировки:
trace_decode -p <path to trace file> > postgres_3.htmlОтчет соответствует отчету базовой трассировки простых запросов и дополнительно содержит:
- информацию о количестве, минимальной, максимальной и суммарной длительности ожидания каждой блокировки на каждом из шагов выполнения запроса. Для каждой блокировки указано последнее время начала и окончания ожидания, тип блокировки, объект блокировки в терминах идентификаторов - в разделах
STATEMENTи в подразделахEXECUTION, пунктыLWLocksиLocks; - информацию о количестве, минимальной, максимальной и суммарной длительности ожидания каждой легковесной блокировки на каждом из шагов выполнения запроса. Для каждой легковесной блокировки указано последнее время начала и окончания ожидания, тип и режим блокировки - в разделах
STATEMENTи в подразделахEXECUTION, пунктыLWLocksиLocks.
- информацию о количестве, минимальной, максимальной и суммарной длительности ожидания каждой блокировки на каждом из шагов выполнения запроса. Для каждой блокировки указано последнее время начала и окончания ожидания, тип блокировки, объект блокировки в терминах идентификаторов - в разделах
Отчет базовой трассировки с потребляемыми ресурсами
-
Включите базовую трассировку на сессию пользователя postgres:
SELECT start_session_tracing(pg_backend_pid(), 9, 'postgres_4');Вывод возвращаемого сообщения:
INFO: Process <pid> is signaled tracing to ON with level 9 for filename "<path to trace file>" -
Выполните команды в сессии пользователя postgres:
CREATE SCHEMA schema1;
SELECT 1;
BEGIN;
SELECT 1;
SELECT 2;
COMMIT;
BEGIN;
SELECT 1;
SELECT 2;
ROLLBACK;
CREATE TABLE schema1.table1 (id int, f1 int, f2 int);
INSERT INTO schema1.table1 SELECT generate_series(1,10000) AS id;
SELECT * FROM pg_cass;
DO $$DECLARE r record; BEGIN FOR r IN SELECT table_schema, table_name FROM information_schema.tables WHERE table_type = 'VIEW' AND table_schema = 'public' LOOP EXECUTE 'GRANT ALL ON ' || quote_ident(r.table_schema) || '.' || quote_ident(r.table_name) || ' TO $test_user'; END LOOP; END$$;
EXPLAIN ANALYZE /*+ Parallel(t1 2 hard) */ SELECT * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002, 1003,1004,1005,1006,1007,1008,1009,1010)) t1;
SELECT /*+ Parallel(t1 2 soft) */ * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002,1003,1004,1005, 1006,1007,1008,1009,1010)) t1;
DROP TABLE schema1.table1;
CREATE TABLE schema1.t1 (f1 int);
CREATE UNIQUE INDEX t1_idx ON schema1.t1 (f1);
INSERT INTO schema1.t1 (f1) VALUES (1);
INSERT INTO schema1.t1 (f1) VALUES (1);
INSERT INTO schema1.t1 (f1) VALUES (2);
INSERT INTO schema1.t1 (f1) VALUES (3);
INSERT INTO schema1.t1 (f1) VALUES (4);
INSERT INTO schema1.t1 (f1) VALUES (5);
SELECT * FROM schema1.t1 WHERE t1.f1 = 5;
SET enable_indexscan = false;
SELECT * FROM schema1.t1 WHERE t1.f1 = 5;
SET enable_indexscan = true;
PREPARE s1 (char) AS SELECT count(1) FROM pg_class where relkind = $1;
EXECUTE s1 ('r');
EXECUTE s1 ('i');
CREATE user u1 with password '<password>';
DROP user u1;
DEALLOCATE s1;
DROP TABLE schema1.t1;
DROP SCHEMA schema1; -
Сформируйте отчет по созданному файлу трассировки:
trace_decode -p <path to trace file> > postgres_4.htmlОтчет соответствует отчету базовой трассировки простых запросов и дополнительно содержит:
- информацию о потребленных ресурсах на каждом шаге выполнения запроса, и запросом в целом, включая минимальное, максимальное и суммарное потребление ресурсов, таких как CPU, память, ввод/вывод, обращения к
shared bufferи порождение записей WAL - в подразделах... RESOURCES, кромеLWlocksиLocks, не содержащих информацию поshared buffersи WAL; - информацию о потребленных ресурсах на последнем ожидании поступления запроса, включая минимальное, максимальное и суммарное потребление ресурсов, таких как CPU, память, ввод/вывод, обращения к
shared bufferи порождение записей WAL - в разделеNETWORK, в подразделах... RESOURCES; - суммарную информацию по обработанным запросам, включая минимальное, максимальное и суммарное потребление ресурсов, таких как CPU, память, ввод/вывод, обращения к
shared bufferи порождение записей WAL - в разделеSUMMARY, в подразделах... RESOURCES; - суммарную информацию по ожиданиям поступления запросов, включая минимальное, максимальное и суммарное потребление ресурсов, таких как CPU, память, ввод/вывод, обращения к
shared bufferи порождение записей WAL - в разделеSUMMARY, в подразделеNETWORKв подпунктах... RESOURCES.
- информацию о потребленных ресурсах на каждом шаге выполнения запроса, и запросом в целом, включая минимальное, максимальное и суммарное потребление ресурсов, таких как CPU, память, ввод/вывод, обращения к
Агрегированный отчет с полной информацией
-
Включите базовую трассировку на сессию пользователя postgres:
SELECT start_session_tracing(pg_backend_pid(), 15, 'postgres_5');Вывод возвращаемой информации:
INFO: Process <pid> is signaled tracing to ON with level 15 for filename "<path to trace file>" -
Выполните команды в сессии пользователя postgres:
CREATE SCHEMA schema1;
SELECT 1;
BEGIN;
SELECT 1;
SELECT 2;
COMMIT;
BEGIN;
SELECT 1;
SELECT 2;
ROLLBACK;
CREATE TABLE schema1.table1 (id int, f1 int, f2 int);
INSERT INTO schema1.table1 SELECT generate_series(1,10000) AS id;
SELECT * FROM pg_cass;
DO $$DECLARE r record; BEGIN FOR r IN SELECT table_schema, table_name FROM information_schema.tables WHERE table_type = 'VIEW' AND table_schema = 'public' LOOP EXECUTE 'GRANT ALL ON ' || quote_ident(r.table_schema) || '.' || quote_ident(r.table_name) || ' TO $test_user'; END LOOP; END$$;
EXPLAIN ANALYZE /*+ Parallel(t1 2 hard) */ SELECT * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002, 1003,1004,1005,1006,1007,1008,1009,1010)) t1;
SELECT /*+ Parallel(t1 2 soft) */ * FROM (SELECT * FROM schema1.table1 t2 WHERE id IN (1,2,3,4,5,6,7,8,9,19) UNION ALL SELECT * FROM schema1.table1 t3 WHERE id IN (1001,1002,1003,1004,1005, 1006,1007,1008,1009,1010)) t1;
DROP table schema1.table1;
CREATE TABLE schema1.t1 (f1 int);
CREATE UNIQUE INDEX t1_idx ON schema1.t1 (f1);
INSERT INTO schema1.t1 (f1) VALUES (1);
INSERT INTO schema1.t1 (f1) VALUES (1);
INSERT INTO schema1.t1 (f1) VALUES (2);
INSERT INTO schema1.t1 (f1) VALUES (3);
INSERT INTO schema1.t1 (f1) VALUES (4);
INSERT INTO schema1.t1 (f1) VALUES (5);
SELECT * FROM schema1.t1 WHERE t1.f1 = 5;
SET enable_indexscan = false;
SELECT * FROM schema1.t1 where t1.f1 = 5;
SET enable_indexscan = true;
PREPARE s1 (char) AS SELECT count(1) FROM pg_class WHERE relkind = $1;
EXECUTE s1 ('r');
EXECUTE s1 ('i');
CREATE user u1 WITH PASSWORD '<password>';
DROP user u1;
DEALLOCATE s1;
DROP TABLE schema1.t1;
DROP SCHEMA schema1; -
Сформируйте отчет по созданному файлу трассировки:
trace_decode -a -p <path to trace file> > postgres_5.htmlАгрегированный отчет содержит следующую информацию:
- по процессу
postmasterи трассируемому процессу бэкенда - в разделеProcess info; - по GUC переменным конфигурации - в разделе
GUC variables; - по уровню трассировки - в разделе
Session tracing level; - агрегированное представление в разрезе уникальности запроса по всем запросам выполненным в пункте, включая статистическую информацию об успешности, ошибочности или откате транзакции, информацию по минимальной, максимальной, суммарной длительности и потреблению ресурсов, а также по каждой из блокировок и легковесных блокировок и суммарное количество их ожиданий. Также указывается время первого начала выполнения запроса и каждой из фаз запроса, и время последнего окончания запроса и фаз запросов - в разделах
STATEMENT; - по всем ошибочным запросам содержится текст последней ошибки и код последней ошибки - в разделах
STATEMENTи в подразделахEXECUTION, в подпунктахError; - по всем запросам, имевшим план выполнения содержится фактически выполненный последний план выполнения запросов с указанием потребленных ресурсов. Если в течении сбора трассировки запрос выполнялся с несколькими разными планами — отображаются все планы - в разных подразделах
EXECUTION; - по всем запросам, имевшим
bind-переменные содержатся последние значенияbind-переменных в привязке к плану запроса. Если в течении сбора трассировки запрос выполнялся с несколькими разными планами (для каждого плана будут отображены связанные с ним последниеbindпеременные) - в подразделахEXECUTION, подпунктеBind params; - по запросам, в ходе выполнения которых порождались и выполнялись параллельные рабочие процессы (информация по каждому такому запросу, включая минимальную, максимальную и суммарную длительность и потребление ресурсов его выполнения и PID) - в подразделах
EXECUTION, подпунктеParallel workers; - суммарную информацию по количеству обработанных запросов, минимальной, максимальной и суммарной длительности, количестве успешных, ошибочных и откаченных запросов - в разделах
STATEMENT, пунктCommon stats; - суммарную информацию по количеству ожиданий поступления запросов, их минимальной, максимальной и суммарной длительности - в разделе
SUMMARY; - пароли в запросах задания или изменения паролей замаскированы - в разделах
STATEMENTи в подразделахEXECUTION, в полеquery; - информация о запросах упорядочена в порядке убывания суммарной длительности выполнения запроса таким образом, что наиболее длительные по суммарной длительности запросы располагаются в начале.
- по процессу