Real-time мониторинг тормозящих запросов PostgreSQL своими руками за полчаса

Kate

Administrator
Команда форума
wkijzfn6sv5v4g4lcyaft3zzwsk.png
В моей практике не раз были ситуации, когда хотелось посмотреть, какие именно запросы долго тупили в базе в определённый (конкретный) момент времени. А может, запросы не тупили, но каких-то запросов было слишком много.


Ключевое слово — в конкретный момент времени. Например, база непонятно от чего напряглась на 5 минут, потом всё само рассосалось, и очень хочется знать, почему. Отчёты за сутки, присылаемые dba на основе pg_stats_statements, не всегда проясняют ситуацию. Другие графики и логи могут помочь. Но всё же хочется не гадать на кофейной гуще, а конкретно посмотреть, что такому-то запросу в такое-то время было плохо, или его было много.


Можно, конечно, подключить системы а ля okmeter, но okmeter стоит денег. Да ещё и отсылает запросы в чужое облако — что, понятно, не в каждой организации можно считать безопасным.


На удивление, сделать такой мониторинг самому занимает всего полчаса времени, буквально с помощью нескольких строк Go-кода и палок.

Как же это сделать?


Часто дёргаем pg_stat_statements​


Если кто вдруг не знает, в стандартной поставке Постгреса есть расширение для сбора статистики по запросам, называется pg_stat_statements. Чтобы его включить, нужно добавить в конфиг shared_preload_libraries='pg_stat_statements' и потом выполнить SQL-команду CREATE EXTENSION pg_stat_statements;. Это расширение собирает данные по запросам, собирая стату в оперативной памяти в сишной структуре. Практически без оверхеда. Посмотрите в мануале, какую информацию по запросам оно может выдать. Забирать стату просто — достаточно сделать запрос,


SELECT [что вас интересует] FROM pg_stat_statements;

и вы получите всю инфу по всем SQL-запросам.


Всё это здорово, но проблема заключается в том, что расширение копит информацию до тех пор, пока не сделаешь ему reset (pg_stat_statements_reset()). Причём этот ресет делается только из-под суперпользователя. Неудобно, и это получается какой-то глобальный стейт. Мало ли кто, когда и зачем это заресетит. Например, dba делает себе отчёт за сутки и отсылает по почте, чтобы понять, что в целом в системе можно подкрутить.


Поэтому мы пойдём другим путём. Чтобы понять, что происходит в каждый небольшой интервал времени, мы будем дёргать pg_stat_statements каждые несколько секунд и смотреть, что изменилось с прошлого вызова. Не буду приводить весь код, но суть примерно такая:


func (w Watcher) Watch() error {

previousStatStatements, err := w.getStatStatements()
if err != nil {
return err
}

// бесконечный цикл
for true {
time.Sleep(3 * time.Second)
currentStatStatements, err := w.getStatStatements()

if err != nil {
return err
}

// записываем изменения
w.logChanges(currentStatStatements, previousStatStatements)

previousStatStatements = currentStatStatements
}
return nil
}

В частности, будем смотреть на поле calls (количество вызовов запроса) и total_exec_time (суммарное время, потраченное на все вызовы запроса). Если для какого-то запроса calls увеличился с прошлого раза, значит, в этот интервал времени был этот запрос. А по разнице с предыдущими значениями calls и total_exec_time мы можем понять, сколько именно таких запросов было, и сколько времени это заняло. Заодно можно посчитать и среднее время запроса за наш небольшой интервал. Ну и куда-то надо это сохранить — давайте для начала просто выведем информацию в лог:


func (w Watcher) logChanges(currentStatStatements map[string]PgStatStatementsRow, previousStatStatements map[string]PgStatStatementsRow) {
currTime := time.Now()
for query, curr := range currentStatStatements {
if strings.Contains(query, "pg_stat_statements") {
continue
}
prev, exists := previousStatStatements[query]
if !exists || prev.Calls > curr.Calls {
prev = PgStatStatementsRow{Calls: 0, TotalTime: 0}
}

if curr.Calls == prev.Calls {
continue
}

timeDiff := curr.TotalTime - prev.TotalTime
countDiff := curr.Calls - prev.Calls
execMeanTime := timeDiff / float64(countDiff)

w.log.Info().
Bool("is_sql_stats", true).
Time("time", currTime).
Float64("time_diff", timeDiff).
Uint64("count_diff", countDiff).
Float64("exec_mean_time", execMeanTime).
Msg(query)
}
}

Записываем в лог и настраиваем отображение​


Остаётся эту информацию куда-то сохранить. Но вообще-то, если честно, мы всё уже сохранили. Практически в любой мало-мальски серьёзной системе есть какой-то сбор логов и удобное отображение. В проектах, над которыми мы работаем в Каруне, обычно stdout контейнера ловится агентом и отправляется в общее хранилище. Т.е. ничего дополнительно изобретать не надо. У нас, по сути, достаточно просто выплюнуть json с информацией, и результат можно смотреть в грейлоге с удобным ui и различными визуальными свистелками.


Просто смотреть на бесконечные логи — это, конечно, грустно. Нужно сделать dashboard.


Создать дашборд — дело пары минут. Покажу, как.


Жмём кнопку "Create New Dashboard"


udr-rdfrz9s7vens7eavrn7gl6e.png

Нажимаем слева плюсик и выбираем Aggregation


hej4zzqpto1ofqh0zwfnbz_5pzi.png

Затем Edit. Откроется окошко, в котором надо выбрать параметры агрегации и отображения.


Rows — это поле, по которому будем агрегировать, т.е. сам sql-запрос. В моём случае оно после разбора джейсона попадает как _message.


bmxia98ztqywmo72drxof9e-lk0.png

Metrics — это агрегационные функции. Нам будут интересны суммарное время выполнения запроса (sum(_time_diff)), сколько раз выполнялся (sum(_count_diff)) и, например, максимальное среди средних времён, так сказать (max(_exec_mean_time))


yi5f-vx2t7rokiadpxt1c4ykigc.png

В итоге имеем примерно такой результат, его можно получить для любого интервала времени:


9bra-fl84gzkvoijnudamspwrje.png

Если заменить тип отображения с Data Table на Pie Chart, то можно строить интересные картинки:


-a82aq5xdhvimc4a_ue74eyzsla.png

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


Что если нет грейлога?​


Я описал простейший случай, как сделать мониторинг на коленке за полчаса, имея только грейлог, который уже и так есть в системе. Разумеется, можно это делать и по-другому. Использовать кибану, например. Или, возможно, стоит писать метрики в prometheus, и отображать в grafana. Да как угодно.


Если у вас совсем ничего такого нет, ну можно тогда выводить информацию не в лог, а писать куда-нибудь в базу данных, а потом селектами информацию агрегировать. И написать свой UI, куда это красиво выводить и т.д.


Вывод​


В общем, ничего сложного тут нет. И не всегда надо ставить или покупать особый софт: можно напилить небольшой велосипедик, не особо напрягаясь.


А потом можно его и доработать: в pg_stat_statements много информации, которую можно получить — не только количество и время.


Исходный код (громко сказано) можно посмотреть здесь.

 
Сверху