АйТи Фреш
Главная / Статьи / 1С и базы данных
1С и базы данных

Функция идёт четыре минуты, а разница между двумя now() — ноль: чем на самом деле измерять время в PostgreSQL

Автор: Семёнов Евгений Сергеевич, директор ООО «АйТи-Фреш» · · ~31 мин чтения
Функция идёт четыре минуты, а разница между двумя now() — ноль: чем на самом деле измерять время в PostgreSQL
Иллюстрация к статье «Функция идёт четыре минуты, а разница между двумя now() — ноль: чем на самом деле измерять время в PostgreSQL».

Эта статья для тех, кто пишет функции и процедуры на PL/pgSQL и однажды увидел в собственном журнале «00:00:00» напротив шага, который реально работает четыре минуты. Я разберу, почему так устроены now(), CURRENT_TIMESTAMP и transaction_timestamp(), чем от них отличаются statement_timestamp() и clock_timestamp(), какой шаблон замера использую у клиентов, где этот шаблон может ввести в заблуждение и что даёт штатная диагностика PostgreSQL 18. Внутри — воспроизводимый опыт, рабочий код и разбор ночного регламента условного клиента: бухгалтерской фирмы «Баланс-Сервис», 30 РМ.

Ноль секунд на шаге, который идёт четыре минуты

Типичное обращение выглядит так. Разработчик написал функцию пересчёта витрин, завёл таблицу журнала, в начале каждого шага сохранил now(), в конце снова вызвал now() и положил в отчёт разницу. Отчёт показывает ноль миллисекунд по всем двенадцати шагам. При этом внешний планировщик зафиксировал старт в 02:00 и завершение примерно через четыре минуты. Человек ищет ошибку в арифметике интервалов, хотя вычитание работает правильно.

Причина в семантике now(). Эта функция возвращает не показание часов в момент вызова, а время начала текущей транзакции. Официальная документация PostgreSQL отдельно подчёркивает: значение не меняется в течение транзакции, и это сделано намеренно, чтобы все изменения одной транзакции имели согласованное представление о текущем времени. Если функция PL/pgSQL вызвана одним оператором и сама не может завершать транзакции, все вызовы now() внутри неё возвращают одну метку. Вычитание двух одинаковых значений закономерно даёт нулевой интервал.

То же правило действует для CURRENT_TIMESTAMP, CURRENT_DATE, CURRENT_TIME, LOCALTIME и LOCALTIMESTAMP. transaction_timestamp() эквивалентна CURRENT_TIMESTAMP, а now() — традиционный эквивалент transaction_timestamp(). Типы результатов различаются: например, CURRENT_DATE возвращает date, а LOCALTIMESTAMP — timestamp without time zone, но опорный момент у них один — начало транзакции. Поэтому ни одна из этих конструкций не подходит для измерения прошедшего времени внутри той же транзакции.

Для показания фактического времени PostgreSQL даёт clock_timestamp(). Она возвращает timestamp with time zone на момент вызова, поэтому значение меняется даже в пределах одного SQL-оператора. В простом журнале этапов достаточно заменить обе метки замера на clock_timestamp(), но я всегда проверяю ещё DDL таблицы: DEFAULT now() у started_at или finished_at способен незаметно вернуть ту же ошибку.

Есть важная граница формулировки. Процедура, вызванная верхнеуровневым CALL, в разрешённом контексте может выполнять COMMIT или ROLLBACK; после этого PostgreSQL автоматически начинает новую транзакцию. Тогда now() изменится на границе транзакций, но всё равно не станет таймером этапа. Функции, вызываемые через SELECT, управлять транзакциями не могут. Поэтому универсальное правило остаётся прежним: транзакционное время — для бизнес-меток, фактические часы — для замера.

Если все этапы журнала показывают ноль, а внешний запуск длится минуты, первым делом проверяйте now(), CURRENT_TIMESTAMP и DEFAULT-выражения в таблице замеров.
Порядок действий: Ноль секунд на шаге, который идёт четыре минуты — схема
Порядок действий: Ноль секунд на шаге, который идёт четыре минуты. Открыть схему в полном размере

Четыре отметки времени: где именно каждая замирает

Поведение проще увидеть в psql. Ниже одна явная транзакция, три отдельных оператора SELECT и пауза между ними. pg_sleep(3) принимает число секунд типа double precision; фактическая пауза будет не короче заданной, но под нагрузкой может оказаться немного длиннее. Именно поэтому в результате разумно ждать разницу не меньше трёх секунд, а не заранее придуманное точное число микросекунд.

BEGIN;
SELECT now() AS tx_started,
       statement_timestamp() AS statement_started,
       clock_timestamp() AS measured_at;

SELECT pg_sleep(3);

SELECT now() AS tx_started,
       statement_timestamp() AS statement_started,
       clock_timestamp() AS measured_at;
COMMIT;

В обоих SELECT колонка tx_started будет одинаковой: транзакция одна. Значение statement_started во втором SELECT станет позднее, потому что сервер получил новую команду. measured_at тоже уйдёт вперёд и обычно будет чуть позднее statement_started, поскольку clock_timestamp() вычисляется уже при исполнении выражения. В первом операторе transaction_timestamp() и statement_timestamp() совпадают; clock_timestamp() не обязана совпадать с ними до микросекунды.

Внутри одного оператора различие видно без искусственно нарисованного вывода. Добавим короткую паузу для каждой строки через LATERAL-подзапрос, зависимый от номера строки, чтобы планировщик не имел права выполнить его один раз. now() останется постоянной, а clock_timestamp() будет считываться заново после каждой паузы.

SELECT g.n,
       now() AS tx_started,
       clock_timestamp() AS measured_at
FROM generate_series(1, 3) AS g(n)
CROSS JOIN LATERAL (
    SELECT pg_sleep(g.n * 0 + 0.1)
) AS delay;

statement_timestamp() полезна как готовая опорная точка внешней команды. Если функция вызвана одним SELECT, а процедура — одним CALL и внутри не завершает транзакцию, выражение clock_timestamp() - statement_timestamp() показывает, сколько прошло с момента получения этой команды сервером. Это удобно для одной итоговой строки, но для отдельных этапов всё равно нужна собственная t_mark: каждый этап начинается позже statement_timestamp().

Тот же нюанс важен в pg_stat_activity. query_start — время начала активного запроса, а xact_start — время начала транзакции. Мониторинговый запрос, открытый внутри старой незавершённой транзакции, получит от now() старую метку xact_start своего сеанса. Для чужого запроса, начавшегося позже, now() - query_start может стать отрицательным. Я считаю возраст активного запроса от clock_timestamp() и фильтрую state = 'active', чтобы не смешивать длительность запроса с возрастом транзакции.

SELECT pid,
       usename,
       application_name,
       clock_timestamp() - query_start AS query_age,
       left(query, 120) AS query_text
FROM pg_stat_activity
WHERE state = 'active'
  AND pid <> pg_backend_pid()
  AND clock_timestamp() - query_start > interval '5 minutes'
ORDER BY query_age DESC;
Дашборд с now() - query_start может показывать отрицательные или устаревшие длительности, если сам мониторинговый сеанс держит открытую транзакцию.
Функция идёт четыре минуты, а разница между двумя now() — ноль: чем на самом деле измерять время в PostgreSQL — схема
Схема к статье. Открыть схему в полном размере

Шаблон замера, который я ставлю клиентам

Для первого разбора мне достаточно двух меток типа timestamptz и сообщений RAISE. t_start хранит начало всего запуска, t_mark — начало текущего этапа. extract(epoch from interval) в PostgreSQL 18 возвращает numeric, поэтому результат можно умножить на 1000 и округлить без приведения к double precision. Метки я обновляю после сообщения об окончившемся шаге, чтобы следующий интервал не включал работу предыдущего.

CREATE OR REPLACE FUNCTION etl.rebuild_marts(p_day date)
RETURNS void
LANGUAGE plpgsql
AS $$
DECLARE
    t_start timestamptz := clock_timestamp();
    t_mark  timestamptz := t_start;
BEGIN
    PERFORM etl.load_raw(p_day);
    RAISE NOTICE 'load_raw       : % ms',
        round(extract(epoch FROM clock_timestamp() - t_mark) * 1000);
    t_mark := clock_timestamp();

    PERFORM etl.build_dim(p_day);
    RAISE NOTICE 'build_dim      : % ms',
        round(extract(epoch FROM clock_timestamp() - t_mark) * 1000);
    t_mark := clock_timestamp();

    PERFORM etl.build_fact(p_day);
    RAISE NOTICE 'build_fact     : % ms',
        round(extract(epoch FROM clock_timestamp() - t_mark) * 1000);

    RAISE LOG 'rebuild_marts(%): total % ms', p_day,
        round(extract(epoch FROM clock_timestamp() - t_start) * 1000);
END;
$$;

Уровень NOTICE по умолчанию отправляется клиенту, потому что client_min_messages по умолчанию равен NOTICE. Попадёт ли сообщение в серверный журнал, определяет другой параметр — log_min_messages; его значение по умолчанию WARNING не включает NOTICE. Уровень LOG ранжируется для серверного журнала иначе и при стандартном log_min_messages = WARNING записывается, но слово «гарантированно» здесь лишнее: администратор может изменить порог и направление логирования. Поэтому перед ночным прогоном я проверяю SHOW client_min_messages, SHOW log_min_messages и куда настроен log_destination.

Подробные NOTICE удобны при ручном тесте, а одну итоговую строку я оставляю уровнем LOG. Сообщения RAISE не откатываются вместе с транзакцией, тогда как INSERT в обычную таблицу журнала откатывается. Это важнее красивого дашборда: при ошибке в середине функции именно серверный журнал сохраняет последний завершённый этап и контекст исключения.

Для истории успешных прогонов можно завести таблицу. В PostgreSQL 18 у generated column по умолчанию тип VIRTUAL, поэтому здесь я явно пишу STORED, как и в исходном замысле. Выражение использует только значения текущей строки и неизменяемые операции над интервалом, что соответствует ограничениям generated column.

CREATE TABLE etl.step_log (
    id          bigint GENERATED ALWAYS AS IDENTITY PRIMARY KEY,
    run_id      uuid        NOT NULL,
    step        text        NOT NULL,
    started_at  timestamptz NOT NULL,
    finished_at timestamptz NOT NULL,
    duration_ms numeric GENERATED ALWAYS AS
        (extract(epoch FROM finished_at - started_at) * 1000) STORED,
    clock_went_back boolean GENERATED ALWAYS AS
        (finished_at < started_at) STORED
);

started_at и finished_at надо передавать явно из clock_timestamp(). DEFAULT now() здесь вернёт начало транзакции и снова даст ноль. Отдельный вычисляемый флаг clock_went_back сохраняет редкий эпизод перевода системных часов назад для расследования; CHECK (finished_at >= started_at), напротив, отверг бы такую запись и скрыл контекст сбоя.

Для run_id в PostgreSQL 18 есть встроенная uuidv7(), создающая упорядочиваемый по времени UUID версии 7. В PostgreSQL 17 и более ранних ветках встроенной uuidv7() нет; для уникального идентификатора запуска можно использовать gen_random_uuid(), которая создаёт UUID версии 4. UUID помогает связать все этапы одного запуска, но не заменяет started_at: извлекать бизнес-время из идентификатора без необходимости я не советую.

-- PostgreSQL 18
SELECT uuidv7() AS run_id;

-- PostgreSQL 17 и ниже
SELECT gen_random_uuid() AS run_id;

Если журнал обязан переживать откат основной работы, отдельное соединение через dblink действительно создаёт отдельный серверный сеанс и отдельную транзакцию. Но это не бесплатная «автономная транзакция»: надо безопасно настроить подключение, права, тайм-ауты и поведение при недоступности самого сервера. Для большинства ночных функций RAISE LOG проще. dblink я оставляю для случаев, где структурированные записи о неуспешных запусках являются обязательным требованием.

Таблица журнала внутри той же транзакции не покажет шаги упавшего запуска: её INSERT откатятся. Для аварийного разбора оставляйте серверный LOG или осознанно выносите запись в другое соединение.
Цифры и версии: Шаблон замера, который я ставлю клиентам — схема
Цифры и версии: Шаблон замера, который я ставлю клиентам. Открыть схему в полном размере

Разбор: бухгалтерская фирма «Баланс-Сервис», 30 РМ

Условный клиент из практического разбора — бухгалтерская фирма «Баланс-Сервис», 30 РМ. Учёт ведётся в 1С, поверх него ночью собираются витрины для BI на отдельном сервере: 16 vCPU, 128 ГБ RAM, NVMe, Ubuntu 24.04 LTS и PostgreSQL 18 из репозитория PGDG. На момент разбора была установлена актуальная минорная версия 18.6, выпущенная 13 августа 2026 года. База витрин занимала 340 ГБ. Регламент запускался расширением pg_cron в 02:00: одна функция etl.rebuild_marts(current_date - 1), внутри двенадцать шагов.

Название фирмы условное, но техническую последовательность и цифры замера я сохраняю. В cron.job_run_details при включённом по умолчанию cron.log_run видны start_time, end_time, status и return_message. По этой внешней истории средний запуск занимал 4 минуты 12 секунд, а в первый рабочий день месяца доходил до 9 минут. Внутренний журнал при этом двенадцать раз подряд показывал 0 мс.

В коде бухгалтерской фирмы «Баланс-Сервис», 30 РМ, оказалось сразу два источника одной ошибки: now() присваивалась обеим меткам, а у finished_at ещё стоял DEFAULT now(). Даже после частичной правки DDL мог продолжить подставлять время начала транзакции. Я убрал дефолт, передал обе метки явно через clock_timestamp(), добавил итоговый RAISE LOG и промежуточные RAISE NOTICE. Сами расчёты на этом этапе не менял, чтобы получить честную базовую линию.

Следующий запуск разложился так: load_raw — 3,1 с, build_dim — 11,4 с, ещё девять шагов вместе — 9,8 с, build_fact_sales — 227,6 с. Сумма этих групп равна 251,9 с; округлённое общее время внешнего замера — 252 с. Один шаг занимал около 90,3 % общего времени. Теперь вместо общего ощущения «сервер медленный» появился конкретный оператор, который можно было исследовать.

Для build_fact_sales я временно включил auto_explain.log_nested_statements, потому что обычный EXPLAIN внешнего SELECT показывает план вызова функции, а не планы всех SQL-операторов внутри PL/pgSQL. В журнале обнаружился цикл FOR примерно на 41 000 строк. На каждой итерации выполнялся отдельный UPDATE таблицы фактов с поиском по полям doc_id и line_no без подходящего составного индекса. Среднее наблюдаемое время одного такого действия было около 5,5 мс; умножение на 41 000 даёт примерно 225,5 с, что согласуется с замером этапа 227,6 с с учётом работы цикла и прочих операций.

Цикл переписали в один множественный UPDATE ... FROM и добавили B-tree-индекс по (doc_id, line_no). После изменения build_fact_sales выполнялся 6,2 с вместо 227,6 с. Общее время регламента стало 30,4 с вместо 252 с; ускорение по общему времени — примерно в 8,3 раза. В тяжёлый день месяца запуск стал укладываться в 52 с вместо 9 минут. Конфигурацию памяти и сервер не меняли.

Этот разбор полезен не только красивым итогом. Ошибочные метки скрывали узкое место, а обсуждение команды уходило в shared_buffers и покупку RAM. После исправления часов стало видно, что железо большую часть ночи ждало последовательность коротких UPDATE. Замер не оптимизирует запрос сам, но без него команда выбирает объект оптимизации почти наугад.

Было: внутренний журнал          После исправления меток
load_raw         00:00:00        load_raw             3 100 ms
build_dim        00:00:00        build_dim            11 400 ms
build_fact_sales 00:00:00        build_fact_sales    227 600 ms
прочие 9 шагов   00:00:00        прочие 9 шагов        9 800 ms
итого            00:00:00        итог внешнего замера 252 000 ms

После оптимизации я оставил итоговый замер и таблицу этапов как регрессионный контроль. Для обычной ночи важнее не одно рекордное число, а распределение по многим запускам: медиана, верхние квантили, число обработанных документов и объём входных данных. Если завтра витрина вырастет, команда увидит изменение build_fact_sales отдельно от load_raw и не вернётся к гаданию по общей длительности.

До настройки shared_buffers и покупки памяти почините измерение. Честное распределение по этапам часто показывает один запрос, индекс или цикл, а не нехватку ресурсов всего сервера.

Когда ручной таймер не нужен: диагностика PostgreSQL 18

Ручные t_mark полезны, когда длинную функцию надо разложить по бизнес-этапам. Для отдельной SQL-команды я начинаю с \timing в psql. Эта метакоманда измеряет наблюдаемое клиентом время команды; в него попадает не только исполнение на сервере, но и обмен с клиентом. Поэтому число из psql и Execution Time из EXPLAIN (ANALYZE) отвечают на разные вопросы и не обязаны совпадать.

\timing on
SELECT etl.rebuild_marts(current_date - 1);
\timing off

Следующий уровень — EXPLAIN (ANALYZE). В PostgreSQL 18 сведения BUFFERS автоматически включаются при ANALYZE, поэтому писать BUFFERS отдельно больше не обязательно. В той же версии EXPLAIN ANALYZE сообщает число обращений к индексу на узлах индексного сканирования, а план с типом узла, отключённым enable-параметром, явно помечается Disabled: true. Помните: ANALYZE действительно выполняет оператор. Для INSERT, UPDATE, DELETE или MERGE я сначала оцениваю последствия и при безопасном тесте использую явную транзакцию с ROLLBACK. Такой откат не отменяет внешние побочные эффекты и не возвращает значения sequence, поэтому тест должен быть изолирован даже при наличии ROLLBACK.

BEGIN;
EXPLAIN (ANALYZE, WAL, SETTINGS)
UPDATE etl.fact_sales AS f
SET amount = s.amount
FROM etl.stage_sales AS s
WHERE f.doc_id = s.doc_id
  AND f.line_no = s.line_no;
ROLLBACK;

Для SQL внутри функций удобен поставляемый модуль auto_explain. Он не требует CREATE EXTENSION, но библиотеку надо загрузить в сеанс через LOAD, session_preload_libraries или shared_preload_libraries. Я не смешиваю это требование с pg_stat_statements: последний действительно обязан находиться в shared_preload_libraries, поскольку резервирует общую память. Для постоянной диагностики конфигурация может выглядеть так.

# postgresql.conf
shared_preload_libraries = 'pg_stat_statements,auto_explain'

auto_explain.log_min_duration = '500ms'
auto_explain.log_analyze = on
auto_explain.log_buffers = on
auto_explain.log_nested_statements = on
auto_explain.log_timing = off
auto_explain.sample_rate = 0.1

У auto_explain.log_min_duration единица по умолчанию — миллисекунды; -1 отключает логирование, 0 логирует все подходящие планы. sample_rate принимает долю от 0 до 1: значение 0.1 статистически выбирает десятую часть операторов в каждом сеансе, а не десятую часть сеансов. Для вложенных операторов одного верхнеуровневого запроса решение согласованное: будут разобраны все вложенные операторы этого запуска либо ни один.

Самая дорогая настройка здесь — auto_explain.log_analyze = on. Документация предупреждает, что сбор метрик узлов выполняется для всех операторов, даже если они не дойдут до порога log_min_duration. auto_explain.log_timing = off уменьшает накладные расходы, но тогда в узлах не будет точного времени: останутся фактические строки и циклы, а общую длительность операторов можно сопоставлять с записью журнала. На нагруженной OLTP-базе я включаю ANALYZE на ограниченное окно, подбираю sample_rate по трафику и после разбора возвращаю настройки.

pg_stat_statements решает другую задачу: агрегирует статистику одинаковых SQL-операторов. Модуль надо добавить в shared_preload_libraries, перезапустить сервер, а затем выполнить CREATE EXTENSION в нужной базе. compute_query_id по умолчанию имеет значение auto и автоматически включается при загрузке pg_stat_statements; явное on тоже допустимо. По умолчанию pg_stat_statements.track = top, поэтому операторы внутри функций не считаются отдельно. Значение all добавляет вложенные операторы.

# postgresql.conf; изменение shared_preload_libraries требует перезапуска
shared_preload_libraries = 'pg_stat_statements,auto_explain'
compute_query_id = auto
pg_stat_statements.track = all
CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

SELECT calls,
       round(total_exec_time::numeric, 1) AS total_ms,
       round(mean_exec_time::numeric, 2)  AS mean_ms,
       round(max_exec_time::numeric, 2)   AS max_ms,
       left(query, 120)                   AS query_text
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 20;

total_exec_time, mean_exec_time, min_exec_time, max_exec_time и stddev_exec_time измеряются в миллисекундах. В PostgreSQL 18 представление получило parallel_workers_to_launch, parallel_workers_launched и wal_buffers_full. Кроме того, CREATE TABLE AS и DECLARE получили query id и могут учитываться модулем. Эти новшества полезны, но для вложенных SQL решающим параметром остаётся track = all.

Наконец, pg_stat_user_functions помогает разложить время по функциям. track_functions принимает none, pl или all; значение по умолчанию none. pl отслеживает функции на процедурных языках, включая PL/pgSQL, а all добавляет SQL- и C-функции. Простые SQL-функции, встроенные оптимизатором в вызывающий запрос, не попадут в статистику независимо от настройки.

ALTER SYSTEM SET track_functions = 'pl';
SELECT pg_reload_conf();

SELECT schemaname,
       funcname,
       calls,
       round(total_time::numeric, 1) AS total_ms,
       round(self_time::numeric, 1)  AS self_ms,
       round((total_time / NULLIF(calls, 0))::numeric, 2) AS avg_ms
FROM pg_stat_user_functions
ORDER BY self_time DESC
LIMIT 20;

В pg_stat_user_functions total_time включает время самой функции и вызванных ею функций, self_time исключает дочерние вызовы; обе колонки измеряются в миллисекундах. Разница между ними быстро показывает, где искать продолжение цепочки. Статистика накопительная, поэтому перед контролируемым тестом надо зафиксировать исходные значения или осознанно сбросить нужные счётчики в согласованное окно — сброс на боевом сервере затронет наблюдаемость коллег.

auto_explain.log_analyze = on добавляет работу ко всем рассматриваемым операторам, а не только к тем, чей план попадёт в журнал. На OLTP включайте его ограниченно и измеряйте накладные расходы.

Где clock_timestamp() сама становится проблемой

Первое ограничение — категория волатильности. now() помечена STABLE: в пределах одного оператора она возвращает одинаковый результат, а выражение с такой функцией безопасно использовать как значение в условии индексного сканирования. clock_timestamp() помечена VOLATILE и может вычисляться для каждой строки, где требуется результат. Для отбора свежих записей я оставляю now(); для фиксации начала и конца этапа использую clock_timestamp(). Менять их местами ради абстрактной «точности» не стоит.

-- Подходящая семантика для одного порога на весь оператор
SELECT id, created_at
FROM app.events
WHERE created_at >= now() - interval '1 hour';

-- Фактические часы нужны в точках замера, а не в фильтре каждой строки
SELECT clock_timestamp() AS started_at;

Нюанс про индекс надо формулировать аккуратно. STABLE-функцию нельзя использовать в выражении самого индекса, которому нужна неизменность между операторами, но её результат может быть параметром Index Cond во время выполнения запроса. VOLATILE-выражение планировщик не может считать одним постоянным порогом на весь оператор. Потеря индексного условия зависит от конкретного выражения и плана, поэтому её надо подтверждать EXPLAIN, а не обещать для любого запроса.

Второе ограничение — DEFAULT. Для обычной created_at дефолт now() часто правильнее: все строки, созданные одной транзакцией, получают согласованную временную метку. clock_timestamp() в DEFAULT допустима синтаксически, но в INSERT ... SELECT может дать разные значения строкам одного логического события. В таблице производительных замеров это иногда именно то, что нужно; в журнале бизнес-операций чаще мешает.

Третье ограничение — clock_timestamp() читает системные часы, а это не монотонный секундомер. Коррекция часов операционной системой или особенности виртуализации способны сделать вторую метку меньше первой. PostgreSQL поставляет pg_test_timing именно для оценки накладных расходов чтения времени и проверки, не идёт ли системное время назад во время теста. Если отрицательная длительность важна для аудита, я сохраняю обе исходные метки и признак ошибки часов, а не только обрезанный ноль.

SELECT started_at,
       finished_at,
       clock_went_back,
       GREATEST(interval '0', finished_at - started_at) AS safe_duration
FROM etl.step_log;

Четвёртое ограничение — цена чтения часов. Официальная документация pg_test_timing предлагает ориентир для хорошей системы: более 90 % отдельных вызовов укладываются менее чем в одну микросекунду, а средняя стоимость цикла находится ниже 100 наносекунд. Это не обещание для любого ядра и гипервизора. Десяток меток вокруг этапов ETL обычно теряется в шуме, а вызов clock_timestamp() на каждой строке большой таблицы уже становится измеримой частью работы.

# По умолчанию тест длится 3 секунды; опция ниже задаёт это явно
pg_test_timing --duration=3

# Текущий источник времени в Linux, если такой sysfs-интерфейс доступен
cat /sys/devices/system/clocksource/clocksource0/current_clocksource

# Источники, доступные ядру
cat /sys/devices/system/clocksource/clocksource0/available_clocksource

Не надо автоматически объявлять tsc хорошим, а hpet или acpi_pm плохими. Документация PostgreSQL называет TSC предпочтительным на современных процессорах, когда он надёжен, но отдельно предупреждает: операционная система может выбрать более медленный источник ради стабильности, и менять её решение следует осторожно. HPET считается подходящей заменой, когда TSC ненадёжен; acpi_pm имеет более грубую верхнюю границу разрешения. Решение принимают по pg_test_timing, рекомендациям гипервизора и документации ОС.

Пятое ограничение — тип результата timeofday(). Эта историческая функция показывает фактическое время, как clock_timestamp(), но возвращает форматированную строку text. Для вычитания меток её пришлось бы разбирать или приводить, что создаёт зависимость от формата. clock_timestamp() сразу возвращает timestamp with time zone, поэтому в новом SQL причин брать timeofday() почти нет.

Не переносите clock_timestamp() в WHERE только ради слова «точнее». Для отбора строк обычно нужен единый порог на весь оператор, а не новое показание часов для каждой строки.

Точность замера: что именно входит в интервал

Даже правильная функция времени не отвечает автоматически на вопрос, который вы имели в виду. Интервал вокруг PERFORM включает исполнение вложенной функции и небольшую стоимость двух чтений часов, но не включает время ожидания команды в очереди до начала backend-процесса. \timing показывает клиентскую длительность, EXPLAIN — серверный план с собственной измерительной ценой, pg_stat_statements — накопленную серверную статистику нормализованного оператора. Я подписываю метрику так, чтобы из названия было ясно, где стоят границы.

Отдельная ловушка — асинхронная работа. Если SQL только ставит сообщение в очередь или инициирует внешнее действие, clock_timestamp() измерит время постановки, а не завершение задачи. То же касается COMMIT: функция, закончившая расчёт до фиксации транзакции, не измеряет последующую задержку синхронной записи WAL, если конечная метка поставлена раньше COMMIT. Для пользовательской задержки нужен замер на стороне клиента или планировщика от отправки команды до получения успешного ответа.

Следующая ловушка — блокировки. Четыре минуты внутри шага могут оказаться не вычислением, а ожиданием чужой транзакции. Ручной t_mark честно включит ожидание в этап, но не объяснит причину. В момент проблемы я смотрю wait_event_type и wait_event в pg_stat_activity, блокирующие PID через pg_blocking_pids(), а затем сопоставляю временной интервал с серверным журналом. Исключать ожидание из бизнес-длительности обычно не надо: пользователь всё равно ждал.

SELECT a.pid,
       a.wait_event_type,
       a.wait_event,
       pg_blocking_pids(a.pid) AS blocking_pids,
       clock_timestamp() - a.query_start AS query_age,
       left(a.query, 120) AS query_text
FROM pg_stat_activity AS a
WHERE a.state = 'active'
ORDER BY query_age DESC;

Ещё одна граница — округление. Я храню started_at и finished_at с полной доступной точностью timestamptz, а duration_ms вычисляю для отчёта. Если округлить каждую ступень до целых секунд и потом сложить, сумма разойдётся с общим интервалом. В кейсе выше исходные значения 3,1 + 11,4 + 9,8 + 227,6 дают 251,9 с, а внешний итог показан как 252 с. Это нормальное округление, не потерянные сто миллисекунд.

Для сравнения выпусков кода одного времени мало. Рядом с duration_ms я сохраняю число обработанных строк, объём входного набора, run_id, версию приложения и статус. Тогда рост с 30,4 до 52 секунд можно объяснить месячным объёмом, а не сразу считать регрессией. clock_timestamp() даёт честную ось времени; качество вывода зависит от контекста, который мы положили рядом.

Правильный clock_timestamp() измеряет только промежуток между двумя выбранными точками. Если точки поставлены не вокруг нужной работы, число будет точным, а вывод — неверным.
Порядок действий: Точность замера: что именно входит в интервал — схема
Порядок действий: Точность замера: что именно входит в интервал. Открыть схему в полном размере

Что делать сначала, а что отложить

Когда функция выполняется непредсказуемо, я начинаю с поиска now(), CURRENT_TIMESTAMP и DEFAULT-выражений именно в местах вычисления длительности. Заодно проверяю, нет ли процедуры с COMMIT внутри: транзакционные границы меняют now(), но не превращают её в секундомер. После этого добавляю t_start и t_mark, делаю один контролируемый прогон и получаю долю каждого этапа.

На самом тяжёлом этапе подключаю диагностику по масштабу задачи. Для одной команды хватает EXPLAIN (ANALYZE); для SQL внутри PL/pgSQL временно использую auto_explain.log_nested_statements; для накопленной картины — pg_stat_statements.track = all; для дерева вызовов функций — track_functions = pl и pg_stat_user_functions. Одновременно проверяю ожидания, потому что долгий этап может стоять на блокировке, а не читать данные.

Не начинаю с изменения shared_buffers, work_mem и числа параллельных работников, пока нет базовой линии. Конфигурационная правка без честного показателя «до» оставляет команду без способа отличить эффект от обычного разброса. Не оставляю auto_explain.log_analyze включённым бессрочно на загруженной базе без оценки цены. Не строю триггерный механизм журнала, если задачу надёжно закрывают RAISE LOG и штатная статистика.

С микросекундами тоже не спорю раньше времени. Когда этап занимает 227,6 с, полезно сначала найти цикл и индекс, а не выяснять стоимость одного clock_timestamp(). pg_test_timing нужен, если EXPLAIN ANALYZE заметно искажает короткие массовые операции или среда виртуализации вызывает подозрение. Защиту от перевода часов добавляю там, где отрицательный интервал ломает отчёт или SLA, но сохраняю признак события для диагностики.

Поведение now(), statement_timestamp() и clock_timestamp() в PostgreSQL 18 осталось прежним. Изменения восемнадцатой ветки относятся к диагностике: BUFFERS автоматически входит в EXPLAIN ANALYZE; появились число индексных обращений и явная отметка отключённого узла; pg_stat_all_tables получил total_vacuum_time, total_autovacuum_time, total_analyze_time и total_autoanalyze_time; pg_stat_io — read_bytes, write_bytes и extend_bytes; pg_stat_statements — счётчики параллельных работников и wal_buffers_full; для run_id появилась uuidv7().

PostgreSQL 18.6 — текущая минорная версия ветки 18 на дату проверки 8 сентября 2026 года; она выпущена 13 августа 2026 года. Ветка 14 на эту дату ещё поддерживается, её последняя минорная версия — 14.24, а финальный выпуск запланирован на 12 ноября 2026 года. Семантика функций времени применима и к 14-й ветке, но после окончания поддержки обновления ошибок и безопасности для неё прекратятся. Переезжать на 18 только ради clock_timestamp() не нужно; планировать переход с 14-й уже нужно.

Итоговый принцип я формулирую так: now() отвечает «когда началась текущая транзакция», statement_timestamp() — «когда сервер получил текущую команду», clock_timestamp() — «что показывают системные часы в этой точке». Для бизнес-целостности часто нужен первый ответ, для возраста команды — второй, для длительности этапа — две отметки третьего.

now() — согласованное время транзакции, clock_timestamp() — фактическое показание системных часов. Для длительности этапа нужны две метки clock_timestamp(), поставленные вокруг именно той работы, которую вы хотите измерить.

Частые вопросы

Почему разница между двумя now() внутри функции равна нулю?

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

Чем statement_timestamp() отличается от clock_timestamp()?

statement_timestamp() фиксирует начало текущего оператора — точнее, момент получения последнего сообщения-команды от клиента — и постоянна внутри него. clock_timestamp() показывает фактическое системное время при каждом вызове. Первая удобна как начало внешней команды, вторая — для меток отдельных этапов.

Можно ли ставить clock_timestamp() в DEFAULT колонки created_at?

Синтаксически можно, но для обычной бизнес-метки чаще нужен now(): все строки одной транзакции получат согласованное время. clock_timestamp() может дать разные метки строкам одного INSERT ... SELECT. В таблице измерений started_at и finished_at лучше передавать явно.

Как увидеть запросы внутри PL/pgSQL-функции?

Для планов используйте auto_explain.log_nested_statements = on. Для накопленной агрегированной статистики установите pg_stat_statements.track = all; значение top по умолчанию учитывает только верхнеуровневые операторы. Для времени функций включите track_functions = pl и смотрите pg_stat_user_functions.

Почему auto_explain.sample_rate = 0.1 не означает 10 % сеансов?

Документация определяет sample_rate как долю операторов в каждом сеансе. Для вложенных операторов одного верхнеуровневого запроса решение принимается совместно: логируются все вложенные операторы этого запуска или ни один.

Замер показал отрицательную длительность — это ошибка PostgreSQL?

Не обязательно. clock_timestamp() опирается на системные, а не монотонные часы; коррекция ОС или виртуализации может сдвинуть их назад. Сохраните обе метки и признак finished_at < started_at. Для отчёта можно применить GREATEST(interval '0', finished_at - started_at), но не теряйте факт сбоя часов.

Насколько дорог clock_timestamp()?

Это зависит от платформы и источника времени. pg_test_timing считает хорошим результатом более 90 % вызовов короче одной микросекунды и среднюю стоимость цикла ниже 100 наносекунд. Несколько меток вокруг ETL-этапов обычно дёшевы; вызов на каждой строке большого набора надо измерять.

Что изменилось в PostgreSQL 18 по этой теме?

Семантика now(), statement_timestamp() и clock_timestamp() не изменилась. Улучшилась диагностика: BUFFERS автоматически включается в EXPLAIN ANALYZE, показывается число индексных обращений и отключённые узлы, расширены pg_stat_io, pg_stat_all_tables и pg_stat_statements, добавлена uuidv7().

Нужно ли обновляться с PostgreSQL 14 ради правильного замера?

Нет, clock_timestamp() и описанная семантика доступны в старых поддерживаемых ветках. Но поддержка PostgreSQL 14 завершается 12 ноября 2026 года, поэтому обновление надо планировать ради исправлений ошибок и безопасности, а не ради самого таймера.

Столкнулись с похожей задачей? Обращайтесь — решим

Если у вас происходит что-то из описанного в этой статье — или любая другая проблема с ИТ-инфраструктурой, — обращайтесь в любое время. Мои специалисты и я лично разберём ситуацию, найдём настоящую причину и доведём до решения.

Возьмёмся и за разовую задачу, и за постоянное обслуживание. Первичная консультация — бесплатно и без обязательств.

📞 +7 903 729-62-41 💬 MAX: +7 903 729-62-41 ✈ Telegram @ITfresh_Boss

С уважением, Семёнов Евгений Сергеевич, директор «АйТи Фреш» — IT-аутсорсинг для компаний до 50 рабочих мест, 15+ лет практики

Источники

© ООО «АйТи-Фреш» · Москва · Все статьи