27.4. Динамическая трассировка
Postgres Pro позволяет выполнять динамическую трассировку сервера базы данных. Имеющиеся возможности позволяют вызывать внешнюю утилиту в определённых точках кода и таким образом отслеживать его выполнение.
Несколько подобных точек сбора метрик, или точек трассировки, уже встроено в исходный код. Предполагается, что эти точки будут использоваться разработчиками и администраторами базы данных. По умолчанию точки трассировки не входят в сборку Postgres Pro; пользователь должен явно указать конфигурационному скрипту необходимость включения этих макросов.
В настоящее время поддерживается только утилита DTrace, которая доступна для Solaris, OS X, FreeBSD, NetBSD, и Oracle Linux. Проект SystemTap для Linux представляет собой эквивалент DTrace и также может быть использован. Теоретически возможна поддержка и других утилит динамической трассировки, для этого необходимо изменить определения для макроса в src/include/utils/probes.h.
27.4.1. Компиляция для включения динамической трассировки
По умолчанию точки трассировки недоступны, поэтому в конфигурационном скрипте Postgres Pro требуется явно указать необходимость их подключения. Для поддержки утилиты DTrace укажите --enable-dtrace в конфигурационном файле. Более подробно смотрите Раздел 15.4.
27.4.2. Встроенные точки трассировки
В исходный код входит несколько стандартных точек трассировки, которые представлены в Таблице 27.18; в Таблице 27.19 показаны типы данных, которые используются для этих точек. Конечно, для более детального отслеживания работы Postgres Pro можно добавлять и другие точки трассировки.
Таблица 27.18. Встроенные точки трассировки DTrace
| Имя | Параметры | Описание |
|---|---|---|
| transaction-start | (LocalTransactionId) | Срабатывает в начале новой транзакции. arg0 задаёт идентификатор транзакции. |
| transaction-commit | (LocalTransactionId) | Срабатывает при успешном завершении транзакции. arg0 задаёт идентификатор транзакции. |
| transaction-abort | (LocalTransactionId) | Срабатывает, когда транзакция завершается с ошибкой. arg0 задаёт идентификатор транзакции. |
| query-start | (const char *) | Срабатывает, когда начинается обработка запроса. arg0 задаёт текст запроса. |
| query-done | (const char *) | Срабатывает по завершении обработки запроса. arg0 задаёт текст запроса. |
| query-parse-start | (const char *) | Срабатывает, когда начинается разбор запроса. arg0 задаёт текст запроса. |
| query-parse-done | (const char *) | Срабатывает по завершении разбора (parsing) запроса. arg0 задаёт текст запроса. |
| query-rewrite-start | (const char *) | Срабатывает, когда начинается модификация запроса. arg0 задаёт текст запроса. |
| query-rewrite-done | (const char *) | Срабатывает по завершении модификации запроса. arg0 задаёт текст запроса. |
| query-plan-start | () | Срабатывает, когда начинает работать планировщик выполнения запроса. |
| query-plan-done | () | Срабатывает по завершении работы планировщика запроса. |
| query-execute-start | () | Срабатывает, когда начинается выполнение запроса. |
| query-execute-done | () | Срабатывает по завершении выполнения запроса. |
| statement-status | (const char *) | Срабатывает каждый раз, когда серверный процесс обновляет свой статус в pg_stat_activity.status. arg0 задаёт новую строку состояния. |
| checkpoint-start | (int) | Срабатывает в начале контрольной точки. arg0 содержит битовые флаги, с помощью которых задаются разные типы контрольных точек, такие как shutdown, immediate или force. |
| checkpoint-done | (int, int, int, int, int) | Срабатывает по завершении контрольной точки. (Перечисленные далее точки трассировки срабатывают последовательно при обработке контрольной точки.) arg0 задаёт число записанных буферов. arg1 — общее число буферов. arg2, arg3 и arg4 задают число файлов xlog, которые были добавлены, удалены или переработаны соответственно. |
| clog-checkpoint-start | (bool) | Срабатывает, когда начинается запись контрольной точки в CLOG. arg0 = true для обычных контрольных точек и false для контрольных точек типа shutdown. |
| clog-checkpoint-done | (bool) | Срабатывает по завершении записи контрольной точки в CLOG. Значение arg0 задаётся аналогично значению для clog-checkpoint-start. |
| subtrans-checkpoint-start | (bool) | Срабатывает, когда начинается запись контрольной точки в SUBTRANS. arg0 = true для обычных контрольных точек и false для контрольных точек типа shutdown. |
| subtrans-checkpoint-done | (bool) | Срабатывает по завершении записи контрольной точки в SUBTRANS. Значение arg0 задаётся аналогично значению для subtrans-checkpoint-start. |
| multixact-checkpoint-start | (bool) | Срабатывает, когда начинается запись контрольной точки в MultiXact. arg0 = true для обычных контрольных точек и false для контрольных точек типа shutdown. |
| multixact-checkpoint-done | (bool) | Срабатывает по завершении записи контрольной точки в MultiXact. Значение arg0 задаётся аналогично значению для multixact-checkpoint-start. |
| buffer-checkpoint-start | (int) | Срабатывает, когда начинается запись буферов контрольной точки. arg0 содержит битовые флаги, с помощью которых задаются разные типы контрольных точек, такие как shutdown, immediate или force. |
| buffer-sync-start | (int, int) | Срабатывает во время контрольной точки, когда начинается запись грязных буферов (после нахождения буферов, которые должны быть записаны). arg0 задаёт общее число буферов. arg1 задаёт число буферов, которые в настоящий момент являются грязными и должны быть записаны. |
| buffer-sync-written | (int) | Срабатывает после записи каждого буфера при выполнении контрольной точки. arg0 задаёт идентификатор буфера. |
| buffer-sync-done | (int, int, int) | Срабатывает после записи всех грязных буферов. arg0 задаёт общее число буферов. arg1 задаёт число буферов, которые фактически были записаны процессом выполнения контрольной точки. arg2 задаёт число буферов, которое должно было быть записано (arg1 из buffer-sync-start); разные значения говорят о том, что во время выполнения этой контрольной точки буферы сбрасывались другими процессами. |
| buffer-checkpoint-sync-start | () | Срабатывает после записи грязных буферов в ядро и до начала формирования запросов fsync. |
| buffer-checkpoint-done | () | Срабатывает по завершении синхронизации буферов с диском. |
| twophase-checkpoint-start | () | Срабатывает, когда начинается двухфазный этап выполнения контрольной точки. |
| twophase-checkpoint-done | () | Срабатывает по завершении двухфазного этапа выполнения контрольной точки. |
| buffer-read-start | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, bool) | Срабатывает, когда начинается чтение из буфера. arg0 и arg1 содержат номер слоя и номер блока этой страницы (arg1 будет иметь значение -1, если выполняется запрос на расширение места для таблицы). arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. arg5 для локального буфера задаёт идентификатор серверного процесса, создавшего временное отношение, или InvalidBackendId (-1) — для разделяемого буфера. arg6 = true для запросов на расширение места для таблицы, false — в случае обычного чтения. |
| buffer-read-done | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, bool, bool) | Срабатывает по завершении чтения буфера. arg0 и arg1 содержат номер слоя и номер блока этой страницы (arg1 будет содержать номер только что добавленного блока, если выполняется запрос на расширение места для таблицы). arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. arg5 для локального буфера задаёт идентификатор серверного процесса, создавшего временное отношение, или InvalidBackendId (-1) — для разделяемого буфера. arg6 = true для запросов на расширение места для таблицы, false — в случае обычного чтения. arg7 = true, если буфер был обнаружен в пуле, false — если нет. |
| buffer-flush-start | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Срабатывает перед формированием любого запроса на запись в разделяемый буфер. arg0 и arg1 содержат номер слоя и номер блока этой страницы. arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. |
| buffer-flush-done | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Срабатывает по завершении запроса на запись в разделяемый буфер. (Учтите, что это отражает только время на передачу данных в ядро; обычно на диск они ещё не записаны.) Аргументы аналогичны buffer-flush-start. |
| buffer-write-dirty-start | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Срабатывает, когда серверный процесс начинает запись грязного буфера. (Частое повторение такой ситуации означает, что значение shared_buffers слишком мало или что управляющие параметры bgwriter необходимо откорректировать.) arg0 и arg1 содержат номер слоя и номер блока этой страницы. arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. |
| buffer-write-dirty-done | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Срабатывает по завершении записи грязного буфера. Аргументы аналогичны buffer-write-dirty-start. |
| wal-buffer-write-dirty-start | () | Срабатывает, когда серверный процесс начинает запись грязного WAL буфера из-за того, что свободные WAL буферы закончились. (Частое повторение такой ситуации означает, что значение wal_buffers слишком мало.) |
| wal-buffer-write-dirty-done | () | Срабатывает по завершении записи грязного WAL буфера. |
| xlog-insert | (unsigned char, unsigned char) | Срабатывает при добавлении записи в WAL. arg0 задаёт идентификатор менеджера ресурсов (rmid) для этой записи. arg1 задаёт информационные флаги. |
| xlog-switch | () | Срабатывает при запросе на переключение сегмента WAL. |
| smgr-md-read-start | (ForkNumber, BlockNumber, Oid, Oid, Oid, int) | Срабатывает, когда начинается чтение блока из отношения. arg0 и arg1 содержат номер слоя и номер блока этой страницы. arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. arg5 для локального буфера задаёт идентификатор серверного процесса, создавшего временное отношение, или InvalidBackendId (-1) — для разделяемого буфера. |
| smgr-md-read-done | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, int, int) | Срабатывает по завершении чтения блока из отношения. arg0 и arg1 содержат номер слоя и номер блока этой страницы. arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. arg5 для локального буфера задаёт идентификатор серверного процесса, создавшего временное отношение, или InvalidBackendId (-1) — для разделяемого буфера. arg6 задаёт количество фактически прочитанных байтов, тогда как arg7 задаёт количество запрошенных байтов (различия говорят о наличии проблемы). |
| smgr-md-write-start | (ForkNumber, BlockNumber, Oid, Oid, Oid, int) | Срабатывает, когда начинается запись блока в отношение. arg0 и arg1 содержат номер слоя и номер блока этой страницы. arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. arg5 для локального буфера задаёт идентификатор серверного процесса, создавшего временное отношение, или InvalidBackendId (-1) — для разделяемого буфера. |
| smgr-md-write-done | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, int, int) | Срабатывает по завершении записи блока в отношение. arg0 и arg1 содержат номер слоя и номер блока этой страницы. arg2, arg3 и arg4 содержат OID-ы табличного пространства, базы данных и отношения, которые однозначно идентифицируют отношение. arg5 для локального буфера задаёт идентификатор серверного процесса, создавшего временное отношение, или InvalidBackendId (-1) — для разделяемого буфера. arg6 задаёт количество фактически записанных байтов, тогда как arg7 задаёт количество запрошенных байтов (различия говорят о наличии проблемы). |
| sort-start | (int, bool, int, int, bool) | Срабатывает, когда начинается операция сортировки. arg0 задаёт сортировку таблицы, индекса или элемента данных. arg1 = true, если данные ожидаются уникальными. arg2 задаёт число ключевых столбцов. arg3 задаёт объём доступной рабочей памяти в килобайтах. arg4 = true, если требуется произвольный доступ к результату сортировки. |
| sort-done | (bool, long) | Срабатывает по завершении сортировки. arg0 = true для внешней сортировки, false — для внутренней сортировки. arg1 задаёт число дисковых блоков, использованных для внешней сортировки, или объём памяти, использованной для внутренней сортировки, в килобайтах. |
| lwlock-acquire | (char *, int, LWLockMode) | Срабатывает, когда накладывается блокировка LWLock. arg0 задаёт идентификатор блокировки. arg1 задаёт смещение LWLOCK в своей части. arg2 задаёт тип запрошенной блокировки: монопольная или разделяемая. |
| lwlock-release | (char *, int) | Срабатывает, когда блокировка LWLock была снята (однако учтите, что никакие ждущие процессы ещё не были активированы). arg0 задаёт идентификатор блокировки LWLock. arg1 задаёт смещение внутри идентификатора блокировки LWLock. |
| lwlock-wait-start | (char *, int, LWLockMode) | Срабатывает, когда оказывается, что наложить блокировку LWLock немедленно нельзя, и серверный процесс начинает ожидать освобождения блокировки. arg0 задаёт идентификатор блокировки LWLock. arg1 задаёт смещение внутри идентификатора блокировки LWLock. arg2 задаёт тип запрошенной блокировки, монопольная или разделяемая. |
| lwlock-wait-done | (char *, int, LWLockMode) | Срабатывает, когда серверный процесс прекращает ожидание блокировки LWLock (но саму блокировку он ещё не получил). arg0 задаёт идентификатор блокировки LWLock. arg1 задаёт смещение внутри идентификатора блокировки LWLock. arg2 задаёт тип запрошенной блокировки, монопольная или разделяемая. |
| lwlock-condacquire | (char *, int, LWLockMode) | Срабатывает, когда блокировка LWLock была успешно получена процессом, запросившим её в режиме без ожидания. arg0 задаёт идентификатор блокировки LWLock. arg1 задаёт смещение внутри идентификатора блокировки LWLock. arg2 задаёт тип запрошенной блокировки, монопольная или разделяемая. |
| lwlock-condacquire-fail | (char *, int, LWLockMode) | Срабатывает, когда процесс, запросивший блокировку LWLock в режиме без ожидания, не смог её получить. arg0 задаёт идентификатор блокировки LWLock. arg1 задаёт смещение внутри идентификатора блокировки LWLock. arg2 задаёт тип запрошенной блокировки, монопольная или разделяемая. |
| lock-wait-start | (unsigned int, unsigned int, unsigned int, unsigned int, unsigned int, LOCKMODE) | Срабатывает, когда запрос на тяжёлую блокировку (блокировку lmgr) переходит в состояние ожидания, поскольку блокировка недоступна. Аргументы с arg0 до arg3 задают атрибуты, идентифицирующие объект, на который накладывается блокировка. arg4 задаёт тип объекта, на который накладывается блокировка. arg5 задаёт тип запрошенной блокировки. |
| lock-wait-done | (unsigned int, unsigned int, unsigned int, unsigned int, unsigned int, LOCKMODE) | Срабатывает, когда запрос на тяжёлую блокировку (блокировку lmgr) выходит из состояния ожидания (т. е. получает блокировку). Аргументы аналогичны lock-wait-start. |
| deadlock-found | () | Срабатывает, когда детектор взаимных блокировок обнаруживает такую взаимную блокировку |
Таблица 27.19. Предопределённые типы, используемые в параметрах точек трассировки
| Тип | Определение |
|---|---|
| LocalTransactionId | unsigned int |
| LWLockMode | int |
| LOCKMODE | int |
| BlockNumber | unsigned int |
| Oid | unsigned int |
| ForkNumber | int |
| bool | char |
27.4.3. Использование точек трассировки
В приведённом ниже примере показан скрипт DTrace для анализа числа транзакций в системе, который можно использовать в качестве альтернативы созданию снимка данных pg_stat_database до и после выполнения теста производительности:
#!/usr/sbin/dtrace -qs
postgresql$1:::transaction-start
{
@start["Start"] = count();
self->ts = timestamp;
}
postgresql$1:::transaction-abort
{
@abort["Abort"] = count();
}
postgresql$1:::transaction-commit
/self->ts/
{
@commit["Commit"] = count();
@time["Total time (ns)"] = sum(timestamp - self->ts);
self->ts=0;
}При выполнении этот D-скрипт возвращает результат вида:
# ./txn_count.d `pgrep -n postgres` or ./txn_count.d <PID> ^C Start 71 Commit 70 Total time (ns) 2312105013
Примечание
SystemTap использует отличную от DTrace нотацию для скриптов трассировки, хотя лежащие в их основе точки трассировки совместимы. Стоит отметить, что на момент написания этой главы в скриптах SystemTap имена точек трассировки должны обрамляться двойными подчёркиваниями, а не дефисами. Ожидается, что эта проблема будет решена в следующих версиях SystemTap.
Необходимо помнить, что скрипты DTrace должны быть аккуратно написаны и отлажены, в противном случае собранная трассировочная информация может оказаться бессмысленной. В большинстве случаев причиной обнаруженных проблем является инструментарий, а не сама система. Отправляя на рассмотрение данные, полученные с использованием динамической трассировки, обязательно прилагайте скрипт, с помощью которого они были получены, для того чтобы его также проверить и обсудить.
27.4.4. Задание новых точек трассировки
Новые точки трассировки разработчик может определить в любом участке кода, однако это потребует перекомпиляции. Ниже приведены шаги, необходимые для добавления новых точек трассировки:
Определить имена точек трассировки и данные, которые будут доступны в этих точках
Добавить описание точек трассировки в
src/backend/utils/probes.dВключить
pg_trace.h, если его ещё не использовали в модуле (модулях), содержащих точки трассировки, и вставитьTRACE_POSTGRESQLотладочные макросы в нужные места исходного кодаПерекомпилировать и убедиться в доступности новых точек трассировки
Пример: Вот пример того, как можно добавить точку для трассировки всех новых транзакций по их идентификатору.
Устанавливает, что проба будет называться
transaction-startи принимать параметр типа LocalTransactionIdДобавляем определение пробы в
src/backend/utils/probes.d:probe transaction__start(LocalTransactionId);
Обратите внимание на использование двойного подчёркивания в имени пробы. В скрипте DTrace, использующем эту точку, двойное подчёркивание нужно будет заменить дефисом, поэтому в документации для пользователей имя этой пробы —
transaction-start.Во время компиляции
transaction__startпреобразуется в макросTRACE_POSTGRESQL_TRANSACTION_START(обратите внимание, что здесь используется одинарное подчёркивание), который доступен в результате включенияpg_trace.h. Добавим вызов макроса в требуемую точку исходного кода. В данном случае это будет выглядеть приблизительно так:TRACE_POSTGRESQL_TRANSACTION_START(vxid.localTransactionId);
После перекомпиляции и запуска нового бинарного файла используйте следующую команду DTrace, чтобы проверить доступность только что добавленной пробы. Должен получиться результат, подобный этому:
# dtrace -ln transaction-start ID PROVIDER MODULE FUNCTION NAME 18705 postgresql49878 postgres StartTransactionCommand transaction-start 18755 postgresql49877 postgres StartTransactionCommand transaction-start 18805 postgresql49876 postgres StartTransactionCommand transaction-start 18855 postgresql49875 postgres StartTransactionCommand transaction-start 18986 postgresql49873 postgres StartTransactionCommand transaction-start
При добавлении макросов трассировки в код, написанный на языке C, необходимо позаботиться о следующем:
Нужно убедиться, что типы данных, определённые в параметрах пробы, совпадают с типами данных переменных, которые используются в макросе. В противном случае компиляция завершится с ошибками.
В большинстве платформ в случае, если Postgres Pro собран с указанием
--enable-dtrace, то аргументы макроса трассировки вычисляются каждый раз, когда макрос получает управление, даже если трассировка не выполняется. Об этом не стоит беспокоиться, если вы просто возвращаете значения небольшого числа локальных переменных. Однако избегайте использования ресурсоёмких вызовов функций в аргументах. Если это необходимо, то постарайтесь защитить макрос проверкой, которая будет определять, действительно ли включена трассировка:if (TRACE_POSTGRESQL_TRANSACTION_START_ENABLED()) TRACE_POSTGRESQL_TRANSACTION_START(some_function(...));Каждый макрос трассировки имеет соответствующий макрос
ENABLED.
27.4. Dynamic Tracing
Postgres Pro provides facilities to support dynamic tracing of the database server. This allows an external utility to be called at specific points in the code and thereby trace execution.
A number of probes or trace points are already inserted into the source code. These probes are intended to be used by database developers and administrators. By default the probes are not compiled into Postgres Pro; the user needs to explicitly tell the configure script to make the probes available.
Currently, the DTrace utility is supported, which, at the time of this writing, is available on Solaris, OS X, FreeBSD, NetBSD, and Oracle Linux. The SystemTap project for Linux provides a DTrace equivalent and can also be used. Supporting other dynamic tracing utilities is theoretically possible by changing the definitions for the macros in src/include/utils/probes.h.
27.4.1. Compiling for Dynamic Tracing
By default, probes are not available, so you will need to explicitly tell the configure script to make the probes available in Postgres Pro. To include DTrace support specify --enable-dtrace to configure. See Section 15.4 for further information.
27.4.2. Built-in Probes
A number of standard probes are provided in the source code, as shown in Table 27.18; Table 27.19 shows the types used in the probes. More probes can certainly be added to enhance Postgres Pro's observability.
Table 27.18. Built-in DTrace Probes
| Name | Parameters | Description |
|---|---|---|
| transaction-start | (LocalTransactionId) | Probe that fires at the start of a new transaction. arg0 is the transaction ID. |
| transaction-commit | (LocalTransactionId) | Probe that fires when a transaction completes successfully. arg0 is the transaction ID. |
| transaction-abort | (LocalTransactionId) | Probe that fires when a transaction completes unsuccessfully. arg0 is the transaction ID. |
| query-start | (const char *) | Probe that fires when the processing of a query is started. arg0 is the query string. |
| query-done | (const char *) | Probe that fires when the processing of a query is complete. arg0 is the query string. |
| query-parse-start | (const char *) | Probe that fires when the parsing of a query is started. arg0 is the query string. |
| query-parse-done | (const char *) | Probe that fires when the parsing of a query is complete. arg0 is the query string. |
| query-rewrite-start | (const char *) | Probe that fires when the rewriting of a query is started. arg0 is the query string. |
| query-rewrite-done | (const char *) | Probe that fires when the rewriting of a query is complete. arg0 is the query string. |
| query-plan-start | () | Probe that fires when the planning of a query is started. |
| query-plan-done | () | Probe that fires when the planning of a query is complete. |
| query-execute-start | () | Probe that fires when the execution of a query is started. |
| query-execute-done | () | Probe that fires when the execution of a query is complete. |
| statement-status | (const char *) | Probe that fires anytime the server process updates its pg_stat_activity.status. arg0 is the new status string. |
| checkpoint-start | (int) | Probe that fires when a checkpoint is started. arg0 holds the bitwise flags used to distinguish different checkpoint types, such as shutdown, immediate or force. |
| checkpoint-done | (int, int, int, int, int) | Probe that fires when a checkpoint is complete. (The probes listed next fire in sequence during checkpoint processing.) arg0 is the number of buffers written. arg1 is the total number of buffers. arg2, arg3 and arg4 contain the number of xlog file(s) added, removed and recycled respectively. |
| clog-checkpoint-start | (bool) | Probe that fires when the CLOG portion of a checkpoint is started. arg0 is true for normal checkpoint, false for shutdown checkpoint. |
| clog-checkpoint-done | (bool) | Probe that fires when the CLOG portion of a checkpoint is complete. arg0 has the same meaning as for clog-checkpoint-start. |
| subtrans-checkpoint-start | (bool) | Probe that fires when the SUBTRANS portion of a checkpoint is started. arg0 is true for normal checkpoint, false for shutdown checkpoint. |
| subtrans-checkpoint-done | (bool) | Probe that fires when the SUBTRANS portion of a checkpoint is complete. arg0 has the same meaning as for subtrans-checkpoint-start. |
| multixact-checkpoint-start | (bool) | Probe that fires when the MultiXact portion of a checkpoint is started. arg0 is true for normal checkpoint, false for shutdown checkpoint. |
| multixact-checkpoint-done | (bool) | Probe that fires when the MultiXact portion of a checkpoint is complete. arg0 has the same meaning as for multixact-checkpoint-start. |
| buffer-checkpoint-start | (int) | Probe that fires when the buffer-writing portion of a checkpoint is started. arg0 holds the bitwise flags used to distinguish different checkpoint types, such as shutdown, immediate or force. |
| buffer-sync-start | (int, int) | Probe that fires when we begin to write dirty buffers during checkpoint (after identifying which buffers must be written). arg0 is the total number of buffers. arg1 is the number that are currently dirty and need to be written. |
| buffer-sync-written | (int) | Probe that fires after each buffer is written during checkpoint. arg0 is the ID number of the buffer. |
| buffer-sync-done | (int, int, int) | Probe that fires when all dirty buffers have been written. arg0 is the total number of buffers. arg1 is the number of buffers actually written by the checkpoint process. arg2 is the number that were expected to be written (arg1 of buffer-sync-start); any difference reflects other processes flushing buffers during the checkpoint. |
| buffer-checkpoint-sync-start | () | Probe that fires after dirty buffers have been written to the kernel, and before starting to issue fsync requests. |
| buffer-checkpoint-done | () | Probe that fires when syncing of buffers to disk is complete. |
| twophase-checkpoint-start | () | Probe that fires when the two-phase portion of a checkpoint is started. |
| twophase-checkpoint-done | () | Probe that fires when the two-phase portion of a checkpoint is complete. |
| buffer-read-start | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, bool) | Probe that fires when a buffer read is started. arg0 and arg1 contain the fork and block numbers of the page (but arg1 will be -1 if this is a relation extension request). arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. arg5 is the ID of the backend which created the temporary relation for a local buffer, or InvalidBackendId (-1) for a shared buffer. arg6 is true for a relation extension request, false for normal read. |
| buffer-read-done | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, bool, bool) | Probe that fires when a buffer read is complete. arg0 and arg1 contain the fork and block numbers of the page (if this is a relation extension request, arg1 now contains the block number of the newly added block). arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. arg5 is the ID of the backend which created the temporary relation for a local buffer, or InvalidBackendId (-1) for a shared buffer. arg6 is true for a relation extension request, false for normal read. arg7 is true if the buffer was found in the pool, false if not. |
| buffer-flush-start | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Probe that fires before issuing any write request for a shared buffer. arg0 and arg1 contain the fork and block numbers of the page. arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. |
| buffer-flush-done | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Probe that fires when a write request is complete. (Note that this just reflects the time to pass the data to the kernel; it's typically not actually been written to disk yet.) The arguments are the same as for buffer-flush-start. |
| buffer-write-dirty-start | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Probe that fires when a server process begins to write a dirty buffer. (If this happens often, it implies that shared_buffers is too small or the bgwriter control parameters need adjustment.) arg0 and arg1 contain the fork and block numbers of the page. arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. |
| buffer-write-dirty-done | (ForkNumber, BlockNumber, Oid, Oid, Oid) | Probe that fires when a dirty-buffer write is complete. The arguments are the same as for buffer-write-dirty-start. |
| wal-buffer-write-dirty-start | () | Probe that fires when a server process begins to write a dirty WAL buffer because no more WAL buffer space is available. (If this happens often, it implies that wal_buffers is too small.) |
| wal-buffer-write-dirty-done | () | Probe that fires when a dirty WAL buffer write is complete. |
| xlog-insert | (unsigned char, unsigned char) | Probe that fires when a WAL record is inserted. arg0 is the resource manager (rmid) for the record. arg1 contains the info flags. |
| xlog-switch | () | Probe that fires when a WAL segment switch is requested. |
| smgr-md-read-start | (ForkNumber, BlockNumber, Oid, Oid, Oid, int) | Probe that fires when beginning to read a block from a relation. arg0 and arg1 contain the fork and block numbers of the page. arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. arg5 is the ID of the backend which created the temporary relation for a local buffer, or InvalidBackendId (-1) for a shared buffer. |
| smgr-md-read-done | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, int, int) | Probe that fires when a block read is complete. arg0 and arg1 contain the fork and block numbers of the page. arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. arg5 is the ID of the backend which created the temporary relation for a local buffer, or InvalidBackendId (-1) for a shared buffer. arg6 is the number of bytes actually read, while arg7 is the number requested (if these are different it indicates trouble). |
| smgr-md-write-start | (ForkNumber, BlockNumber, Oid, Oid, Oid, int) | Probe that fires when beginning to write a block to a relation. arg0 and arg1 contain the fork and block numbers of the page. arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. arg5 is the ID of the backend which created the temporary relation for a local buffer, or InvalidBackendId (-1) for a shared buffer. |
| smgr-md-write-done | (ForkNumber, BlockNumber, Oid, Oid, Oid, int, int, int) | Probe that fires when a block write is complete. arg0 and arg1 contain the fork and block numbers of the page. arg2, arg3, and arg4 contain the tablespace, database, and relation OIDs identifying the relation. arg5 is the ID of the backend which created the temporary relation for a local buffer, or InvalidBackendId (-1) for a shared buffer. arg6 is the number of bytes actually written, while arg7 is the number requested (if these are different it indicates trouble). |
| sort-start | (int, bool, int, int, bool) | Probe that fires when a sort operation is started. arg0 indicates heap, index or datum sort. arg1 is true for unique-value enforcement. arg2 is the number of key columns. arg3 is the number of kilobytes of work memory allowed. arg4 is true if random access to the sort result is required. |
| sort-done | (bool, long) | Probe that fires when a sort is complete. arg0 is true for external sort, false for internal sort. arg1 is the number of disk blocks used for an external sort, or kilobytes of memory used for an internal sort. |
| lwlock-acquire | (char *, int, LWLockMode) | Probe that fires when an LWLock has been acquired. arg0 is the LWLock's tranche. arg1 is the LWLock's offset within its tranche. arg2 is the requested lock mode, either exclusive or shared. |
| lwlock-release | (char *, int) | Probe that fires when an LWLock has been released (but note that any released waiters have not yet been awakened). arg0 is the LWLock's tranche. arg1 is the LWLock's offset within its tranche. |
| lwlock-wait-start | (char *, int, LWLockMode) | Probe that fires when an LWLock was not immediately available and a server process has begun to wait for the lock to become available. arg0 is the LWLock's tranche. arg1 is the LWLock's offset within its tranche. arg2 is the requested lock mode, either exclusive or shared. |
| lwlock-wait-done | (char *, int, LWLockMode) | Probe that fires when a server process has been released from its wait for an LWLock (it does not actually have the lock yet). arg0 is the LWLock's tranche. arg1 is the LWLock's offset within its tranche. arg2 is the requested lock mode, either exclusive or shared. |
| lwlock-condacquire | (char *, int, LWLockMode) | Probe that fires when an LWLock was successfully acquired when the caller specified no waiting. arg0 is the LWLock's tranche. arg1 is the LWLock's offset within its tranche. arg2 is the requested lock mode, either exclusive or shared. |
| lwlock-condacquire-fail | (char *, int, LWLockMode) | Probe that fires when an LWLock was not successfully acquired when the caller specified no waiting. arg0 is the LWLock's tranche. arg1 is the LWLock's offset within its tranche. arg2 is the requested lock mode, either exclusive or shared. |
| lock-wait-start | (unsigned int, unsigned int, unsigned int, unsigned int, unsigned int, LOCKMODE) | Probe that fires when a request for a heavyweight lock (lmgr lock) has begun to wait because the lock is not available. arg0 through arg3 are the tag fields identifying the object being locked. arg4 indicates the type of object being locked. arg5 indicates the lock type being requested. |
| lock-wait-done | (unsigned int, unsigned int, unsigned int, unsigned int, unsigned int, LOCKMODE) | Probe that fires when a request for a heavyweight lock (lmgr lock) has finished waiting (i.e., has acquired the lock). The arguments are the same as for lock-wait-start. |
| deadlock-found | () | Probe that fires when a deadlock is found by the deadlock detector. |
Table 27.19. Defined Types Used in Probe Parameters
| Type | Definition |
|---|---|
| LocalTransactionId | unsigned int |
| LWLockMode | int |
| LOCKMODE | int |
| BlockNumber | unsigned int |
| Oid | unsigned int |
| ForkNumber | int |
| bool | char |
27.4.3. Using Probes
The example below shows a DTrace script for analyzing transaction counts in the system, as an alternative to snapshotting pg_stat_database before and after a performance test:
#!/usr/sbin/dtrace -qs
postgresql$1:::transaction-start
{
@start["Start"] = count();
self->ts = timestamp;
}
postgresql$1:::transaction-abort
{
@abort["Abort"] = count();
}
postgresql$1:::transaction-commit
/self->ts/
{
@commit["Commit"] = count();
@time["Total time (ns)"] = sum(timestamp - self->ts);
self->ts=0;
}
When executed, the example D script gives output such as:
# ./txn_count.d `pgrep -n postgres` or ./txn_count.d <PID> ^C Start 71 Commit 70 Total time (ns) 2312105013
Note
SystemTap uses a different notation for trace scripts than DTrace does, even though the underlying trace points are compatible. One point worth noting is that at this writing, SystemTap scripts must reference probe names using double underscores in place of hyphens. This is expected to be fixed in future SystemTap releases.
You should remember that DTrace scripts need to be carefully written and debugged, otherwise the trace information collected might be meaningless. In most cases where problems are found it is the instrumentation that is at fault, not the underlying system. When discussing information found using dynamic tracing, be sure to enclose the script used to allow that too to be checked and discussed.
27.4.4. Defining New Probes
New probes can be defined within the code wherever the developer desires, though this will require a recompilation. Below are the steps for inserting new probes:
Decide on probe names and data to be made available through the probes
Add the probe definitions to
src/backend/utils/probes.dInclude
pg_trace.hif it is not already present in the module(s) containing the probe points, and insertTRACE_POSTGRESQLprobe macros at the desired locations in the source codeRecompile and verify that the new probes are available
Example: Here is an example of how you would add a probe to trace all new transactions by transaction ID.
Decide that the probe will be named
transaction-startand requires a parameter of type LocalTransactionIdAdd the probe definition to
src/backend/utils/probes.d:probe transaction__start(LocalTransactionId);
Note the use of the double underline in the probe name. In a DTrace script using the probe, the double underline needs to be replaced with a hyphen, so
transaction-startis the name to document for users.At compile time,
transaction__startis converted to a macro calledTRACE_POSTGRESQL_TRANSACTION_START(notice the underscores are single here), which is available by includingpg_trace.h. Add the macro call to the appropriate location in the source code. In this case, it looks like the following:TRACE_POSTGRESQL_TRANSACTION_START(vxid.localTransactionId);
After recompiling and running the new binary, check that your newly added probe is available by executing the following DTrace command. You should see similar output:
# dtrace -ln transaction-start ID PROVIDER MODULE FUNCTION NAME 18705 postgresql49878 postgres StartTransactionCommand transaction-start 18755 postgresql49877 postgres StartTransactionCommand transaction-start 18805 postgresql49876 postgres StartTransactionCommand transaction-start 18855 postgresql49875 postgres StartTransactionCommand transaction-start 18986 postgresql49873 postgres StartTransactionCommand transaction-start
There are a few things to be careful about when adding trace macros to the C code:
You should take care that the data types specified for a probe's parameters match the data types of the variables used in the macro. Otherwise, you will get compilation errors.
On most platforms, if Postgres Pro is built with
--enable-dtrace, the arguments to a trace macro will be evaluated whenever control passes through the macro, even if no tracing is being done. This is usually not worth worrying about if you are just reporting the values of a few local variables. But beware of putting expensive function calls into the arguments. If you need to do that, consider protecting the macro with a check to see if the trace is actually enabled:if (TRACE_POSTGRESQL_TRANSACTION_START_ENABLED()) TRACE_POSTGRESQL_TRANSACTION_START(some_function(...));Each trace macro has a corresponding
ENABLEDmacro.