Когда подключение к СУБД уже создано, с помощью расширения можно включить трассирование всех запросов, которые будут выполняться в рамках этого сеанса. Включить трассирование можно как для своего сеанса, используя функцию start_session_trace(), так и для трассирования других сеансов, например сеансов, созданных приложением.
По собранной информации можно определить следующее:
- Текст запроса
- Время затраченное на разбор запроса
- План запроса
- Тип плана запроса(generic, custom)
- Время, затраченное на планирование запроса
- Время, затраченное на выполнение всего запроса
- Время, затраченное на выполнение каждого узла плана
- Время, затраченное на ожидание событий(wait events). Например: чтение файлов, ожидание блокировки
- Блокировки в разделяемой памяти, захваченные во время выполнения запроса
Эта информация будет собрана для каждого запроса, выполнявшегося в момент трассирования.
При трассировании сеансов время выполнения запросов может увеличиться. В наших измерениях скорость выполнения падает на ~5%. Поэтому не стоит оставлять трассирование сеансов на длительное время. Этот инструмент предназначен, в первую очередь, для исследования проблемы, а не её обнаружения.
Чтобы начать трассирование текущего сеанса, необходимо воспользоваться следующей sql функцией:
start_session_trace();
Чтобы завершить трассирование текущего сеанса и сформировать отчёт, необходимо воспользоваться следующей sql функцией:
stop_session_trace();
Чтобы начать трассирование сеанса, который запущен в другом процессе, необходимо воспользоваться следующей sql функцией:
start_session_trace(IN pid INT);
| Аргумент | Описание |
|---|---|
| pid | Идентификатор процесса, в котором необходимо включить трассирование сеанса |
Примечание: Трассирование начнётся после завершения первого SQL-оператора. При этом сам первый SQL-оператор не будет записан в результирующий файл.
Чтобы завершить трассирование сеанса, который запущен в другом процессе, необходимо воспользоваться следующей sql функцией:
stop_session_trace(IN pid INT);
| Аргумент | Описание |
|---|---|
| pid | Идентификатор процесса, в котором необходимо завершить трассирование сеанса |
Результат трассирования будет находиться в каталоге, указанном в настройке pg_uprobe.data_dir(по умолчанию $PGDATA/pg_uprobe).- Название файла имеет следующий вид: [Настройка pg_uprobe.trace_file_name]_[PID_процесса].
Формат вывода информации для трассирования сеанса определяется настройкой pg_uprobe.trace_write_mode. Поддерживаемые значения:
- json: Предпочтительный вариант, который сейчас поддерживается в первую очередь
- text: Вариант, который подходит для анализа небольших сценариев, в котором информация представлена в удобном для чтения виде
Пример результата трассирования простого запроса: example_trace_session.json
Json schema: trace_json_schema.json
а верхнем уровне вывода представлен массив JSON-объектов, где каждый объект представляет собой разбор одного выполненного запроса, массив отсортирован в порядке выполнения этих запросов.
Пример:
[
{
// Данные первого запроса
},
{
// Данные второго запроса
}
]Рассмотрим подробнее данные, полученные при трассировании одного запроса.
{
"parsingTime": "70093 nanosec", // Время затраченное на разбор SQL запроса
"planningTime": "8521955 nanosec", // Время затраченное на планирование SQL запроса
"explain": object, // Вывод команды explain для запроса в json формате
"planType": "custom", // Опциональное поле. Тип плана выбран для подготовленного запроса: generic или custom
"LWLockPlanning": object, // Опциональное поле. Статистика блокировок страниц буферного кэша во время выполнения планирования запроса
"executionEvents": array[object], // Узлы выполнения запроса, в хронологическом порядке выполнения
"executionTime": "282504 nanosec", // Время затраченное на выполнение запроса
"executorNodeStatInPlan": object, // Вывод команды explain для запроса в json формате с статистикой выполнения каждого узла
"exprNodeStat": array[object], // Статистика для вычисляемых выражений
"params": object, // Опциональное поле. Параметры для подготовленного запроса
"locksInsidePortalRun": object, // Опциональное поле. Статистика блокировок страниц буферного кэша во время выполнения запроса. Содержит объекты типа LWLockStat
"locksOutsidePortalRun": object, // Опциональное поле. Статистика блокировок страниц буферного кэша до выполнения запроса или после. Содержит объекты типа LWLockStat
"waitEventStat": object // Опциональное поле. Статистика по событиям ожидания за время выполнения запроса
}Рассмотрим детально поле explain:
{
"Query Text": "select * from t where id = 1;", // Сам запрос
"Plan": object, // Узлы плана
/* Другие поля из explain с типом JSON*/
}После выполнения планирования мы переходим к выполнению, во время которого поочерёдно выполняются узлы плана, для них пишется следующая статистика:
"executionEvents": [
{
"node": "ScanState", // Название узла
"explain": object , // Часть текста команды explain для конкретно этого узла плана
"executeTime": "32256 nanosec", // Время выполнения узла
"LWLockStat": object, // Объект типа LWLockStat
}
]Для дальнейшего анализа рассмотрим объекты LWLockStat. В нём собирается статистика блокировок LWLock на буферный кэш или просто на отдельные блокировки, которые мы ожидали. Чтобы включить отображение всех блокировок, которые брались в это время необходимо воспользоваться настройкой pg_uprobe.write_only_sleep_lwlocks_stat.
Данная статистика собирается для каждой страницы буферного кэша, к которой обращались во время выполнения той или иной операции.
{
"bufferTag": {// к какому объекту базы данных относится страница с диска
"spcOid": 1663, // oid табличного пространства
"spcName": "pg_default", // Имя табличного пространства
"dbOid": 5, // oid базы данных
"dbName": "postgres", // Имя базы данных
"relNumber": 2662, // oid отношения
"relName": "pg_catalog.pg_class_oid_index", // Полное имя отношения
"relKind": "i", // Тип отношения сокращённо (в данном случае это индекс)
"forkName": "main", // Тип файла (в данном случае файл с данными)
"blockNumber": 3 // Порядковый номер блока в файле
},
"exclusive": { // Статистика для взятия эксклюзивной блокировки
"totalCalls": 0, // Количество взятий блокировки
"sleepCount": 0, // Количество засыпаний при ожидании блокировки
"sleepTimeSum": "0 nanosec", // Общее время ожидания
"maxSleepTime": "0 nanosec" // Максимальное время одного ожидания
},
"shared": { // Статистика для разделяемой эксклюзивной блокировки
"totalCalls": 5, // Количество взятий блокировки
"sleepCount": 0, // Количество засыпаний при ожидании блокировки
"sleepTimeSum": "0 nanosec", // Общее время ожидания
"maxSleepTime": "0 nanosec" // Максимальное время одного ожидания
}
}После того как запрос выполнился формируется объект executorNodeStatInPlan:
"executorNodeStatInPlan": {
/* Другие поля из explain с типом JSON*/
"traceData": {
"maxTime": 32256, // Максимальное время выполнения узла плана
"totalCalls": 3, // Количество выполнений узла плана
"totalTimeSum": 32980 // Суммарное время выполнений узла плана
}
}Статистика для вычисляемых выражений выводиться в объекте exprNodeStat:
"exprNodeStat": [
{
"node": "Const", // Название узла выражения
"totalCalls": 1, // Сколько раз вычислялось
"totalTimeSum": "239 nanosec", // Суммарное время вычисления
"maxTime": "239 nanosec" // Максимальное время вычисления
}
]Статистика по событиям ожидания за время выполнения запроса
"waitEventStat": [
{
"name": "DataFileRead", // Название события ожидания
"count": 5, // Количество произошедших событий
"timeSum": "860555 nanosec", // Общее время ожидания
"maxTime": "275268 nanosec" // Максимальное время одного ожидания
}
]