14. PSQL-профайлер

14.1. Общие сведения

Профайлер позволяет пользователям измерять затраты на производительность кода SQL и PSQL. Это реализовано с помощью системного пакета, передающего данные в плагин профайлера. В этом тексте части сервера и плагина рассматриваются как единое целое, так же, как будет использоваться профайлер по умолчанию (Default_Profiler).

Пакет RDB$PROFILER позволяет профилировать выполнение кода PSQL, собирая статистику, о том сколько раз была выполнена каждая строка, а также ее минимальное, максимальное и общее время выполнения (с точностью до наносекунд). Также он дает доступ к статистике явных и неявных SQL-курсоров.

Чтобы собрать данные, необходимо запустить сеанс профайлера с помощью RDB$PROFILER.START_SESSION. Эта функция возвращает идентификатор сеанса профайлера, который позже сохраняется в таблицах снапшотов профайлера для запроса и анализа. Сеанс профайлера может быть локальным (то же подключение) или удаленным (другое подключение).

Удаленное профилирование пересылает команды удаленному подключению. Возможно одновременно профилировать несколько подключений. Также возможно, что локально или удаленно запущенный сеанс профайлера содержит команды, переданные другим подключением.

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

Если удаленное подключение происходит от другого пользователя, то вызывающий пользователь должен иметь системные привилегии PROFILE_ANY_ATTACHMENT.

После запуска сеанса статистика PSQL и SQL операторов начинает собираться в памяти. Обратите внимание, что сеанс профайлера собирает данные только об операторах, выполняемых в подключении, связанном с сеансом.

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

Сеанс может быть приостановлен, чтобы временно отключить сбор статистики. Он может быть возобновлен позже, чтобы вернуть сбор статистики в том же сеансе.

Новый сеанс может быть запущен, когда сеанс уже активен. В этом случае он имеет ту же семантику завершения текущего сеанса с помощью RDB$PROFILER.FINISH_SESSION(FALSE), поэтому таблицы снапшотов не обновляются в то же время.

Чтобы проанализировать собранные данные, необходимо сбросить данные в таблицы снапшотов, что может быть сделано при завершении или приостановке сеанса (с параметром FLUSH, установленным в TRUE) или вызовом RDB$PROFILER.FLUSH. Данные удаляются с помощью автономной транзакции (транзакция, запущенная и завершенная для конкретной цели обновления данных профайлера).

Накладные расходы, возникающие во время работы профайлера

Во время работы профайлера возникают накладные расходы, которые замедляют работу сервера. Эти расходы зависят от операционной системы, версии ядра и модели процессора, их трудно предсказать. Но иногда они могут быть очень высокими, например, более 100%.

Если такие накладные расходы возникают в Linux, то с помощью следующей команды вы можете увидеть, какой источник сигнала тактовой частоты используется для синхронизации:

cat /sys/devices/system/clocksource/clocksource0/current_clocksource

Если результат отличается от tsc, это может быть причиной проблемы.

Еще одна возможная причина замедления в Linux - эта ошибка.

Пример сеанса профайлера

Ниже приведен пример сеанса профайлера и запросов для анализа данных:

/* Preparation - create table and routines that will be analyzed */

create table tab (
   id integer not null,
   val integer not null
);

set term !;

create or alter function mult(p1 integer, p2 integer) returns integer
as
begin
   return p1 * p2;
end!

create or alter procedure ins
as
   declare n integer = 1;
begin
   while (n <= 1000)
   do begin
      if (mod(n, 2) = 1) then
         insert into tab values (:n, mult(:n, 2))
      n = n + 1;
   end
end!

set term ;!

/* Start profiling */

select rdb$profiler.start_session(\rr{Profile Session 1}) from rdb$database;

set term !;

execute block
as
begin
   execute procedure ins;
   delete from tab;
end!

set term ;!

execute procedure rdb$profiler.finish_session(true);
execute procedure ins;

select rdb$profiler.start_session(\rr{Profile Session 2}) from rdb$database;

select mod(id, 5), sum(val)
from tab
where id <= 50
group by mod(id, 5)
order by sum(val);

execute procedure rdb$profiler.finish_session(true);

/* Data analysis */

set transaction read committed;

select * from plg$prof_sessions;

select * from plg$prof_psql_stats_view;

select * from plg$prof_record_source_stats_view;

select preq.*
from plg$prof_requests preq
join plg$prof_sessions pses
   on pses.profile_id = preq.profile_id and
      pses.description = 'Profile Session 1';

select pstat.*
from plg$prof_psql_stats pstat
join plg$prof_sessions pses
   on pses.profile_id = pstat.profile_id and
      pses.description = 'Profile Session 1'
order by pstat.profile_id,
         pstat.request_id,
         pstat.line_num,
         pstat.column_num;

select pstat.*
from plg$prof_record_source_stats pstat
join plg$prof_sessions pses
   on pses.profile_id = pstat.profile_id and
      pses.description = 'Profile Session 2'
order by pstat.profile_id,
         pstat.request_id,
         pstat.cursor_id,
         pstat.record_source_id;

14.2. Функция START_SESSION

RDB$PROFILER.START_SESSION запускает новый сеанс профайлера, превращает его в текущий сеанс (с заданным ATTACHMENT_ID) и возвращает его идентификатор.

Если значение FLUSH_INTERVAL не NULL, то автосброс настраивается таким же образом, как и при вызове RDB$PROFILER.SET_FLUSH_INTERVAL.

Если значение PLUGIN_NAME равно NULL (по умолчанию), то будет использован плагин профайлера конфигурации базы данных по умолчанию.

PLUGIN_OPTIONS - это параметры, настраиваемые для плагина, в данном случае для Default_Profiler должно быть значение NULL.

Входные параметры:

DESCRIPTION - тип VARCHAR(255) CHARACTER SET UTF8 по умолчанию NULL;
FLUSH_INTERVAL - тип INTEGER по умолчанию NULL;
ATTACHMENT_ID - тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION;
PLUGIN_NAME - тип VARCHAR(255) CHARACTER SET UTF8 по умолчанию NULL;
PLUGIN_OPTIONS - тип VARCHAR(255) CHARACTER SET UTF8 по умолчанию NULL.

Возвращает тип BIGINT NOT NULL.

14.3. Процедура PAUSE_SESSION

RDB$PROFILER.PAUSE_SESSION приостанавливает текущий сеанс профайлера (с заданным ATTACHMENT_ID), поэтому статистика следующих выполненных инструкций не собирается.

Если значение FLUSH равно TRUE, таблицы снапшотов обновляются данными до текущего момента. В противном случае данные остаются только в памяти для последующего обновления.

Вызов RDB$PROFILER.PAUSE_SESSION(TRUE) имеет ту же семантику, что и вызов RDB$PROFILER.PAUSE_SESSION(FALSE), за которым следует RDB$PROFILER.FLUSH (используя тот же ATTACHMENT_ID).

Входные параметры:

FLUSH тип BOOLEAN NOT NULL по умолчанию FALSE;
ATTACHMENT_ID тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION.

14.4. Процедура RESUME_SESSION

RDB$PROFILER.RESUME_SESSION возобновляет текущий сеанс профайлера (с заданным ATTACHMENT_ID), если он был приостановлен, запуская снова сбор статистики.

Входные параметры:

ATTACHMENT_ID тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION.

14.5. Процедура FINISH_SESSION

RDB$PROFILER.FINISH_SESSION завершает текущий сеанс профайлера (с заданным ATTACHMENT_ID).

Если значение FLUSH равно TRUE, таблицы снапшотов обновляются данными завершенного сеанса (и старых завершенных сеансов, которые еще не присутствуют в снапшоте). В противном случае данные остаются только в памяти для последующего обновления.

Вызов RDB$PROFILER.FINISH_SESSION(TRUE) имеет ту же семантику, что и вызов RDB$PROFILER.FINISH_SESSION(FALSE), за которым следует RDB$PROFILER.FLUSH (используя тот же ATTACHMENT_ID).

Входные параметры:

FLUSH тип BOOLEAN NOT NULL по умолчанию TRUE;
ATTACHMENT_ID тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION.

14.6. Процедура CANCEL_SESSION

RDB$PROFILER.CANCEL_SESSION отменяет текущий сеанс профайлера (с заданным ATTACHMENT_ID).

Все данные сеанса, присутствующие в плагине профайлера, удаляются и не будут сброшены.

Данные, которые уже были сброшены, не удаляются автоматически.

Входные параметры:

ATTACHMENT_ID тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION.

14.7. Процедура DISCARD

RDB$PROFILER.DISCARD удаляет все сеансы (с заданным ATTACHMENT_ID) из памяти, не cбрасывая их данные.

Если есть активный сеанс, он завершается.

Входные параметры:

ATTACHMENT_ID тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION.

14.8. Процедура FLUSH

RDB$PROFILER.FLUSH обновляет таблицы снапшотов данными из сеансов профайлера (с заданным ATTACHMENT_ID) в памяти.

После обновления данные сохраняются в таблицах PLG$PROF_SESSIONS, PLG$PROF_STATEMENTS, PLG$PROF_RECORD_SOURCES, PLG$PROF_REQUESTS, PLG$PROF_PSQL_STATS и PLG$PROF_RECORD_SOURCE_STATS и могут быть прочитаны и проанализированы.

Данные обновляются с помощью автономной транзакции, поэтому, еесли процедура вызывается в снапшот-транзакции, данные не будут считываться в той же транзакции.

Как только происходит обновление, завершенные сеансы удаляются из памяти.

Входные параметры:

ATTACHMENT_ID тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION.

14.9. Процедура SET_FLUSH_INTERVAL

RDB$PROFILER.SET_FLUSH_INTERVAL включает (FLUSH_INTERVAL > 0) или выключает (FLUSH_INTERVAL = 0) периодический сброс данных. FLUSH_INTERVAL - количество секунд.

Входные параметры:

FLUSH_INTERVAL тип INTEGER NOT NULL;
ATTACHMENT_ID тип BIGINT NOT NULL по умолчанию CURRENT_CONNECTION.

14.10. Таблицы снапшотов

Таблицы снапшотов (а также представления и последовательность) автоматически создаются при первом использовании профайлера. Они принадлежат текущему пользователю с правами на чтение/запись для PUBLIC. Когда сеанс завершается, связанные данные в других таблицах снапшотов профайлера также автоматически удаляются с помощью внешних ключей с опцией DELETE CASCADE.

Ниже приведен список таблиц, в которых хранятся данные профайлера.

PLG$PROF_SESSIONS

Идентификатор столбца	Тип данных	Описание
PROFILE_ID	BIGINT	Идентификатор сеанса профайлера.
ATTACHMENT_ID	BIGINT	Идентификатор подключения.
USER_NAME	CHAR(63) CHARACTER SET UTF8	Имя пользователя.
DESCRIPTION	VARCHAR(255) CHARACTER SET UTF8	Описание, переданное в `RDB$PROFILER.START_SESSION`.
START_TIMESTAMP	TIMESTAMP WITH TIME ZONE	Момент запуска сессии профайлера.
FINISH_TIMESTAMP	TIMESTAMP WITH TIME ZONE	Момент, когда сессия профайлера была завершена (`NULL`, если не завершена).

PLG$PROF_STATEMENTS

Идентификатор столбца	Тип данных	Описание
PROFILE_ID	BIGINT	Идентификатор сеанса профайлера.
STATEMENT_ID	BIGINT	Идентификатор оператора.
PARENT_STATEMENT_ID	BIGINT	Идентификатор родительского оператора - связан с подпрограммами.
STATEMENT_TYPE	VARCHAR(20) CHARACTER SET UTF8	Блок, функция, процедура или триггер.
PACKAGE_NAME	CHAR(63) CHARACTER SET UTF8	Пакет функции или процедуры.
ROUTINE_NAME	CHAR(63) CHARACTER SET UTF8	Имя функции, процедуры или триггера.
SQL_TEXT	BLOB	SQL-текст для BLOCK.

PLG$PROF_CURSORS

Идентификатор столбца	Тип данных	Описание
PROFILE_ID	BIGINT	Идентификатор сеанса профайлера.
STATEMENT_ID	BIGINT	Идентификатор оператора.
CURSOR_ID	INTEGER	Идентификатор курсора.
NAME	CHAR(63) CHARACTER SET UTF8	Имя явного курсора.
LINE_NUM	INTEGER	Номер строки оператора.
COLUMN_NUM	INTEGER	Номер столбца оператора.

PLG$PROF_RECORD_SOURCES

Идентификатор столбца	Тип данных	Описание
PROFILE_ID	BIGINT	Идентификатор сеанса профайлера.
STATEMENT_ID	BIGINT	Идентификатор оператора.
CURSOR_ID	BIGINT	Идентификатор курсора.
RECORD_SOURCE_ID	BIGINT	Идентификатор источника записи.
PARENT_RECORD_SOURCE_ID	BIGINT	Идентификатор источника родительской записи.
ACCESS_PATH	VARCHAR(255) CHARACTER SET UTF8	План запроса.

PLG$PROF_PSQL_STATS

Идентификатор столбца	Тип данных	Описание
PROFILE_ID	BIGINT	Идентификатор сеанса профайлера.
REQUEST_ID	BIGINT	Идентификатор запроса.
LINE_NUM	INTEGER	Номер строки оператора.
COLUMN_NUM	INTEGER	Номер столбца оператора.
STATEMENT_ID	BIGINT	Идентификатор оператора.
COUNTER	BIGINT	Количество выполненных раз строки/столбца.
MIN_ELAPSED_TIME	BIGINT	Минимальное затраченное время (в наносекундах) выполнения строки/столбца.
MAX_ELAPSED_TIME	BIGINT	Максимальное затраченное время (в наносекундах) выполнения строки/столбца.
TOTAL_ELAPSED_TIME	BIGINT	Общее затраченное время (в наносекундах) выполнения строки/столбца.

PLG$PROF_RECORD_SOURCE_STATS

Идентификатор столбца	Тип данных	Описание
PROFILE_ID	BIGINT	Идентификатор сеанса профайлера.
REQUEST_ID	BIGINT	Идентификатор запроса.
CURSOR_ID	BIGINT	Идентификатор курсора.
RECORD_SOURCE_ID	BIGINT	Идентификатор источника записи.
STATEMENT_ID	BIGINT	Идентификатор оператора.
OPEN_COUNTER	BIGINT	Количество раз открытия источника записи.
OPEN_MIN_ELAPSED_TIME	BIGINT	Минимальное время открытия источника записи (в наносекундах).
OPEN_MAX_ELAPSED_TIME	BIGINT	Максимальное время открытия источника записи (в наносекундах).
OPEN_TOTAL_ELAPSED_TIME	BIGINT	Общее время открытия источника записи (в наносекундах).
FETCH_COUNTER	BIGINT	Количество выборок из источника записи.
FETCH_MIN_ELAPSED_TIME	BIGINT	Минимальное время выборки из источника записи (в наносекундах).
FETCH_MAX_ELAPSED_TIME	BIGINT	Максимальное время выборки из источника записи (в наносекундах).
FETCH_TOTAL_ELAPSED_TIME	BIGINT	Общее время выборки из источника записи (в наносекундах).

PLG$PROF_REQUESTS

Идентификатор столбца	Тип данных	Описание
PROFILE_ID	BIGINT	Идентификатор сеанса профайлера.
STATEMENT_ID	BIGINT	Идентификатор оператора.
REQUEST_ID	BIGINT	Идентификатор запроса.
CALLER_STATEMENT_ID	BIGINT	Идентификатор оператора (`STATEMENT_ID`), вызвавшего текущий запрос.
CALLER_REQUEST_ID	BIGINT	Идентификатор запроса (`REQUEST_ID`), вызвавшего текущий запрос.
START_TIMESTAMP	TIMESTAMP WITH TIME ZONE	Момент запуска сессии профайлера.
FINISH_TIMESTAMP	TIMESTAMP WITH TIME ZONE	Момент, когда сессия профайлера была завершена (`NULL`, если не завершена).
TOTAL_ELAPSED_TIME	BIGINT	Общее время выполнения запроса (в наносекундах).

14.11. Дополнительные представления

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

PLG$PROF_STATEMENT_STATS_VIEW

select req.profile_id,
       req.statement_id,
       sta.statement_type,
       sta.package_name,
       sta.routine_name,
       sta.parent_statement_id,
       sta_parent.statement_type parent_statement_type,
       sta_parent.routine_name parent_routine_name,
      (
         select sql_text
         from plg$prof_statements
         where profile_id = req.profile_id and
               statement_id = coalesce(sta.parent_statement_id, req.statement_id)
      ) sql_text,
      count(*) counter,
      min(req.total_elapsed_time) min_elapsed_time,
      max(req.total_elapsed_time) max_elapsed_time,
      cast(sum(req.total_elapsed_time) as bigint) total_elapsed_time,
      cast(sum(req.total_elapsed_time) / count(*) as bigint) avg_elapsed_time

from plg$prof_requests req
join plg$prof_statements sta
      on sta.profile_id = req.profile_id and
         sta.statement_id = req.statement_id
left join plg$prof_statements sta_parent
      on sta_parent.profile_id = sta.profile_id and
         sta_parent.statement_id = sta.parent_statement_id
group by req.profile_id,
         req.statement_id,
         sta.statement_type,
         sta.package_name,
         sta.routine_name,
         sta.parent_statement_id,
         sta_parent.statement_type,
         sta_parent.routine_name
order by sum(req.total_elapsed_time) desc

PLG$PROF_PSQL_STATS_VIEW

select pstat.profile_id,
       pstat.statement_id,
       sta.statement_type,
       sta.package_name,
       sta.routine_name,
       sta.parent_statement_id,
       sta_parent.statement_type parent_statement_type,
       sta_parent.routine_name parent_routine_name,
       (select sql_text
        from plg$prof_statements
        where profile_id = pstat.profile_id and
              statement_id = coalesce(sta.parent_statement_id, pstat.statement_id)
       ) sql_text,
       pstat.line_num,
       pstat.column_num,
       cast(sum(pstat.counter) as bigint) counter,
       min(pstat.min_elapsed_time) min_elapsed_time,
       max(pstat.max_elapsed_time) max_elapsed_time,
       cast(sum(pstat.total_elapsed_time) as bigint) total_elapsed_time,
       cast(sum(pstat.total_elapsed_time) / nullif(sum(pstat.counter), 0) as bigint)
                                                                   avg_elapsed_time
from plg$prof_psql_stats pstat
join plg$prof_statements sta
      on sta.profile_id = pstat.profile_id and
         sta.statement_id = pstat.statement_id
left join plg$prof_statements sta_parent
      on sta_parent.profile_id = sta.profile_id and
         sta_parent.statement_id = sta.parent_statement_id
group by pstat.profile_id,
         pstat.statement_id,
         sta.statement_type,
         sta.package_name,
         sta.routine_name,
         sta.parent_statement_id,
         sta_parent.statement_type,
         sta_parent.routine_name,
         pstat.line_num,
         pstat.column_num
order by sum(pstat.total_elapsed_time) desc

PLG$PROF_RECORD_SOURCE_STATS_VIEW

select rstat.profile_id,
       rstat.statement_id,
       sta.statement_type,
       sta.package_name,
       sta.routine_name,
       sta.parent_statement_id,
       sta_parent.statement_type parent_statement_type,
       sta_parent.routine_name parent_routine_name,
       (select sql_text
        from plg$prof_statements
        where profile_id = rstat.profile_id and
              statement_id = coalesce(sta.parent_statement_id, rstat.statement_id)
       ) sql_text,
       rstat.cursor_id,
       rstat.record_source_id,
       recsrc.parent_record_source_id,
       recsrc.access_path,
       cast(sum(rstat.open_counter) as bigint) open_counter,
       min(rstat.open_min_elapsed_time) open_min_elapsed_time,
       max(rstat.open_max_elapsed_time) open_max_elapsed_time,
       cast(sum(rstat.open_total_elapsed_time) as bigint) open_total_elapsed_time,
       cast(sum(rstat.open_total_elapsed_time) / nullif(sum(rstat.open_counter), 0)
                                                   as bigint) open_avg_elapsed_time,
       cast(sum(rstat.fetch_counter) as bigint) fetch_counter,
       min(rstat.fetch_min_elapsed_time) fetch_min_elapsed_time,
       max(rstat.fetch_max_elapsed_time) fetch_max_elapsed_time,
       cast(sum(rstat.fetch_total_elapsed_time) as bigint) fetch_total_elapsed_time,
       cast(sum(rstat.fetch_total_elapsed_time) / nullif(sum(rstat.fetch_counter), 0)
                                                    as bigint) fetch_avg_elapsed_time,
       cast(coalesce(sum(rstat.open_total_elapsed_time), 0) +
            coalesce(sum(rstat.fetch_total_elapsed_time), 0) as bigint)
                                                         open_fetch_total_elapsed_time
from plg$prof_record_source_stats rstat
join plg$prof_record_sources recsrc
      on recsrc.profile_id = rstat.profile_id and
         recsrc.statement_id = rstat.statement_id and
         recsrc.cursor_id = rstat.cursor_id and
         recsrc.record_source_id = rstat.record_source_id
join plg$prof_statements sta
      on sta.profile_id = rstat.profile_id and
         sta.statement_id = rstat.statement_id
left join plg$prof_statements sta_parent
      on sta_parent.profile_id = sta.profile_id and
         sta_parent.statement_id = sta.parent_statement_id
group by rstat.profile_id,
         rstat.statement_id,
         sta.statement_type,
         sta.package_name,
         sta.routine_name,
         sta.parent_statement_id,
         sta_parent.statement_type,
         sta_parent.routine_name,
         rstat.cursor_id,
         rstat.record_source_id,
         recsrc.parent_record_source_id,
         recsrc.access_path
order by coalesce(sum(rstat.open_total_elapsed_time), 0) +
         coalesce(sum(rstat.fetch_total_elapsed_time), 0) desc