Правильно [c]читаем параллельные планы PostgreSQL

    Исторически, модель работы сервера PostgreSQL выглядит как множество независимых процессов с частично разделяемой памятью. Каждый из них обслуживает только одно клиентское подключение и один запрос в любой момент времени — и никакой многопоточности.

    Поэтому внутри каждого отдельного процесса нет никаких традиционных «странных» проблем с параллельным выполнением кода, блокировками, race condition,… А разработка самой СУБД приятна и проста.

    Но эта же простота накладывает существенное ограничение. Раз внутри процесса всего один рабочий поток, то и использовать он может не более одного ядра CPU для выполнения запроса — а, значит, скорость работы сервера впрямую зависит от частоты и архитектуры отдельного ядра.

    В наш век закончившейся «гонки мегагерцев» и победивших многоядерных и многопроцессорных систем такое поведение является непозволительной роскошью и расточительностью. Поэтому, начиная с версии PostgreSQL 9.6, при отработке запроса часть операций может выполняться несколькими процессами одновременно.


    Со схемами работы некоторых параллельных узлов можно ознакомиться в статье «Parallelism in PostgreSQL» by Ibrar Ahmed, откуда взято и это изображение.
    Правда, читать планы в этом случае становится… нетривиально.

    Вкратце хронология внедрения параллельного исполнения операций плана выглядит так:


    Поэтому, если вы пользуетесь одной из последних версий PostgreSQL, шансы увидеть в плане Parallel ... весьма велики. А с ним приходят и…

    Странности со временем


    Возьмем план из PostgreSQL 9.6:


    [посмотреть на explain.tensor.ru]

    Только один Parallel Seq Scan выполнялся 153.621ms внутри поддерева, а Gather вместе со всеми подузлами — всего 104.867ms.

    Как так? Суммарно времени «наверху» стало — меньше?..

    Взглянем чуть подробнее на Gather-узел:

    Gather (actual time=0.969..104.867 rows=333333 loops=1)
      Workers Planned: 2
      Workers Launched: 2
      Buffers: shared hit=4425

    Workers Launched: 2 говорит нам о том, что дополнительно к основному процессу ниже по дереву были задействованы еще 2 дополнительных — итого 3. Поэтому все, что происходило внутри Gather-поддерева является суммарным творчеством всех 3 процессов сразу.

    Теперь посмотрим, что там в Parallel Seq Scan:

    Parallel Seq Scan on tst (actual time=0.024..51.207 rows=111111 loops=3)
      Filter: ((i % 3) = 0)
      Rows Removed by Filter: 222222
      Buffers: shared hit=4425

    Ага! loops=3 — это сводная информация по всем 3 процессам. И, в среднем, каждый такой цикл занял по 51.207ms. То есть суммарно для отработки этого узла серверу понадобилось 51.207 x 3 = 153.621 миллисекунды процессорного времени. То есть если мы хотим понять «чем был занят сервер» — именно это число и поможет нам понять.
    Замечу, что для понимания «реального» времени выполнения надо суммарное время разделить на количество worker'ов — то есть [actual time] x [loops] / [Workers Launched].

    В нашем примере каждый worker выполнил лишь один цикл по узлу, поэтому 153.621 / 3 = 51.207. И да, теперь уже нет ничего странного, что единственный Gather в головном процессе выполнился за «как бы меньшее время».

    Итого: смотрите на explain.tensor.ru суммарное (по всем процессам) время узла, чтобы понять, какой именно нагрузкой был занят ваш сервер, и оптимизации какой части запроса стоит уделять время.

    В этом смысле поведение того же explain.depesz.com, показывающего сразу «усредненное реальное» время, выглядит менее полезным для целей отладки:



    Не согласны? Добро пожаловать в комментарии!

    Gather Merge теряет все


    Теперь выполним тот же запрос на версии PostgreSQL 10:


    [посмотреть на explain.tensor.ru]

    Обратим внимание, что в плане у нас вместо узла Gather теперь оказался Gather Merge. Вот что говорит по этому поводу мануал:
    Когда над параллельной частью плана оказывается узел Gather Merge, а не Gather, это означает, что все процессы, выполняющие части параллельного плана, выдают кортежи в отсортированном порядке, и что ведущий процесс выполняет слияние с сохранением порядка. Узел же Gather, напротив, получает кортежи от подчинённых процессов в произвольном удобном ему порядке, нарушая порядок сортировки, который мог существовать.

    Но не все ладно в датском королевстве:

    Limit (actual time=110.740..113.138 rows=10000 loops=1)
      Buffers: shared hit=888 read=801, temp read=18 written=218
      I/O Timings: read=9.709
      ->  Gather Merge (actual time=110.739..117.654 rows=10000 loops=1)
            Workers Planned: 2
            Workers Launched: 2
            Buffers: shared hit=2943 read=1578, temp read=24 written=571
            I/O Timings: read=17.156

    При передаче атрибутов Buffers и I/O Timings вверх по дереву часть данных была безвременно утрачена. Мы можем оценить размер этой потери как раз примерно в 2/3, которые формируются вспомогательными процессами.

    Увы, в самом плане эту информацию взять неоткуда — отсюда и «минусы» на вышележащем узле. И если посмотреть дальнейшую эволюцию этого плана в PostgreSQL 12, то он принципиально не меняется, разве что добавляется немного статистики по каждому worker на Sort-узле:

    Limit (actual time=77.063..80.480 rows=10000 loops=1)
      Buffers: shared hit=1764, temp read=223 written=355
      ->  Gather Merge (actual time=77.060..81.892 rows=10000 loops=1)
            Workers Planned: 2
            Workers Launched: 2
            Buffers: shared hit=4519, temp read=575 written=856
            ->  Sort (actual time=72.630..73.252 rows=4278 loops=3)
                  Sort Key: i
                  Sort Method: external merge  Disk: 1832kB
                  Worker 0:  Sort Method: external merge  Disk: 1512kB
                  Worker 1:  Sort Method: external merge  Disk: 1248kB
                  Buffers: shared hit=4519, temp read=575 written=856
                  ->  Parallel Seq Scan on tst (actual time=0.014..44.970 rows=111111 loops=3)
                        Filter: ((i % 3) = 0)
                        Rows Removed by Filter: 222222
                        Buffers: shared hit=4425
    Planning Time: 0.142 ms
    Execution Time: 83.884 ms

    Итого: не доверяйте данным узла над Gather Merge.
    Тензор
    Разработчик системы СБИС

    Комментарии 0

    Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

    Самое читаемое