Медленный SELECT при JOIN'е по ключу партиционирования

[JanMihail]

Описание проблемы

Есть 2 таблицы со следующей структурой:

CREATE TABLE public.valuation (
    id bigserial NOT NULL,
    cost numeric(20,6) NULL,
    discount numeric(20,6) NULL,
    cost_with_vat numeric(20,6) NULL,
    vat_sum numeric(20,6) NULL,
    vat_rate_code text NULL,
    currency_code text NOT NULL,
    CONSTRAINT valuation_pkey PRIMARY KEY (id)
);

CREATE TABLE public.orders (
    id uuid NOT NULL DEFAULT gen_random_uuid(),
    "number" text NOT NULL,
    paid_online_on_delivery_id int8 NULL,
    CONSTRAINT orders_pkey PRIMARY KEY (id)
);

CREATE UNIQUE INDEX udx_orders_number ON public.orders USING btree (number);

Связь

  valuation.id --> orders.paid_online_on_delivery_id (1 к 1)

Количественные показатели таблиц

SELECT
    COUNT(*),
    MIN(id),
    MAX(id)
FROM
    valuation;

count	min	max
919648130	2	3581811089

SELECT
    COUNT(*)
FROM
    orders;

count
84808668

Таблица valuation разбита на партиции по диапазонам. Ключ партиционирования - id. Всего 100 партиций.

SELECT 
    *
from
    pathman_partition_list
where
    parent = 'valuation'::regclass

Результат запроса: https://gist.github.com/JanMihail/fd45cfef5ac24fe960e91a92c648b266#file-partitions-csv

Выполняю такой запрос

EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1104290452'

Результат

number	id	cost
1104290452	3512174003	0.000000

Nested Loop  (cost=0.99..17.04 rows=1 width=14) (actual time=0.130..0.131 rows=1 loops=1)
  Buffers: shared read=9 written=1
  ->  Index Scan using udx_orders_number on orders o  (cost=0.57..8.59 rows=1 width=18) (actual time=0.059..0.060 rows=1 loops=1)
        Index Cond: (number = '1104290452'::text)
        Buffers: shared read=5
  ->  Custom Scan (RuntimeAppend)  (cost=0.43..8.44 rows=1 width=23) (actual time=0.049..0.049 rows=1 loops=1)
        Prune by: (o.paid_online_on_delivery_id = v.id)
        Buffers: shared read=4 written=1
        ->  Index Scan using valuation_3513_pkey on valuation_3513 v_1  (cost=0.42..8.44 rows=1 width=13) (actual time=0.048..0.048 rows=1 loops=1)
              Index Cond: (id = o.paid_online_on_delivery_id)
              Buffers: shared read=4 written=1
Planning time: 12748.652 ms
Execution time: 0.198 ms

Из результатов вижу, что на планирование запроса ушло целых 12 секунд 748 миллисекунд.

Теперь я пробую сделать то же самое, но указываю в запросе конкретную партицию valuation_3513 из предыдущего EXPLAIN и смотрю на результаты.

EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.cost
FROM
    orders o
JOIN partitions.valuation_3513 v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1104290452'

Результат

number	id	cost
1104290452	3512174003	0.000000

Nested Loop  (cost=0.99..17.03 rows=1 width=15) (actual time=0.034..0.035 rows=1 loops=1)
  Buffers: shared hit=9
  ->  Index Scan using udx_orders_number on orders o  (cost=0.57..8.59 rows=1 width=18) (actual time=0.022..0.023 rows=1 loops=1)
        Index Cond: (number = '1104290452'::text)
        Buffers: shared hit=5
  ->  Index Scan using valuation_3513_pkey on valuation_3513 v  (cost=0.42..8.44 rows=1 width=13) (actual time=0.010..0.010 rows=1 loops=1)
        Index Cond: (id = o.paid_online_on_delivery_id)
        Buffers: shared hit=4
Planning time: 0.351 ms
Execution time: 0.083 ms

Время планирования резко уменьшилось до 0.351 миллисекунд. Получается, что в первом запросе 12 секунд потратилось на поиск нужной партиции. Тогда я делаю следующий запрос.

EXPLAIN (ANALYZE, BUFFERS)
SELECT
    id,
    cost
FROM  
    valuation
where
    id = 3512174003

Результат

id	cost
3512174003	0.000000

Append  (cost=0.42..8.44 rows=1 width=12) (actual time=0.016..0.017 rows=1 loops=1)
  Buffers: shared hit=4
  ->  Index Scan using valuation_3513_pkey on valuation_3513  (cost=0.42..8.44 rows=1 width=13) (actual time=0.016..0.016 rows=1 loops=1)
        Index Cond: (id = '3512174003'::bigint)
        Buffers: shared hit=4
Planning time: 0.128 ms
Execution time: 0.029 ms

При таком запросе на выбор нужной партиции затрачено всего 0.128 миллисекунд. Почему при JOIN по id (ключ партиционирования) время планирования резко подскакивает до 12 секунд? Что можно сделать, чтобы время планирования стало приемлемым?

Что я пытался делать:

1. VACUUM ANALYZE всех партиций.
2. REINDEX всех партиций.
3. merge_range_partitions первых 80 партиций. По итогу оставалось 20 партиций. Результаты чуть лучше, но всё равно время планирования остаётся в пределах 4-7 секунд.
4. Увеличение параметра shared_buffers и перезапуск сервера Postgres.

Ничего из этого не дало мне нужного результата.
Прошу помогите мне решить проблему.

Environment

SELECT * FROM pg_extension

extname	extowner	extnamespace	extrelocatable	extversion	extconfig	extcondition
plpgsql	10	11	false	1.0
pg_repack	10	2200	false	1.4.4
pg_trgm	10	2200	true	1.3
pgcrypto	10	2200	true	1.3
uuid-ossp	10	2200	true	1.1
pg_pathman	2672077	2200	false	1.5	{47426753,47426764}	{,}

SELECT version()

version
PostgreSQL 10.6 (Ubuntu 10.6-1.pgdg16.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 5.4.0-6ubuntu1~16.04.10) 5.4.0 20160609, 64-bit

SELECT pgpro_version()
SQL Error [42883]: ERROR: function pgpro_version() does not exist

SELECT pgpro_edition()
SQL Error [42883]: ERROR: function pgpro_edition() does not exist

SELECT get_pathman_lib_version()
SQL Error [42883]: ERROR: function get_pathman_lib_version() does not exist

[zilder]

Почему при JOIN по id (ключ партиционирования) время планирования резко подскакивает до 12 секунд?

Потому что при join получается параметризированный запрос с условием типа id = $1, и на этапе планирования postgres не знает, каким будет значение параметра. pg_pathman при планировании может оптимизировать только условия вида КЛЮЧ ОПЕРАТОР КОНСТАНТА, например id = 123 или id between 100 and 200.

Что можно сделать, чтобы время планирования стало приемлемым?

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

[maksm90]

Почему при JOIN по id (ключ партиционирования) время планирования резко подскакивает до 12 секунд?

Потому что при join получается параметризированный запрос с условием типа id = $1, и на этапе планирования postgres не знает, каким будет значение параметра. pg_pathman при планировании может оптимизировать только условия вида КЛЮЧ ОПЕРАТОР КОНСТАНТА, например id = 123 или id between 100 and 200.

При планировании же выбирается RuntimeAppend, т.е. pruning осуществляется на этапе исполнения. Я думаю, что проблема внутри кастомной части планирования. Предлагаю собрать perf-профиль на explain'ах.

[JanMihail]

Прошло какое-то время и проблема сама собой устранилась. Сейчас результаты вот такие:

EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1105047037';

Nested Loop  (cost=0.99..17.04 rows=1 width=22) (actual time=3.041..3.043 rows=1 loops=1)
  Buffers: shared hit=3 read=6
  ->  Index Scan using udx_orders_number on orders o  (cost=0.57..8.59 rows=1 width=18) (actual time=0.748..0.750 rows=1 loops=1)
        Index Cond: (number = '1105047037'::text)
        Buffers: shared hit=3 read=2
  ->  Custom Scan (RuntimeAppend)  (cost=0.43..8.44 rows=1 width=12) (actual time=2.265..2.265 rows=1 loops=1)
        Prune by: (o.paid_online_on_delivery_id = v.id)
        Buffers: shared read=4
        ->  Index Scan using valuation_3582_pkey on valuation_3582 v_1  (cost=0.42..8.44 rows=1 width=12) (actual time=2.264..2.264 rows=1 loops=1)
              Index Cond: (id = o.paid_online_on_delivery_id)
              Buffers: shared read=4
Planning time: 4.340 ms
Execution time: 3.092 ms

Неоднократно пытался воспроизвести то же самое. Удалял полностью таблицы, создавал заново, партиционировал и заполнял данными. Проблема не воспроизвелась. Похоже, что это какой-то внешний фактор, например autovacuum. Но как это однозначно определить пока непонятно, т.к. воспроизвести повторно пока не удаётся.

[JanMihail]

Проблема снова появилась. Постарался максимум информации вытащить в моменте.

Проблемные запросы

Запрос № 1

orders=# EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1105047037';
                                                            QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.99..10.64 rows=1 width=22) (actual time=0.944..0.944 rows=0 loops=1)
   Buffers: shared hit=2 read=2
   ->  Index Scan using udx_orders_number on orders o  (cost=0.56..5.38 rows=1 width=18) (actual time=0.943..0.943 rows=0 loops=1)
         Index Cond: (number = '1105047037'::text)
         Buffers: shared hit=2 read=2
   ->  Custom Scan (RuntimeAppend)  (cost=0.43..5.24 rows=1 width=12) (never executed)
         Prune by: (o.paid_online_on_delivery_id = v.id)
 Planning time: 95693.529 ms
 Execution time: 1.420 ms
(9 строк)

Запрос № 2

orders=# EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1104047036';
                                                                     QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.99..10.64 rows=1 width=22) (actual time=2.251..2.252 rows=1 loops=1)
   Buffers: shared hit=2 read=8
   ->  Index Scan using udx_orders_number on orders o  (cost=0.56..5.38 rows=1 width=18) (actual time=1.140..1.141 rows=1 loops=1)
         Index Cond: (number = '1104047036'::text)
         Buffers: shared hit=2 read=3
   ->  Custom Scan (RuntimeAppend)  (cost=0.43..5.24 rows=1 width=12) (actual time=1.070..1.070 rows=1 loops=1)
         Prune by: (o.paid_online_on_delivery_id = v.id)
         Buffers: shared read=5
         ->  Index Scan using valuation_3762_pkey on valuation_3762 v_1  (cost=0.57..5.38 rows=1 width=12) (actual time=1.069..1.069 rows=1 loops=1)
               Index Cond: (id = o.paid_online_on_delivery_id)
               Buffers: shared read=5
 Planning time: 3834.163 ms
 Execution time: 2.333 ms
(13 строк)

Запрос № 3

orders=# EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1';
                                                                     QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.99..10.64 rows=1 width=22) (actual time=0.092..0.093 rows=1 loops=1)
   Buffers: shared hit=9
   ->  Index Scan using udx_orders_number on orders o  (cost=0.56..5.38 rows=1 width=18) (actual time=0.031..0.031 rows=1 loops=1)
         Index Cond: (number = '1'::text)
         Buffers: shared hit=5
   ->  Custom Scan (RuntimeAppend)  (cost=0.43..5.24 rows=1 width=12) (actual time=0.017..0.017 rows=1 loops=1)
         Prune by: (o.paid_online_on_delivery_id = v.id)
         Buffers: shared hit=4
         ->  Index Scan using valuation_3760_pkey on valuation_3760 v_1  (cost=0.42..5.24 rows=1 width=12) (actual time=0.016..0.016 rows=1 loops=1)
               Index Cond: (id = o.paid_online_on_delivery_id)
               Buffers: shared hit=4
 Planning time: 4337.439 ms
 Execution time: 0.204 ms
(13 строк)

Активные процессы

select * from pg_stat_activity where datname = 'orders' and state = 'active';

Срез № 1: https://gist.github.com/JanMihail/5d113b5b9f6d48b422658e3130b23a00#file-process-list-1-csv
Срез № 2: https://gist.github.com/JanMihail/5d113b5b9f6d48b422658e3130b23a00#file-process-list-2-csv

Блокировки

select l.database, d.datname, l.relation, c.relname,
l.locktype, 
l.virtualxid, l.virtualtransaction, l.transactionid,
l.pid, l.mode, l.granted,
c.relacl
from pg_locks as l
LEFT JOIN pg_database AS d ON l.database= d.oid
LEFT JOIN pg_class AS c ON l.relation = c.oid
where d.datname = 'orders'
order by c.relname

Срез № 1: https://gist.github.com/JanMihail/5d113b5b9f6d48b422658e3130b23a00#file-pg-locks-1-csv
Срез № 2: https://gist.github.com/JanMihail/5d113b5b9f6d48b422658e3130b23a00#file-pg-locks-2-csv
Срез № 3: https://gist.github.com/JanMihail/5d113b5b9f6d48b422658e3130b23a00#file-pg-locks-3-csv

[JanMihail]

После того как прошли все autovacuum'ы, время планирования стало приемлемым.

Запрос № 1

EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1105047037';

Nested Loop  (cost=0.99..10.64 rows=1 width=22) (actual time=0.737..0.737 rows=0 loops=1)
  Buffers: shared hit=2 read=2
  ->  Index Scan using udx_orders_number on orders o  (cost=0.56..5.38 rows=1 width=18) (actual time=0.735..0.735 rows=0 loops=1)
        Index Cond: (number = '1105047037'::text)
        Buffers: shared hit=2 read=2
  ->  Custom Scan (RuntimeAppend)  (cost=0.43..5.24 rows=1 width=12) (never executed)
        Prune by: (o.paid_online_on_delivery_id = v.id)
Planning time: 113.575 ms
Execution time: 0.876 ms

Запрос № 2

EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1104047036';

Nested Loop  (cost=0.99..10.64 rows=1 width=22) (actual time=3.743..3.746 rows=1 loops=1)
  Buffers: shared hit=2 read=8
  ->  Index Scan using udx_orders_number on orders o  (cost=0.56..5.38 rows=1 width=18) (actual time=1.152..1.154 rows=1 loops=1)
        Index Cond: (number = '1104047036'::text)
        Buffers: shared hit=2 read=3
  ->  Custom Scan (RuntimeAppend)  (cost=0.43..5.24 rows=1 width=12) (actual time=2.544..2.545 rows=1 loops=1)
        Prune by: (o.paid_online_on_delivery_id = v.id)
        Buffers: shared read=5
        ->  Index Scan using valuation_3762_pkey on valuation_3762 v_1  (cost=0.57..5.38 rows=1 width=12) (actual time=2.541..2.541 rows=1 loops=1)
              Index Cond: (id = o.paid_online_on_delivery_id)
              Buffers: shared read=5
Planning time: 6.817 ms
Execution time: 3.823 ms

Запрос № 3

EXPLAIN (ANALYZE, BUFFERS)
SELECT
    o.number,
    v.id,
    v.cost
FROM
    orders o
JOIN valuation v ON v.id = o.paid_online_on_delivery_id
WHERE
    o.number = '1';

Nested Loop  (cost=0.99..10.64 rows=1 width=22) (actual time=5.755..5.761 rows=1 loops=1)
  Buffers: shared hit=1 read=8
  ->  Index Scan using udx_orders_number on orders o  (cost=0.56..5.38 rows=1 width=18) (actual time=2.087..2.091 rows=1 loops=1)
        Index Cond: (number = '1'::text)
        Buffers: shared hit=1 read=4
  ->  Custom Scan (RuntimeAppend)  (cost=0.43..5.24 rows=1 width=12) (actual time=3.497..3.498 rows=1 loops=1)
        Prune by: (o.paid_online_on_delivery_id = v.id)
        Buffers: shared read=4
        ->  Index Scan using valuation_3760_pkey on valuation_3760 v_1  (cost=0.42..5.24 rows=1 width=12) (actual time=3.493..3.493 rows=1 loops=1)
              Index Cond: (id = o.paid_online_on_delivery_id)
              Buffers: shared read=4
Planning time: 10.663 ms
Execution time: 5.858 ms

Вывод

Нельзя запускать неблокирующий перенос данных (partition_table_concurrently) сразу на несколько больших таблиц, т.к. после этого Postgres начинает активно запускать процессы autovacuum всех партиций. Пока этот процесс не закончится, время планирования запроса сильно проседает. В моём случае это продолжалось больше 7-8 часов. Партиционировал я 4 больших таблицы (300-900 миллионов строк).

Как я в итоге поступил

1. Создал партиции без переноса данных

SELECT create_range_partitions('valuation',   'id', 1::bigint, 1000000::bigint, NULL, false);
SELECT create_range_partitions('client',      'id', 1::bigint, 1000000::bigint, NULL, false);
SELECT create_range_partitions('online_shop', 'id', 1::bigint, 1000000::bigint, NULL, false);
SELECT create_range_partitions('address',     'id', 1::bigint, 1000000::bigint, NULL, false);

2. Запустил перенос данных из одной таблицы в партиции

SELECT partition_table_concurrently('valuation', 10000);

3. Дождался завершения переноса

Периодически выполняю запрос, пока он не будет возвращать пустоту

SELECT * FROM pathman_concurrent_part_tasks;

4. Отключаю родительскую таблицу из планирования

SELECT set_enable_parent('valuation', FALSE);

5. Жду пока все процессы autovacuum завершатся на всех партициях и на родительской таблице

Важно!!! Обязательно нужно дождаться, завершения работы autovacuum на родительской таблице, т.к. из неё ушли все данные и количество мёртвых строк очень велико.

6. Повторяю шаги с 2 по 5 для остальных таблиц.

P.S. Если сервер достаточно мощный, то, возможно, у вас всё будет нормально и при переносе данных сразу из четырёх таблиц. Конкретно в моём случае способ описанный выше сработал отлично.

[maksm90]

@JanMihail тут надо отметить, что долгое время планирования происходит при первом запросе в новой сессии при большом кол-ве секций, что обусловлено прогревом локального кэша конфигурацией секционирования. Вы лучше приложите dump схемы ваших таблиц и секций, если это возможно, чтобы мы попатались воспроизвести ваш кейс.

[JanMihail]

@maksm90 Высылаю dump схемы таблиц orderschema.custom.zip

[maksm90]

@JanMihail спасибо. Ваш случай воспроизводится только в случает множества активных vacuum-процессов в базе?

Не могли бы вы собрать профиль ожиданий от pg_wait_sampling для процессa, у которого наблюдается такое долгое время планирования? Мы могли бы для вас пропатчить это расширение, чтобы не прописывать его в shared_preload_libraries.

[JanMihail]

@maksm90, воспроизводится даже когда нет активных vacuum-процессов. При большом количестве запросов база покрывается AccessShareLock блокировками. Возможно причина в этом.

Высылаю профиль ожиданий от pg_wait_sampling
pg_wait_sampling.zip

[maksm90]

@JanMihail спасибо за сэмплы. По ним видно, что у вас contention за мьютексы менеджера блокировок. Чтобы попытаться что-нибудь сделать, нам надо будет воспроизвести вашу нагрузку. Опишите конфигурацию вашей системы и примерную нагрузку на базу.

При большом количестве запросов база покрывается AccessShareLock блокировками. Возможно причина в этом.

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

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