Real-time мониторинг тормозящих запросов PostgreSQL своими руками за полчаса
В моей практике не раз были ситуации, когда хотелось посмотреть, какие именно запросы долго тупили в базе в определённый (конкретный) момент времени. А может, запросы не тупили, но каких-то запросов было слишком много.
Ключевое слово — в конкретный момент времени. Например, база непонятно от чего напряглась на 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»
Нажимаем слева плюсик и выбираем Aggregation
Затем Edit. Откроется окошко, в котором надо выбрать параметры агрегации и отображения.
Rows — это поле, по которому будем агрегировать, т.е. сам sql-запрос. В моём случае оно после разбора джейсона попадает как _message.
Metrics — это агрегационные функции. Нам будут интересны суммарное время выполнения запроса (sum (_time_diff)), сколько раз выполнялся (sum (_count_diff)) и, например, максимальное среди средних времён, так сказать (max (_exec_mean_time))
В итоге имеем примерно такой результат, его можно получить для любого интервала времени:
Если заменить тип отображения с Data Table на Pie Chart, то можно строить интересные картинки:
Можно делать и другие вещи. Всё зависит от вашей фантазии и возможностей грейлога. Например, можно выбрать интервал «последние 5 минут» и нажать кнопку автообновления, чтобы медитировать на то, что происходит в реальном времени.
Что если нет грейлога?
Я описал простейший случай, как сделать мониторинг на коленке за полчаса, имея только грейлог, который уже и так есть в системе. Разумеется, можно это делать и по-другому. Использовать кибану, например. Или, возможно, стоит писать метрики в prometheus, и отображать в grafana. Да как угодно.
Если у вас совсем ничего такого нет, ну можно тогда выводить информацию не в лог, а писать куда-нибудь в базу данных, а потом селектами информацию агрегировать. И написать свой UI, куда это красиво выводить и т.д.
Вывод
В общем, ничего сложного тут нет. И не всегда надо ставить или покупать особый софт: можно напилить небольшой велосипедик, не особо напрягаясь.
А потом можно его и доработать: в pg_stat_statements много информации, которую можно получить — не только количество и время.
Исходный код (громко сказано) можно посмотреть здесь.
