ВЫБРАТЬ ОБНОВЛЕНИЕ становится медленным со временем - PullRequest
Новая
       27

ВЫБРАТЬ ОБНОВЛЕНИЕ становится медленным со временем

1 голос
/ 15 апреля 2020

У нас есть таблица с записями 1B, и есть 4 процесса, которые работают над этим одновременно. Они запрашивают строки со своими идентификаторами сеансов по 1000 строк за раз, а затем обновляют таблицу после 10000 строк. Для запроса используется следующий запрос: 

EXPLAIN (ANALYZE,BUFFERS) WITH b AS 
(
   SELECT
      userid,
      address
   FROM
      UserEvents 
   WHERE
      deliveryId = 2108625 
      AND 
      (
         tsExpire > GetDate() 
         OR tsExpire IS NULL
      )
      AND sendTime <= GetDate() 
      AND session_id = 0 
      AND level IN 
      (
         'default'
      )
   ORDER BY
      sendTime FOR 
      UPDATE
         SKIP LOCKED LIMIT 1000 
)
UPDATE
   UserEvents e 
SET
   session_id = 1 
FROM
b
WHERE
   e.userid = b.userid RETURNING b.userid,
   b.address

Этот запрос обычно выполняется в течение 500 мс, когда все 4 процесса выполняются одновременно. Внезапно за последние несколько запусков он значительно замедлился со временем. Вот планы объяснения: 

"Update on UserEvents e  (cost=5753.03..8567.46 rows=1000 width=1962) (actual time=1373.284..1422.244 rows=1000 loops=1)"
"  Buffers: shared hit=1146920 read=59 dirtied=194"
"  I/O Timings: read=13.916"
"  CTE b"
"    ->  Limit  (cost=0.56..5752.46 rows=1000 width=82) (actual time=1373.094..1380.853 rows=1000 loops=1)"
"          Buffers: shared hit=1121721 read=27 dirtied=23"
"          I/O Timings: read=3.440"
"          ->  LockRows  (cost=0.56..179683.91 rows=31239 width=82) (actual time=1373.093..1380.775 rows=1000 loops=1)"
"                Buffers: shared hit=1121721 read=27 dirtied=23"
"                I/O Timings: read=3.440"
"                ->  Index Scan using UserEvents_nextpass2 on UserEvents  (cost=0.56..179371.52 rows=31239 width=82) (actual time=1366.046..1373.339 rows=4186 loops=1)"
"                      Index Cond: ((deliveryId = 2108625) AND (sendTime <= '2020-04-15 08:33:57.372282+00'::timestamp with time zone))"
"                      Filter: (((tsexpire > '2020-04-15 08:33:57.372282+00'::timestamp with time zone) OR (tsexpire IS NULL)) AND (session_id = 0) AND ((level)::text = 'default'::text))"
"                      Rows Removed by Filter: 29614"
"                      Buffers: shared hit=1113493 read=27"
"                      I/O Timings: read=3.440"
"  ->  Nested Loop  (cost=0.58..2815.00 rows=1000 width=1962) (actual time=1373.218..1389.995 rows=1000 loops=1)"
"        Buffers: shared hit=1126728 read=27 dirtied=23"
"        I/O Timings: read=3.440"
"        ->  CTE Scan on b  (cost=0.00..20.00 rows=1000 width=1692) (actual time=1373.106..1382.263 rows=1000 loops=1)"
"              Buffers: shared hit=1121721 read=27 dirtied=23"
"              I/O Timings: read=3.440"
"        ->  Index Scan using UserEvents_id on UserEvents e  (cost=0.58..2.79 rows=1 width=268) (actual time=0.007..0.007 rows=1 loops=1000)"
"              Index Cond: (userid = b.userid)"
"              Buffers: shared hit=5007"
"Planning Time: 0.331 ms"
"Execution Time: 1422.457 ms"

Удивительно, но сканирование индекса на UserEvents_nextpass2 значительно замедляется после вызова этого запроса несколько тысяч раз. Это частичный индекс для ненулевых sendTime значений. sendTime обновляется после того, как каждый процесс обновляет строки и удаляет их идентификаторы сеанса. Но это относится к последним событиям 1B, что может быть причиной такой медлительности? Буду признателен за любую помощь.

Объясните план относительно более быстрого запуска с 700 мс: 

"Update on UserEvents e  (cost=5707.45..8521.87 rows=1000 width=1962) (actual time=695.897..751.557 rows=1000 loops=1)"
"  Buffers: shared hit=605921 read=68 dirtied=64"
"  I/O Timings: read=27.139"
"  CTE b"
"    ->  Limit  (cost=0.56..5706.87 rows=1000 width=82) (actual time=695.616..707.835 rows=1000 loops=1)"
"          Buffers: shared hit=580158 read=33 dirtied=29"
"          I/O Timings: read=10.491"
"          ->  LockRows  (cost=0.56..179686.41 rows=31489 width=82) (actual time=695.615..707.770 rows=1000 loops=1)"
"                Buffers: shared hit=580158 read=33 dirtied=29"
"                I/O Timings: read=10.491"
"                ->  Index Scan using UserEvents_nextpass2 on UserEvents  (cost=0.56..179371.52 rows=31489 width=82) (actual time=691.529..704.076 rows=3000 loops=1)"
"                      Index Cond: ((deliveryId = 2108625) AND (sendTime <= '2020-04-15 07:42:42.856859+00'::timestamp with time zone))"
"                      Filter: (((tsexpire > '2020-04-15 07:42:42.856859+00'::timestamp with time zone) OR (tsexpire IS NULL)) AND (session_id = 0) AND ((level)::text = 'default'::text))"
"                      Rows Removed by Filter: 29722"
"                      Buffers: shared hit=573158 read=33"
"                      I/O Timings: read=10.491"
"  ->  Nested Loop  (cost=0.58..2815.00 rows=1000 width=1962) (actual time=695.658..716.356 rows=1000 loops=1)"
"        Buffers: shared hit=585165 read=33 dirtied=29"
"        I/O Timings: read=10.491"
"        ->  CTE Scan on b  (cost=0.00..20.00 rows=1000 width=1692) (actual time=695.628..709.116 rows=1000 loops=1)"
"              Buffers: shared hit=580158 read=33 dirtied=29"
"              I/O Timings: read=10.491"
"        ->  Index Scan using UserEvents_id on UserEvents e  (cost=0.58..2.79 rows=1 width=268) (actual time=0.007..0.007 rows=1 loops=1000)"
"              Index Cond: (userid = b.userid)"
"              Buffers: shared hit=5007"
"Planning Time: 0.584 ms"
"Execution Time: 751.713 ms"

Мой индекс в этой таблице: 

CREATE INDEX UserEvents_nextpass2 ON public.UserEvents USING btree (deliveryid ASC NULLS LAST, sendTime ASC NULLS LAST) WHERE sendTime IS NOT NULL;

Ответы [ 2 ]

0 голосов
/ 17 апреля 2020

Нет простого способа сократить количество страниц, к которым обращаются в строке, потому что все мои проиндексированные столбцы обновляются одновременно. Так как мой фильтр отбрасывал ~ 80% строк, я решил добавить свои строки фильтра в многостолбцовый индекс. Таким образом, мой индекс изменился с: 

CREATE INDEX UserEvents_nextpass2 
ON public.UserEvents USING btree (deliveryid ASC NULLS LAST, sendTime ASC NULLS LAST) 
WHERE sendTime IS NOT NULL;

на: 

CREATE INDEX UserEvents_nextpass2 
ON public.UserEvents USING btree (deliveryid ASC NULLS LAST, sendTime ASC NULLS LAST, tsexpired, session_id, level) 
WHERE sendTime IS NOT NULL;

Это уменьшило мои отфильтрованные-удаленные строки до 0, и я получил доступ только к тем строкам, которые мне действительно нужны. Размер моего буфера был уменьшен до <100 000 с 1 121 721. Время запроса уменьшилось до 1,5 мс с 1,5 с. </p>

Извлеченный урок: Always prefer a multi-column index over filtering

0 голосов
/ 15 апреля 2020 
Index Scan using UserEvents_nextpass2 on UserEvents  (cost=0.56..179371.52 rows=31239 width=82) (actual time=1366.046..1373.339 rows=4186 loops=1)"
      Buffers: shared hit=1113493 read=27"

Похоже, что в индексе "UserEvents_nextpass2" много устаревших данных. Посещение 266 страниц для каждого возвращенного ряда немного смешно. Есть ли у вас какие-либо давно открытые транзакции, которые блокируют VACUUM и btree-speci c microvacuum эффективно выполнять свою работу?

Посмотрите в pg_stat_activity. Кроме того, включен ли hotstandby_feedback? Вакуумный_дифер_cleanup_age не ноль?

...