Казалось бы, случайная задержка в запросах - PullRequest
Новая
       10

Казалось бы, случайная задержка в запросах

0 голосов
/ 14 февраля 2020

Это продолжение до этой проблемы Я недавно отправил go.

У меня есть следующий код: 

SET work_mem = '16MB'; 
SELECT      s.start_date, s.end_date, s.resources, s.activity_index, r.resource_id, sa.usedresourceset 
FROM        rm_o_resource_usage_instance_splits_new s 
INNER JOIN  rm_o_resource_usage r ON s.usage_id = r.id 
INNER JOIN  scheduledactivities sa ON s.activity_index = sa.activity_index AND r.schedule_id = sa.solution_id and s.solution = sa.solution_id 
WHERE       r.schedule_id = 10 
ORDER BY    r.resource_id, s.start_date

Когда я запускаю EXPLAIN (ANALYZE, BUFFERS) Я получаю следующее: 

Sort  (cost=3724.02..3724.29 rows=105 width=89) (actual time=245.802..247.573 rows=22302 loops=1)
  Sort Key: r.resource_id, s.start_date
  Sort Method: quicksort  Memory: 6692kB
  Buffers: shared hit=198702 read=5993 written=612
  ->  Nested Loop  (cost=703.76..3720.50 rows=105 width=89) (actual time=1.898..164.741 rows=22302 loops=1)
        Buffers: shared hit=198702 read=5993 written=612
        ->  Hash Join  (cost=703.34..3558.54 rows=105 width=101) (actual time=1.815..11.259 rows=22302 loops=1)
              Hash Cond: (s.usage_id = r.id)
              Buffers: shared hit=3 read=397 written=2
              ->  Bitmap Heap Scan on rm_o_resource_usage_instance_splits_new s  (cost=690.61..3486.58 rows=22477 width=69) (actual time=1.782..5.820 rows=22302 loops=1)
                    Recheck Cond: (solution = 10)
                    Heap Blocks: exact=319
                    Buffers: shared hit=2 read=396 written=2
                    ->  Bitmap Index Scan on rm_o_resource_usage_instance_splits_new_solution_idx  (cost=0.00..685.00 rows=22477 width=0) (actual time=1.609..1.609 rows=22302 loops=1)
                          Index Cond: (solution = 10)
                          Buffers: shared hit=2 read=77
              ->  Hash  (cost=12.66..12.66 rows=5 width=48) (actual time=0.023..0.023 rows=1 loops=1)
                    Buckets: 1024  Batches: 1  Memory Usage: 9kB
                    Buffers: shared hit=1 read=1
                    ->  Bitmap Heap Scan on rm_o_resource_usage r  (cost=4.19..12.66 rows=5 width=48) (actual time=0.020..0.020 rows=1 loops=1)
                          Recheck Cond: (schedule_id = 10)
                          Heap Blocks: exact=1
                          Buffers: shared hit=1 read=1
                          ->  Bitmap Index Scan on rm_o_resource_usage_sched  (cost=0.00..4.19 rows=5 width=0) (actual time=0.017..0.017 rows=1 loops=1)
                                Index Cond: (schedule_id = 10)
                                Buffers: shared read=1
        ->  Index Scan using scheduledactivities_activity_index_idx on scheduledactivities sa  (cost=0.42..1.53 rows=1 width=16) (actual time=0.004..0.007 rows=1 loops=22302)
              Index Cond: (activity_index = s.activity_index)
              Filter: (solution_id = 10)
              Rows Removed by Filter: 5
              Buffers: shared hit=198699 read=5596 written=610
Planning time: 7.070 ms
Execution time: 248.691 ms

Каждый раз, когда я запускаю EXPLAIN, я получаю примерно одинаковые результаты. Время выполнения всегда между 170 мс и 250 мс, что для меня совершенно нормально. Тем не менее, когда этот запрос выполняется через проект C ++ (с использованием PQexec(conn, query), где conn - выделенное соединение, а query - вышеупомянутый запрос), время, которое требуется, может сильно различаться. В общем, запрос очень быстрый, и вы не замечаете задержки. Проблема в том, что иногда этот запрос может занять от 2 до 3 минут.

Если я открою pgadmin и посмотрю на «активность сервера» для базы данных, то там будет около 30 или около того соединений, в основном находящихся в «простое». Соединение вышеупомянутого запроса помечается как «активное» и будет оставаться «активным» в течение нескольких минут.

Я в недоумении, почему для выполнения одного и того же запроса случайным образом требуется несколько минут без каких-либо изменений данных в БД. Я попытался увеличить work_mem, что не имело никакого значения (да и не ожидал). Любая помощь или предложения будут с благодарностью.

Больше нет определенных тегов c, но в настоящее время я использую Postgres 10.11, но это также было проблемой в других версиях 10.x. Система представляет собой четырехъядерный процессор Xeon с частотой 3,4 ГГц, с SSD и 24 ГБ памяти.

В соответствии с предложением jjanes, я вставил auto_explain. В конечном итоге go этот вывод: 

duration: 128057.373 ms 
plan:
Query Text: SET work_mem = '32MB';SELECT        s.start_date, s.end_date, s.resources, s.activity_index, r.resource_id, sa.usedresourceset FROM     rm_o_resource_usage_instance_splits_new s INNER JOIN    rm_o_resource_usage r ON s.usage_id = r.id INNER JOIN  scheduledactivities sa ON s.activity_index = sa.activity_index AND r.schedule_id = sa.solution_id and s.solution = sa.solution_id WHERE      r.schedule_id = 12642 ORDER BY   r.resource_id, s.start_date
Sort  (cost=14.36..14.37 rows=1 width=98) (actual time=128042.083..128043.287 rows=21899 loops=1)
  Output: s.start_date, s.end_date, s.resources, s.activity_index, r.resource_id, sa.usedresourceset
  Sort Key: r.resource_id, s.start_date
  Sort Method: quicksort  Memory: 6585kB
  Buffers: shared hit=21198435 read=388 dirtied=119
  ->  Nested Loop  (cost=0.85..14.35 rows=1 width=98) (actual time=4.995..127958.935 rows=21899 loops=1)
        Output: s.start_date, s.end_date, s.resources, s.activity_index, r.resource_id, sa.usedresourceset
        Join Filter: (s.activity_index = sa.activity_index)
        Rows Removed by Join Filter: 705476285
        Buffers: shared hit=21198435 read=388 dirtied=119
        ->  Nested Loop  (cost=0.42..9.74 rows=1 width=110) (actual time=0.091..227.705 rows=21899 loops=1)
              Output: s.start_date, s.end_date, s.resources, s.activity_index, s.solution, r.resource_id, r.schedule_id
              Inner Unique: true
              Join Filter: (s.usage_id = r.id)
              Buffers: shared hit=22102 read=388 dirtied=119
              ->  Index Scan using rm_o_resource_usage_instance_splits_new_solution_idx on public.rm_o_resource_usage_instance_splits_new s  (cost=0.42..8.44 rows=1 width=69) (actual time=0.082..17.418 rows=21899 loops=1)
                    Output: s.start_time, s.end_time, s.resources, s.activity_index, s.usage_id, s.start_date, s.end_date, s.solution
                    Index Cond: (s.solution = 12642)
                    Buffers: shared hit=203 read=388 dirtied=119
              ->  Seq Scan on public.rm_o_resource_usage r  (cost=0.00..1.29 rows=1 width=57) (actual time=0.002..0.002 rows=1 loops=21899)
                    Output: r.id, r.schedule_id, r.resource_id
                    Filter: (r.schedule_id = 12642)
                    Rows Removed by Filter: 26
                    Buffers: shared hit=21899
        ->  Index Scan using scheduled_activities_idx on public.scheduledactivities sa  (cost=0.42..4.60 rows=1 width=16) (actual time=0.006..4.612 rows=32216 loops=21899)
              Output: sa.usedresourceset, sa.activity_index, sa.solution_id
              Index Cond: (sa.solution_id = 12642)
              Buffers: shared hit=21176333",,,,,,,,,""

РЕДАКТИРОВАТЬ: полные определения таблиц ниже: 

CREATE TABLE public.rm_o_resource_usage_instance_splits_new
(
    start_time integer NOT NULL,
    end_time integer NOT NULL,
    resources jsonb NOT NULL,
    activity_index integer NOT NULL,
    usage_id bigint NOT NULL,
    start_date text COLLATE pg_catalog."default" NOT NULL,
    end_date text COLLATE pg_catalog."default" NOT NULL,
    solution bigint NOT NULL,
    CONSTRAINT rm_o_resource_usage_instance_splits_new_pkey PRIMARY KEY (start_time, activity_index, usage_id),
    CONSTRAINT rm_o_resource_usage_instance_splits_new_solution_fkey FOREIGN KEY (solution)
        REFERENCES public.rm_o_schedule_stats (id) MATCH SIMPLE
        ON UPDATE CASCADE
        ON DELETE CASCADE,
    CONSTRAINT rm_o_resource_usage_instance_splits_new_usage_id_fkey FOREIGN KEY (usage_id)
        REFERENCES public.rm_o_resource_usage (id) MATCH SIMPLE
        ON UPDATE CASCADE
        ON DELETE CASCADE
)
WITH (
    OIDS = FALSE
)
TABLESPACE pg_default;

CREATE INDEX rm_o_resource_usage_instance_splits_new_activity_idx
    ON public.rm_o_resource_usage_instance_splits_new USING btree
    (activity_index ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX rm_o_resource_usage_instance_splits_new_solution_idx
    ON public.rm_o_resource_usage_instance_splits_new USING btree
    (solution ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX rm_o_resource_usage_instance_splits_new_usage_idx
    ON public.rm_o_resource_usage_instance_splits_new USING btree
    (usage_id ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE TABLE public.rm_o_resource_usage
(
    id bigint NOT NULL DEFAULT nextval('rm_o_resource_usage_id_seq'::regclass),
    schedule_id bigint NOT NULL,
    resource_id text COLLATE pg_catalog."default" NOT NULL,
    CONSTRAINT rm_o_resource_usage_pkey PRIMARY KEY (id),
    CONSTRAINT rm_o_resource_usage_schedule_id_fkey FOREIGN KEY (schedule_id)
        REFERENCES public.rm_o_schedule_stats (id) MATCH SIMPLE
        ON UPDATE CASCADE
        ON DELETE CASCADE
)
WITH (
    OIDS = FALSE
)
TABLESPACE pg_default;

CREATE INDEX rm_o_resource_usage_idx
    ON public.rm_o_resource_usage USING btree
    (id ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX rm_o_resource_usage_sched
    ON public.rm_o_resource_usage USING btree
    (schedule_id ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE TABLE public.scheduledactivities
(
    id bigint NOT NULL DEFAULT nextval('scheduledactivities_id_seq'::regclass),
    solution_id bigint NOT NULL,
    activity_id text COLLATE pg_catalog."default" NOT NULL,
    sequence_index integer,
    startminute integer,
    finishminute integer,
    issue text COLLATE pg_catalog."default",
    activity_index integer NOT NULL,
    is_objective boolean NOT NULL,
    usedresourceset integer DEFAULT '-1'::integer,
    start timestamp without time zone,
    finish timestamp without time zone,
    is_ore boolean,
    is_ignored boolean,
    CONSTRAINT scheduled_activities_pkey PRIMARY KEY (id),
    CONSTRAINT scheduledactivities_solution_id_fkey FOREIGN KEY (solution_id)
        REFERENCES public.rm_o_schedule_stats (id) MATCH SIMPLE
        ON UPDATE CASCADE
        ON DELETE CASCADE
)
WITH (
    OIDS = FALSE
)
TABLESPACE pg_default;

CREATE INDEX scheduled_activities_activity_id_idx
    ON public.scheduledactivities USING btree
    (activity_id COLLATE pg_catalog."default" ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX scheduled_activities_id_idx
    ON public.scheduledactivities USING btree
    (id ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX scheduled_activities_idx
    ON public.scheduledactivities USING btree
    (solution_id ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX scheduledactivities_activity_index_idx
    ON public.scheduledactivities USING btree
    (activity_index ASC NULLS LAST)
    TABLESPACE pg_default;

РЕДАКТИРОВАТЬ: Дополнительно вывод из auto_explain после добавления индекса on scheduledactivities (solution_id, activity_index)

  Output: s.start_date, s.end_date, s.resources, s.activity_index, r.resource_id, sa.usedresourceset
  Sort Key: r.resource_id, s.start_date
  Sort Method: quicksort  Memory: 6283kB
  Buffers: shared hit=20159117 read=375 dirtied=190
  ->  Nested Loop  (cost=0.85..10.76 rows=1 width=100) (actual time=5.518..122489.627 rows=20761 loops=1)
        Output: s.start_date, s.end_date, s.resources, s.activity_index, r.resource_id, sa.usedresourceset
        Join Filter: (s.activity_index = sa.activity_index)
        Rows Removed by Join Filter: 668815615
        Buffers: shared hit=20159117 read=375 dirtied=190
        ->  Nested Loop  (cost=0.42..5.80 rows=1 width=112) (actual time=0.057..217.563 rows=20761 loops=1)
              Output: s.start_date, s.end_date, s.resources, s.activity_index, s.solution, r.resource_id, r.schedule_id
              Inner Unique: true
              Join Filter: (s.usage_id = r.id)
              Buffers: shared hit=20947 read=375 dirtied=190
              ->  Index Scan using rm_o_resource_usage_instance_splits_new_solution_idx on public.rm_o_resource_usage_instance_splits_new s  (cost=0.42..4.44 rows=1 width=69) (actual time=0.049..17.622 rows=20761 loops=1)
                    Output: s.start_time, s.end_time, s.resources, s.activity_index, s.usage_id, s.start_date, s.end_date, s.solution
                    Index Cond: (s.solution = 12644)
                    Buffers: shared hit=186 read=375 dirtied=190
              ->  Seq Scan on public.rm_o_resource_usage r  (cost=0.00..1.35 rows=1 width=59) (actual time=0.002..0.002 rows=1 loops=20761)
                    Output: r.id, r.schedule_id, r.resource_id
                    Filter: (r.schedule_id = 12644)
                    Rows Removed by Filter: 22
                    Buffers: shared hit=20761
        ->  Index Scan using scheduled_activities_idx on public.scheduledactivities sa  (cost=0.42..4.94 rows=1 width=16) (actual time=0.007..4.654 rows=32216 loops=20761)
              Output: sa.usedresourceset, sa.activity_index, sa.solution_id
              Index Cond: (sa.solution_id = 12644)
              Buffers: shared hit=20138170",,,,,,,,,""

Самый простой способ воспроизвести проблему - добавить дополнительные значения в три таблицы. Я не удалил ничего, только сделал несколько тысяч вставок.

Ответы [ 2 ]

2 голосов
/ 15 февраля 2020 
->  Index Scan using .. s  (cost=0.42..8.44 rows=1 width=69) (actual time=0.082..17.418 rows=21899 loops=1)
                    Index Cond: (s.solution = 12642)

Планировщик считает, что найдет 1 строку, а вместо этого находит 21899. Эта ошибка может привести к плохим планам. И единственное условие равенства должно оцениваться довольно точно, поэтому я бы сказал, что статистика в вашей таблице далека. Может случиться так, что модуль запуска autova c настроен плохо, поэтому он не запускается достаточно часто, или может случиться так, что отдельные части ваших данных меняются очень быстро (вы просто вставили 21899 строк с s.solution = 12642 непосредственно перед выполнить запрос?) и поэтому статистика не может быть достаточно точной. 

  ->  Nested Loop ...
        Join Filter: (s.activity_index = sa.activity_index)
        Rows Removed by Join Filter: 705476285
        ->  ...
        ->  Index Scan using scheduled_activities_idx on public.scheduledactivities sa  (cost=0.42..4.60 rows=1 width=16) (actual time=0.006..4.612 rows=32216 loops=21899)
              Output: sa.usedresourceset, sa.activity_index, sa.solution_id
              Index Cond: (sa.solution_id = 12642)

Если вы не можете заставить его использовать соединение Ha sh, вы можете по крайней мере уменьшить вред Вложенный L oop путем построения индекса on scheduledactivities (solution_id, activity_index). Таким образом, критерий activity_index может быть частью условия индекса, а не фильтром соединения. Вероятно, вы могли бы затем отбросить индекс исключительно на solution_id, так как нет смысла поддерживать оба индекса.

0 голосов
/ 15 февраля 2020

Оператор SQL быстрого плана использует WHERE r.schedule_id = 10 и возвращает около 22000 строк (по оценкам, 105). Оператор SQL медленного плана использует WHERE r.schedule_id = 12642 и возвращает около 21000 строк (с оценкой только 1).

Медленный план использует вложенные циклы вместо соединений ha sh: возможно, из-за неправильной оценки для объединений: оценочные строки равны 1, но фактические строки равны 21899. Например, на этом шаге: 

Nested Loop  (cost=0.42..9.74 rows=1 width=110) (actual time=0.091..227.705 rows=21899 loops=1)

Если данные не изменяются, возможно, возникает проблема c statisti ( перекос данных) для некоторых столбцов.

...