PostgreSQL: запрос выполняется очень медленно при первом запуске, быстро при последующих запусках
У меня есть запрос, который выполняется особенно медленно при первом запуске с учетной записью конкретного клиента. Затем он работает значительно быстрее на всех последующих запусках. Эта проблема чрезвычайно выражена на вращающемся диске - это все еще проблема, хотя намного менее раздражающая, на SSD.
Это объяснение первого запуска запроса: http://explain.depesz.com/s/NdTV
Aggregate (cost=1056.860..1056.870 rows=1 width=0) (actual time=356.740..356.740 rows=1 loops=1)
Output: five_two(*)
Buffers: shared hit=331 read=508
-> Nested Loop (cost=935.080..1056.860 rows=1 width=0) (actual time=292.458..356.712 rows=71 loops=1)
Buffers: shared hit=331 read=508
-> Nested Loop (cost=935.080..1051.990 rows=1 width=4) (actual time=292.440..356.116 rows=71 loops=1)
Output: xray_oscar.zulu_lima
Buffers: shared hit=136 read=490
-> HashAggregate (cost=935.080..935.090 rows=1 width=4) (actual time=282.669..282.673 rows=8 loops=1)
Output: foxtrot_echo.quebec
Buffers: shared hit=80 read=458
-> Sort (cost=935.060..935.070 rows=1 width=8) (actual time=282.661..282.662 rows=8 loops=1)
Output: foxtrot_echo.quebec, foxtrot_echo.five_echo
Sort Key: foxtrot_echo.five_echo
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=80 read=458
-> Nested Loop (cost=0.000..935.050 rows=1 width=8) (actual time=110.522..282.639 rows=8 loops=1)
Output: foxtrot_echo.quebec, foxtrot_echo.five_echo
Buffers: shared hit=80 read=458
-> Seq Scan on charlie_hotel_yankee (cost=0.000..870.560 rows=6 width=4) (actual time=1.880..5.777 rows=35 loops=1)
Output: seven_charlie.quebec, seven_charlie.foxtrot_mike, seven_charlie."foxtrot_india", seven_charlie.yankee, seven_charlie.seven_papa, seven_charlie.romeo_hotel, seven_charlie.foxtrot_two, seven_charlie.golf, seven_charlie.kilo_seven, seven_charlie.four
Filter: ((NOT seven_charlie.golf) AND (seven_charlie.yankee = 14732))
Rows Removed by Filter: 38090
Buffers: shared hit=2 read=392
-> Index Scan using xray_bravo on delta_charlie (cost=0.000..10.740 rows=1 width=12) (actual time=7.908..7.908 rows=0 loops=35)
Output: foxtrot_echo.quebec, foxtrot_echo.uniform, foxtrot_echo.seven_papa, foxtrot_echo.romeo_hotel, foxtrot_echo.five_echo
Index Cond: (foxtrot_echo.uniform = seven_charlie.quebec)
Filter: ((foxtrot_echo.five_echo >= 'three'::date) AND (foxtrot_echo.five_echo <= 'november_foxtrot_golf'::date))
Rows Removed by Filter: 7
Buffers: shared hit=78 read=66
-> Index Scan using whiskey_papa on xray_india (cost=0.000..116.890 rows=1 width=8) (actual time=1.267..9.176 rows=9 loops=8)
Output: xray_oscar.quebec, xray_oscar.foxtrot_mike, xray_oscar.foxtrot_tango, xray_oscar.seven_papa, xray_oscar.romeo_hotel, xray_oscar.zulu_lima, xray_oscar.lima_five, xray_oscar.bravo, xray_oscar.mike, xray_oscar.papa_hotel, xray_oscar.papa_romeo, delta_lima (...)
Index Cond: (xray_oscar.lima_five = foxtrot_echo.quebec)
Filter: ((xray_oscar.charlie_hotel_foxtrot & 1) = 0)
Buffers: shared hit=56 read=32
-> Index Scan using kilo_whiskey on seven_echo (cost=0.000..4.860 rows=1 width=4) (actual time=0.007..0.007 rows=1 loops=71)
Output: lima_november.quebec, lima_november.seven_papa, lima_november.romeo_hotel, lima_november.victor, lima_november.november_foxtrot_victor, lima_november.romeo_charlie, lima_november.whiskey_lima, lima_november.hotel, lima_november.sierra, lima_november.alpha, lima_november.zulu_yankee (...)
Index Cond: (lima_november.quebec = xray_oscar.zulu_lima)
Filter: (lima_november.yankee = 14732)
Buffers: shared hit=195 read=18
А вот следующие быстрые прогоны: http://explain.depesz.com/s/K1J5
Aggregate (cost=1056.860..1056.870 rows=1 width=0) (actual time=5.783..5.783 rows=1 loops=1)
Output: five_two(*)
Buffers: shared hit=366 read=473
-> Nested Loop (cost=935.080..1056.860 rows=1 width=0) (actual time=5.516..5.770 rows=71 loops=1)
Buffers: shared hit=366 read=473
-> Nested Loop (cost=935.080..1051.990 rows=1 width=4) (actual time=5.505..5.622 rows=71 loops=1)
Output: xray_oscar.zulu_lima
Buffers: shared hit=156 read=470
-> HashAggregate (cost=935.080..935.090 rows=1 width=4) (actual time=5.496..5.496 rows=8 loops=1)
Output: foxtrot_echo.quebec
Buffers: shared hit=85 read=453
-> Sort (cost=935.060..935.070 rows=1 width=8) (actual time=5.490..5.491 rows=8 loops=1)
Output: foxtrot_echo.quebec, foxtrot_echo.five_echo
Sort Key: foxtrot_echo.five_echo
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=85 read=453
-> Nested Loop (cost=0.000..935.050 rows=1 width=8) (actual time=3.565..5.480 rows=8 loops=1)
Output: foxtrot_echo.quebec, foxtrot_echo.five_echo
Buffers: shared hit=85 read=453
-> Seq Scan on charlie_hotel_yankee (cost=0.000..870.560 rows=6 width=4) (actual time=1.865..5.170 rows=35 loops=1)
Output: seven_charlie.quebec, seven_charlie.foxtrot_mike, seven_charlie."foxtrot_india", seven_charlie.yankee, seven_charlie.seven_papa, seven_charlie.romeo_hotel, seven_charlie.foxtrot_two, seven_charlie.golf, seven_charlie.kilo_seven, seven_charlie.four
Filter: ((NOT seven_charlie.golf) AND (seven_charlie.yankee = 14732))
Rows Removed by Filter: 38090
Buffers: shared hit=1 read=393
-> Index Scan using xray_bravo on delta_charlie (cost=0.000..10.740 rows=1 width=12) (actual time=0.008..0.008 rows=0 loops=35)
Output: foxtrot_echo.quebec, foxtrot_echo.uniform, foxtrot_echo.seven_papa, foxtrot_echo.romeo_hotel, foxtrot_echo.five_echo
Index Cond: (foxtrot_echo.uniform = seven_charlie.quebec)
Filter: ((foxtrot_echo.five_echo >= 'three'::date) AND (foxtrot_echo.five_echo <= 'november_foxtrot_golf'::date))
Rows Removed by Filter: 7
Buffers: shared hit=84 read=60
-> Index Scan using whiskey_papa on xray_india (cost=0.000..116.890 rows=1 width=8) (actual time=0.004..0.014 rows=9 loops=8)
Output: xray_oscar.quebec, xray_oscar.foxtrot_mike, xray_oscar.foxtrot_tango, xray_oscar.seven_papa, xray_oscar.romeo_hotel, xray_oscar.zulu_lima, xray_oscar.lima_five, xray_oscar.bravo, xray_oscar.mike, xray_oscar.papa_hotel, xray_oscar.papa_romeo, delta_lima (...)
Index Cond: (xray_oscar.lima_five = foxtrot_echo.quebec)
Filter: ((xray_oscar.charlie_hotel_foxtrot & 1) = 0)
Buffers: shared hit=71 read=17
-> Index Scan using kilo_whiskey on seven_echo (cost=0.000..4.860 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=71)
Output: lima_november.quebec, lima_november.seven_papa, lima_november.romeo_hotel, lima_november.victor, lima_november.november_foxtrot_victor, lima_november.romeo_charlie, lima_november.whiskey_lima, lima_november.hotel, lima_november.sierra, lima_november.alpha, lima_november.zulu_yankee (...)
Index Cond: (lima_november.quebec = xray_oscar.zulu_lima)
Filter: (lima_november.yankee = 14732)
Buffers: shared hit=210 read=3
Я знаю, что Postgres всегда будет работать немного быстрее при последующих запросах по сравнению с первым, когда он его запускает, но я не думал, что это будет настолько существенной разницей. Использование других фильтров идентификаторов клиентов (lima_november.yankee в запросе) Я видел, как один запрос выполнялся быстро за 12 мс и медленно за 1873 мс. Так что это довольно глубокая разница.
Запрос выбирает счетчик из таблицы с примерно 2 миллионами строк на основе трех фильтров. Первый - это идентификатор клиента, который выполняется через объединение, то есть сканирование индекса в нижней части планов запросов. Второй запрос IN, который, кажется, что индекс сканирования whiskey_papa делается. Третье побитовое утверждение - (xray_oscar.charlie_hotel_foxtrot & 1) = 0,
Я не видел buffers вывод explain analyze раньше, так что не знаю, с чего начать читать. Кажется странным, что вложенный цикл в позиции 6 в медленном запросе имеет фактическое время, настолько отличное от строк, вложенных в него. Но я не знаю, как это улучшить (или если это даже главная проблема).
Эти тесты находятся на postgres 9.2.13 на OS X 10.11.1. Какие-нибудь советы?