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


Ключевое слово — в конкретный момент времени. Например, база непонятно от чего напряглась на 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 много информации, которую можно получить — не только количество и время.


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

Комментарии (8)


  1. ololx
    10.08.2021 18:19

    Спасибо за статью, как раз прикручиваю графики для postgres (не через Prometheus) в Graphana. Будет очень полезно.

    Сразу вопрос: если уже настроена трассировка через тот же Jaeger, то чем этот способ лучше? В Jaeger же можно видеть запросы и их время выполнения.


    1. varanio Автор
      10.08.2021 18:21

      Задачи можно решать разными способами. Jaeger вы прикрутили к приложению?


    1. varanio Автор
      10.08.2021 18:37

      Кстати, советую посмотреть на https://github.com/cybertec-postgresql/pgwatch2

      Там дофига дашбордов графаны с самыми разными метриками


      1. ololx
        10.08.2021 18:54

        Благодарю, гляну, пока подключил postgres как datasource и создавал свои графики на основании служебных таблиц.


      1. ololx
        10.08.2021 19:01

        Да, при помощи open tracing, настроил отправку данных трассировки на развернутый сервис Jaeger. А сам Jaeger подключил как datasource в Graphana; по мимо Jaeger просто собираем статы с prometheus и loki.

        Пока разбирался, сделал небольшой пет проект на эту тему для себя еще; если интересно, то он доступен тут - https://github.com/innopolis-university-java-team/spring-boot-metrics-instances


  1. Aytuar
    10.08.2021 20:28

    Графики конечно красивые. Но сколько это стоит по ресурсам на самом сервере БД, overhead какой?


    1. varanio Автор
      10.08.2021 20:44
      -1

      Оверхед около нуля. Само расширение посгреса хранит числа в сишной структуре, инкрементирует их, всё оч быстро.

      Еще запрос к нему раз в несколько секунд - около нуля времени занимает тоже

      Короче, в большинстве случаев можно пренебречь


  1. michailnikolaev
    12.08.2021 16:12
    +1

    Я использую вот такую кверю (она считает разницу прямо в запросе с 20-секундой паузой).

    Кроме того, она схлопывает запросы с различным количеством параметров вместе посредством регулярки.

    SELECT
       round(sum(total_time))                                          AS total,
       round(sum(calls))                                               AS calls,
       round(sum(total_time) / sum(calls))                             AS per_query,
       regexp_replace(query, '(\$[0-9]+\s*,?\s*)+', '$$ ', 'g') AS query_group
    FROM (WITH
        p AS (
          SELECT 20.0
      ),
        t AS (
          SELECT sum(calls) as calls, queryid, max(query) as query, sum(total_time) as total_time FROM pg_stat_statements      
          group by queryid
      ),
      s AS (
          SELECT * FROM pg_sleep((SELECT * FROM p limit 1) + (SELECT count(*) FROM t) * 0.0001)
      ),
        r AS (
          SELECT sum(calls) as calls, queryid, max(query) as query, sum(total_time) as total_time
          FROM s,
               pg_stat_statements
          group by queryid
      )
    SELECT coalesce(r.queryid, t.queryid)                             AS queryid,
           coalesce(r.query, t.query)                                 AS query,
           abs(coalesce(r.calls, 0) - coalesce(t.calls, 0))           AS calls,
           abs(coalesce(r.total_time, 0) - coalesce(t.total_time, 0)) AS total_time
    FROM t inner
           JOIN r ON (t.queryid = r.queryid)
    WHERE coalesce(r.calls, 0) - coalesce(t.calls, 0) != 0)  
             AS s
    GROUP BY regexp_replace(query, '(\$[0-9]+\s*,?\s*)+', '$$ ', 'g')
    ORDER BY sum(total_time) DESC