понедельник, 31 мая 2010 г.

Блеск и нищета PostgreSQL

Давно сталкиваюсь в продакшене с проблемой, что выборки с подзапросами выполняются неприлично долго. Причем в тестах воспроизвести такое поведение никак не удавалось. И вот наконец получилось!
Оказывается, проблема существует всегда, но становится заметной только на таблицах с миллионами записей - простейшая выборка "тормозит", если увеличиваются _значения_ используемых в выборке идентификаторов, потому в таблицах с десятками тысяч и менее записей баг просто незаметен.

Сначала приведу один из рабочих запросов, над которыми ломал голову:
SELECT d.id AS document_id,
 d.phone_number AS phone,
 r.name AS region,
 p.code AS point,
 p.trademark AS point_trademark,
 (case when p.is_priority then '1' else '' end) AS color_it,
 c.code AS center_code,
 a.value AS status,
 u2.name AS user_2,
 tp.name AS template,
 c.name AS center,
 (a.save_date at time zone interval '04:00')::date AS work_date,
 date_trunc('second',(a.save_date at time zone interval '04:00')::time) AS work_time 
 FROM offline.documents AS d
 JOIN auth.users AS u ON d.user_id = u.id
 JOIN auth.regions AS r ON u.region_id = r.id
 JOIN auth.points AS p ON u.point_id = p.id
 JOIN auth.centers AS c ON u.center_id = c.id
 JOIN offline.attributes AS a ON d.id = a.document_id
 AND a.is_last
 AND a.save_date BETWEEN (now()::timestamp - interval '2 week') AND (now()::timestamp + interval '1 day')
 AND a.document_id IN (
  SELECT document_id
  FROM offline.attributes
  WHERE user_id='1111'::int
 )
 JOIN auth.users u2 ON a.user_id=u2.id
 JOIN offline.document_templates tp ON d.document_template_id = tp.id
 JOIN offline.attributes a_s ON d.id = a_s.document_id
 AND a_s.is_last_status
 AND a_s.value='status1'
 WHERE 
 d.id in (
  SELECT document_id
  FROM offline.attributes
  WHERE user_id='1111'::int
 )
 ORDER BY p.is_priority DESC, a_s.save_date ASC
 OFFSET '0'::int
 LIMIT '50'::int;
Последовательное упрощение запроса показало, что проблема скрывается в совершенно элементарном запросе:
SELECT id FROM offline.documents where id in (select document_id from tmp);
Притом подзапрос возвращает менее сотни записей, а выборка из основной таблицы идет по PRIMARY KEY:
explain analyze select document_id from offline.attributes where user_id=3650;
"Index Scan using attributes_user_id_idx on attributes  (cost=0.00..1417.18 rows=546 width=4) (actual time=0.015..0.154 rows=79 loops=1)"
"  Index Cond: (user_id = 3650)"
"Total runtime: 0.195 ms"

create temp table tmp as select document_id from offline.attributes where user_id=3650;
select count(*) from tmp;
79

explain analyze SELECT id FROM offline.documents where id in (select document_id from tmp);
"Merge Join  (cost=100000046.39..100030925.47 rows=200 width=4) (actual time=797.686..888.461 rows=40 loops=1)"
"  Merge Cond: ("outer".id = "inner".document_id)"
"  ->  Index Scan using documents_pkey on documents  (cost=0.00..29407.21 rows=587549 width=4) (actual time=0.010..637.431 rows=587025 loops=1)"
"  ->  Sort  (cost=100000046.39..100000046.89 rows=200 width=4) (actual time=0.150..0.169 rows=40 loops=1)"
"        Sort Key: tmp.document_id"
"        ->  HashAggregate  (cost=100000036.75..100000038.75 rows=200 width=4) (actual time=0.092..0.097 rows=40 loops=1)"
"              ->  Seq Scan on tmp  (cost=100000000.00..100000031.40 rows=2140 width=4) (actual time=0.003..0.046 rows=79 loops=1)"
"Total runtime: 888.522 ms"


explain analyze SELECT d.id FROM offline.documents as d, tmp where d.id=tmp.document_id;
"Merge Join  (cost=100000149.78..100031057.96 rows=2140 width=4) (actual time=795.564..885.250 rows=79 loops=1)"
"  Merge Cond: ("outer".id = "inner".document_id)"
"  ->  Index Scan using documents_pkey on documents d  (cost=0.00..29407.21 rows=587549 width=4) (actual time=0.011..636.265 rows=587025 loops=1)"
"  ->  Sort  (cost=100000149.78..100000155.13 rows=2140 width=4) (actual time=0.098..0.127 rows=79 loops=1)"
"        Sort Key: tmp.document_id"
"        ->  Seq Scan on tmp  (cost=100000000.00..100000031.40 rows=2140 width=4) (actual time=0.003..0.043 rows=79 loops=1)"
"Total runtime: 885.329 ms"

explain analyze SELECT id FROM offline.documents where id in (826798,826798,832792,832792,836566,842270,842270,842144,
842144,842034,842037,842037,844288,844288,844658,844658,844640,853201,853201,853313,853549,853313,853549,855102,855102,
855102,855097,855097,855102,856702,856702,869625,869625,869861,869861,869860,869860,870458,870458,870463,870463,871536,
871536,872055,872055,872279,872279,872368,872368,873792,873789,873789,878005,878005,878022,878022,878022,878022,888492,
888492,890071,890071,890061,890061,891715,891677,891483,891715,891483,895619,895619,899233,899205,899160,899160,899205,
899233,899697,899697);
"Bitmap Heap Scan on documents  (cost=158.28..466.00 rows=79 width=4) (actual time=0.341..0.394 rows=40 loops=1)"
"  Recheck Cond: ((id = 826798) OR (id = 826798) ... OR (id = 899697) OR (id = 899697))"
"  ->  BitmapOr  (cost=158.28..158.28 rows=79 width=0) (actual time=0.330..0.330 rows=0 loops=1)"
"        ->  Bitmap Index Scan on documents_pkey  (cost=0.00..2.00 rows=1 width=0) (actual time=0.013..0.013 rows=1 loops=1)"
"              Index Cond: (id = 826798)"
"        ->  Bitmap Index Scan on documents_pkey  (cost=0.00..2.00 rows=1 width=0) (actual time=0.003..0.003 rows=1 loops=1)"
"              Index Cond: (id = 826798)"
...
"        ->  Bitmap Index Scan on documents_pkey  (cost=0.00..2.00 rows=1 width=0) (actual time=0.005..0.005 rows=1 loops=1)"
"              Index Cond: (id = 899697)"
"        ->  Bitmap Index Scan on documents_pkey  (cost=0.00..2.00 rows=1 width=0) (actual time=0.003..0.003 rows=1 loops=1)"
"              Index Cond: (id = 899697)"
"Total runtime: 0.617 ms"
Еще несколько экспериментов - и готов тестовый сценарий для воспроизведения проблемы:
drop table tmp_facts6;
create table tmp_facts6(id serial NOT NULL, CONSTRAINT tmp_facts6_pkey PRIMARY KEY (id)) WITHOUT OIDS;
insert into tmp_facts6 select id from generate_series(1,1000000) as id;

drop table tmp;
create table tmp as select (1000*random())::int as document_id from generate_series(1,100) as document_id;
explain analyze select id from tmp_facts6 where id in (select document_id from tmp);
"Merge Join  (cost=100000046.39..100021005.39 rows=200 width=4) (actual time=0.292..1.568 rows=96 loops=1)"
"  Merge Cond: ("outer".id = "inner".document_id)"
"  ->  Index Scan using tmp_facts6_pkey on tmp_facts6  (cost=0.00..18456.00 rows=1000000 width=4) (actual time=0.009..0.726 rows=994 loops=1)"
"  ->  Sort  (cost=100000046.39..100000046.89 rows=200 width=4) (actual time=0.252..0.290 rows=96 loops=1)"
"        Sort Key: tmp.document_id"
"        ->  HashAggregate  (cost=100000036.75..100000038.75 rows=200 width=4) (actual time=0.118..0.183 rows=96 loops=1)"
"              ->  Seq Scan on tmp  (cost=100000000.00..100000031.40 rows=2140 width=4) (actual time=0.002..0.057 rows=100 loops=1)"
"Total runtime: 1.645 ms"

drop table tmp;
create table tmp as select (100000*random())::int as document_id from generate_series(1,100) as document_id;
explain analyze select id from tmp_facts6 where id in (select document_id from tmp);
"Merge Join  (cost=100000046.39..100021005.39 rows=200 width=4) (actual time=1.759..115.736 rows=100 loops=1)"
"  Merge Cond: ("outer".id = "inner".document_id)"
"  ->  Index Scan using tmp_facts6_pkey on tmp_facts6  (cost=0.00..18456.00 rows=1000000 width=4) (actual time=0.010..71.777 rows=99397 loops=1)"
"  ->  Sort  (cost=100000046.39..100000046.89 rows=200 width=4) (actual time=0.268..0.313 rows=100 loops=1)"
"        Sort Key: tmp.document_id"
"        ->  HashAggregate  (cost=100000036.75..100000038.75 rows=200 width=4) (actual time=0.121..0.220 rows=100 loops=1)"
"              ->  Seq Scan on tmp  (cost=100000000.00..100000031.40 rows=2140 width=4) (actual time=0.003..0.057 rows=100 loops=1)"
"Total runtime: 115.824 ms"

drop table tmp;
create table tmp as select (1000000*random())::int as document_id from generate_series(1,100) as document_id;
explain analyze select id from tmp_facts6 where id in (select document_id from tmp);
"Merge Join  (cost=100000046.39..100021005.39 rows=200 width=4) (actual time=31.807..1148.310 rows=100 loops=1)"
"  Merge Cond: ("outer".id = "inner".document_id)"
"  ->  Index Scan using tmp_facts6_pkey on tmp_facts6  (cost=0.00..18456.00 rows=1000000 width=4) (actual time=0.011..713.344 rows=995715 loops=1)"
"  ->  Sort  (cost=100000046.39..100000046.89 rows=200 width=4) (actual time=0.263..0.305 rows=100 loops=1)"
"        Sort Key: tmp.document_id"
"        ->  HashAggregate  (cost=100000036.75..100000038.75 rows=200 width=4) (actual time=0.121..0.178 rows=100 loops=1)"
"              ->  Seq Scan on tmp  (cost=100000000.00..100000031.40 rows=2140 width=4) (actual time=0.004..0.062 rows=100 loops=1)"
"Total runtime: 1148.408 ms"
Как видим, скорость выборки падает при пропорционально _увеличению значений идентификаторов_, возвращаемых подзапросом! Грабли просто фееричные, пожалуй, разработчикам PostgreSQL пора давать Шнобелевскую премию.

Upd.Надо же, в форуме указал версию постгреса, а здесь забыл:
select version();
                                                    version                                                     
----------------------------------------------------------------------------------------------------------------
 PostgreSQL 8.1.15 on i486-pc-linux-gnu, compiled by GCC cc (GCC) 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)
(1 row)
В 8.4 этого бага нет, но версия 8.1 поддерживаемая, а в ней не поправили. Вечная память...

10 комментариев:

Oleg Bartunov комментирует...

вы какой версией постгреса пользуетесь и какие настройки в postgresql.conf ?

Вот у меня 8.4.4 и 9.0beta1 ведут нормально:

в subselect-e 1000 записей

postgres=# explain analyze select id from tmp_facts6 where id in (select document_id from tmp);
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=16.50..7194.99 rows=999 width=4) (actual time=4.425..24.664 rows=999 loops=1)
-> HashAggregate (cost=16.50..26.49 rows=999 width=4) (actual time=4.395..6.175 rows=999 loops=1)
-> Seq Scan on tmp (cost=0.00..14.00 rows=1000 width=4) (actual time=0.022..1.923 rows=1000 loops=1)
-> Index Scan using tmp_facts6_pkey on tmp_facts6 (cost=0.00..7.16 rows=1 width=4) (actual time=0.010..0.012 rows=1 loops=999)
Index Cond: (tmp_facts6.id = tmp.document_id)
Total runtime: 26.185 ms
(6 rows)

Time: 27.338 ms

Печников Алексей комментирует...

Oleg Bartunov, проверил этот тест - в последних версиях 8.4 все ок. В релизе debian lenny версия 8.3 вела себя на указанном рабочем запросе идентично (тестировал, оценивая полезность обновления), вероятно, в ранних сборках 8.3 та же проблема существовала.

Информацию о версии добавил в статью, это 8.1.15. В конфиге только лимиты памяти подняты.

Hubbitus комментирует...

Так а вы засабмитили разаработчикам багу в эту стареньку юверсию? Может и бэкпортнут фикс, если уж вы апгрейдится не хотите.

Впрочем смысла использовать Постгри ниже 8.4, когда уже 9 на носу особого наверное и нету, кроме истории?

Печников Алексей комментирует...

Странное заявление про "смысла использовать Постгри ниже 8.4" - большинство продакшен проектов работают как раз на 8.1 и ниже (да, многие проекты пользуются версиями из ветки 7.4 и это вполне всех устраивает). Ровно та же ситуация и с ораклом, к примеру.

Что касается реакции разработчиков, то выше можете видеть комментарий от Oleg Bartunov.

Hubbitus комментирует...

Так а что мешает обновиться? Вроде обещано прозрачное обновление без проблем. Разумеется попробовать стоит на копии...

А сообщение выше от Олега приблизительно то же - юзайте 8.4, там проблема не воспроизводится :)
Впрочем это не есть багрепорт в любом случае.

Печников Алексей комментирует...

Обновиться обычно мешает то, что в новой версии часть запросов безбожно тормозят и надо их переписывать, заново тюнить все параметры и т.п.
Цена обновления весьма ощутима, плюс всегда есть опасность огрести какие-то новые баги, в то время как предыдущая версия стабильно работает.

Hubbitus комментирует...

Ну давно известно что лучшее враг хорошего, и какие-то грабли всенепременно огребете, к гадалке не ходи.

Однако вроде тема началась с того что не все какраз работает :) Точнее не так как хотелось бы.

Печников Алексей комментирует...

Далеко не сразу можно распознать источник проблем, написать для него тесты и проверить их на разных версиях СУБД. Вот, к примеру, тесты проекта, о котором шла речь выше, в 8.2 массово не работали из-за сломанного приведения типов, в 8.3 здорово "тормозили", и только в 8.4 все работало не хуже, чем в 8.1. Когда набрались тесты, которые хуже работают в 8.1, чем в 8.4, появился резон для обновления.

aximmussent комментирует...

проблема скрывается в совершенно элементарном запросе:

SELECT id FROM offline.documents where id in (select document_id from tmp);


Что-то неясно, а вышеозначенный запрос чем не эквивалентен самому подзапросу? -

select document_id from tmp

Алексей Печников комментирует...

aximmussent, о том и речь, что запрос возвращает ровно то же, что и подзапрос, только на несколько порядков медленнее. Разумеется, такого быть не должно... о том и заметка.


(C) Alexey Pechnikov aka MBG, mobigroup.ru