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



Для нас хранимые процедуры удобны, в первую очередь тем, что не надо передавать гигабайты данных между базой и приложением. Удобно сделать несколько действий с разными таблицами в базе, а в приложение только отчитаться о том, что всё было выполнено успешно. Это действительно удобно, но в то же время это привносит и ряд проблем. Бизнес-логика частично прячется в базе, механизмы, которые используются для отладки и мониторинга на PHP/Go/Python/etc неприменимы на стороне СУБД. Конечно, есть свои замечательные средства, например, pg_stat_statements, но иногда они не могут в полной мере ответить на вопрос, какой именно кусок кода в нашей большой и сложной хранимке работает не так. Предложенное нами решение не претендует на звание «серебряной пули», но может помочь быстро определить среднее время выполнения кусков кода внутри хранимой процедуры, которая выполняется тысячи раз в секунду, и сделать это без создания лишней нагрузки. Интересно? Добро пожаловать!

В какой-то момент нам резко и внезапно понадобилось отследить время выполнения определенных фрагментов кода в большой хранимой процедуре. Процедура была сложная, ветвистая и очень часто используемая. Хотелось быстрого и изящного решения без длительного рефакторинга и лишней работы. Результат хотелось видеть как можно более наглядно, идеально было бы получить графики частоты вызовов во времени, объемы обрабатываемых данных, среднее и перцентили времени выполнения. И это всё в режиме реального времени. У нас в компании принято для отображения подобных данных использовать стек Brubeck/Graphite/Grafana и мы, в первую очередь, стали думать, как прокинуть наши метрики туда.

Решение «в лоб» — написать хранимую процедуру на plpython  —  отпало сразу, запускать python интерпретатор для того чтобы «плюнуть» строку по UDP — явный перебор. Следующий вариант был — кидать RAISE NOTICE, а потом долго и мучительно грепать логи. Кроме того, что это похоже на какое-то извращение, так ещё и пропадает вся «реалтаймовость». Также был вариант просто сохранять данные в unlogged таблицу и сбрасывать данные каким-нибудь скриптом в Brubeck. Но добавлять записи на загруженную систему, особенно если запрос только на выборку данных, тоже вариант не очень.

Решение пришло внезапно и неожиданно. Случайно вспомнили про механизм LISTEN/NOTIFY и поняли, что это оно! За полчаса мы написали демон на Питоне, который соединяется с PostgreSQL, слушает канал и отправляет в Brubeck, а внутри хранимой процедуры мы просто пишем в этот канал.

А теперь, собственно, пример использования:

x1 = clock_timestamp();
...your long running query...
x2 = clock_timestamp();

GET DIAGNOSTICS c = ROW_COUNT;

perform pg_notify('channel_test', format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.duration', extract(millisecond from (x2 - x1))::bigint::text, 'ms'));

perform pg_notify('channel_test', format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.count', c::text, 'c'));

Сохраняем время до запроса, сохраняем время после запроса, вычитаем одно из другого, переводим в миллисекунды и отправляем в канал. Наш демон на Питоне ловит это сообщение и отправляет дальше в Brubeck.

У этого решения есть ряд плюсов.:

• Решение было придумано, реализовано и выкачено в бой за 2 часа.
  
• Никаких перезапусков серверов не было.
  
• Из внешних зависимостей  —  лишь один демон на python.
  
• Минимальный overhead, на наших N тысяч транзакций в секунду мы его так и не увидели.
  

Также у данного решения есть ряд особенностей, о которых важно знать. Все эти особенности вытекают из устройства механизма LISTEN/NOTIFY в PostgreSQL:

• Данные, которые вы отправляете в канал, зависят от транзакции. Если вы отправили что-то в канал, и произошел откат транзакции, то в канал ничего не прийдёт.
  
• LISTEN/NOTIFY не работает на standby.
  
• Есть и другие особенности работы NOTIFY в PostgreSQL, например, то, что одинаковые данные будут доставлены только один раз. Со всеми особенностями лучше ознакомиться в документации по LISTEN/NOTIFY.
  

Всё это, конечно, мелочи, с которыми лично мы отлично уживаемся.

Но это еще не все!

За неделю до написания статьи было придумано и написано расширение на C для PostgreSQL – pg_metricus.

Данное расширение не использует LISTEN/NOTIFY и отправляет метрики в сокет агрегатора сразу в момент вызова. За счет чего данные стали независимы от состояния транзакции. Даже если произошел откат транзакции, все ваши данные успешно доехали до агрегатора.

Как его использовать? Да все просто!

Указываем в настройках postgresql.conf хост и порт нашего агрегатора:

pg_metricus.host = '10.4.5.177'
pg_metricus.port = 8224

Делаем

pg_reload_conf()

Собираем исходники:

make install

Устанавливаем расширение:

create schema metricus;
create extension pg_metricus schema metricus;

И все! Можно отправлять данные!

x1 = clock_timestamp();
...your long running query...
x2 = clock_timestamp();

GET DIAGNOSTICS c = ROW_COUNT;

perform metricus.send_metric(format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.duration', extract(millisecond from (x2 - x1))::bigint::text, 'ms'));

perform metricus.send_metric(format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.count', c::text, 'c'));

В заключении хочется отметить, что этот подход позволил решить все озвученные нами проблемы. Мы протестировали, выкатили в бой, и через 5 минут у нас уже были красивые графики в Grafana и первое представление о том, что, как часто и как долго выполняется в нашей исследуемой логике.


Картинка кликабельна

Спасибо за внимание! Ждем ваши вопросы и отзывы.

Проекты доступны по ссылкам ниже:

Github
> https://github.com/avito-tech/pg_metricus_python
> https://github.com/avito-tech/pg_metricus_c

PGXN
> https://pgxn.org/dist/pg_metricus