Problem
Mamy zapytanie jak
SELECT COUNT(1)
FROM article
JOIN reservation ON a_id = r_article_id
WHERE r_last_modified < now() - '8 weeks'::interval
AND r_group_id = 1
AND r_status = 'OPEN';
Ponieważ często dochodzi do przekroczenia limitu czasu (po 10 minutach), postanowiłem zbadać problem.
Dane EXPLAIN (ANALYZE, BUFFERS)
wyjściowe wyglądają następująco:
Aggregate (cost=264775.48..264775.49 rows=1 width=0) (actual time=238960.290..238960.291 rows=1 loops=1)
Buffers: shared hit=200483 read=64361 dirtied=666 written=8, temp read=3631 written=3617
I/O Timings: read=169806.955 write=0.154
-> Hash Join (cost=52413.67..264647.65 rows=51130 width=0) (actual time=1845.483..238957.588 rows=21644 loops=1)
Hash Cond: (reservation.r_article_id = article.a_id)
Buffers: shared hit=200483 read=64361 dirtied=666 written=8, temp read=3631 written=3617
I/O Timings: read=169806.955 write=0.154
-> Index Scan using reservation_r_article_id_idx1 on reservation (cost=0.42..205458.72 rows=51130 width=4) (actual time=34.035..237000.197 rows=21644 loops=1)
Filter: ((r_group_id = 1) AND (r_status = 'OPEN') AND (r_last_modified < (now() - '56 days'::interval)))
Rows Removed by Filter: 151549
Buffers: shared hit=200193 read=48853 dirtied=450 written=8
I/O Timings: read=168614.105 write=0.154
-> Hash (cost=29662.22..29662.22 rows=1386722 width=4) (actual time=1749.392..1749.392 rows=1386814 loops=1)
Buckets: 32768 Batches: 8 Memory Usage: 6109kB
Buffers: shared hit=287 read=15508 dirtied=216, temp written=3551
I/O Timings: read=1192.850
-> Seq Scan on article (cost=0.00..29662.22 rows=1386722 width=4) (actual time=23.822..1439.310 rows=1386814 loops=1)
Buffers: shared hit=287 read=15508 dirtied=216
I/O Timings: read=1192.850
Total runtime: 238961.812 ms
Węzeł wąskiego gardła to oczywiście skanowanie indeksu. Zobaczmy więc definicję indeksu:
CREATE INDEX reservation_r_article_id_idx1
ON reservation USING btree (r_article_id)
WHERE (r_status <> ALL (ARRAY['FULFILLED', 'CLOSED', 'CANCELED']));
Rozmiary i numery wierszy
Jego rozmiar (zgłaszany przez \di+
lub przez fizyczny plik) wynosi 36 MB. Ponieważ rezerwacje zwykle spędzają stosunkowo krótko we wszystkich stanach niewymienionych powyżej, dzieje się dużo aktualizacji, więc indeks jest dość rozdęty (marnuje się tutaj około 24 MB) - wciąż rozmiar jest stosunkowo niewielki.
reservation
Tabela 3,8 GB, zawierające około 40 milionów wierszy. Liczba rezerwacji, które nie zostały jeszcze zamknięte, wynosi około 170 000 (dokładna liczba jest podana w węźle skanowania indeksu powyżej).
Teraz niespodzianka: skanowanie indeksu zgłasza pobranie ogromnej ilości buforów (czyli stron o wielkości 8 kb):
Buffers: shared hit=200193 read=48853 dirtied=450 written=8
Liczby odczytane z pamięci podręcznej i dysku (lub pamięci podręcznej systemu operacyjnego) sumują się do 1,9 GB!
Najgorszy scenariusz
Z drugiej strony najgorszy scenariusz, w którym każda krotka siedzi na innej stronie tabeli, odpowiada za odwiedzenie (21644 + 151549) + 4608 stron (suma wierszy pobranych z tabeli plus numer strony indeksu z fizycznego rozmiar). To wciąż tylko mniej niż 180 000 - znacznie poniżej obserwowanego prawie 250 000.
Interesujące (i może ważne) jest to, że prędkość odczytu dysku wynosi około 2,2 MB / s, co jest dość normalne, jak sądzę.
Więc co?
Czy ktoś ma pojęcie o tym, skąd ta rozbieżność może wynikać?
Uwaga: aby być jasnym, mamy pomysły, co poprawić / zmienić tutaj, ale naprawdę chciałbym zrozumieć liczby, które otrzymałem - o to właśnie chodzi.
Aktualizacja: sprawdzanie efektu buforowania lub mikropróżnienia
Na podstawie odpowiedzi jjanesa sprawdziłem, co się stanie, gdy ponownie uruchomię dokładnie to samo zapytanie. Liczba dotkniętych buforów tak naprawdę się nie zmienia. (Aby to zrobić, uprościłem zapytanie do absolutnego minimum, które wciąż pokazuje problem.) Oto, co widzę od pierwszego uruchomienia:
Aggregate (cost=240541.52..240541.53 rows=1 width=0) (actual time=97703.589..97703.590 rows=1 loops=1)
Buffers: shared hit=413981 read=46977 dirtied=56
I/O Timings: read=96807.444
-> Index Scan using reservation_r_article_id_idx1 on reservation (cost=0.42..240380.54 rows=64392 width=0) (actual time=13.757..97698.461 rows=19236 loops=1)
Filter: ((r_group_id = 1) AND (r_status = 'OPEN') AND (r_last_modified < (now() - '56 days'::interval)))
Rows Removed by Filter: 232481
Buffers: shared hit=413981 read=46977 dirtied=56
I/O Timings: read=96807.444
Total runtime: 97703.694 ms
a po drugim:
Aggregate (cost=240543.26..240543.27 rows=1 width=0) (actual time=388.123..388.124 rows=1 loops=1)
Buffers: shared hit=460990
-> Index Scan using reservation_r_article_id_idx1 on reservation (cost=0.42..240382.28 rows=64392 width=0) (actual time=0.032..385.900 rows=19236 loops=1)
Filter: ((r_group_id = 1) AND (r_status = 'OPEN') AND (r_last_modified < (now() - '56 days'::interval)))
Rows Removed by Filter: 232584
Buffers: shared hit=460990
Total runtime: 388.187 ms
pg_stat_reset()
na nim uruchomić , a następnie uruchomić zapytanie, a następnie pg_statio_user_tables
sprawdzić, gdzie przypisuje bloki.
article
? Wygląda na to, że wszystkie zaangażowane kolumny pochodzą zreservation
tabeli i (przy założeniu, że istnieje FK, wynik powinien być taki sam.