Ogromne niedopasowanie między zgłoszoną wielkością indeksu a liczbą buforów w planie wykonania

10

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.

reservationTabela 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
dezso
źródło
1
Prawdopodobnie nieistotne, ale czy potrzebujesz połączenia article? Wygląda na to, że wszystkie zaangażowane kolumny pochodzą z reservationtabeli i (przy założeniu, że istnieje FK, wynik powinien być taki sam.
ypercubeᵀᴹ
To bardzo dobre pytanie. I masz rację, nie jest to konieczne - jest to zapytanie używane w monitorowaniu przez inny zespół. Mimo to, przynajmniej patrząc na plan zapytań, wszystko inne to tylko dekoracja tego paskudnego skanu indeksu :)
dezso
1
Dodam, że usunięcie złączenia nie robi dużej różnicy - przesadzone skanowanie indeksu pozostaje tam.
dezso
Dostęp do stołu tostowego? Chociaż wątpię, by któraś z kolumn, które tam pokazałeś, byłaby opiekana. Jeśli masz bezczynny klon bazy danych do celów testowych, możesz pg_stat_reset()na nim uruchomić , a następnie uruchomić zapytanie, a następnie pg_statio_user_tablessprawdzić, gdzie przypisuje bloki.
jjanes

Odpowiedzi:

4

Myślę, że kluczem tutaj jest wiele aktualizacji i wzdęcia w indeksie.

Indeks zawiera wskaźniki do wierszy w tabeli, które nie są już „aktywne”. To są stare wersje zaktualizowanych wierszy. Stare wersje wierszy są przechowywane przez jakiś czas, aby zaspokoić zapytania ze starą migawką, a następnie są przechowywane przez jakiś czas, ponieważ nikt nie chce wykonywać pracy usuwania ich częściej niż to konieczne.

Podczas skanowania indeksu musi odwiedzić te wiersze, a następnie zauważa, że ​​nie są już widoczne, więc je ignoruje. explain (analyze,buffers)Oświadczenie nie zgłasza się na tej działalności wyraźnie, jak tylko poprzez liczenie buforów odczytu / trafienie w procesie sprawdzania tych wierszy.

Jest trochę kodu „mikropodciśnienia” dla drzewek, tak że kiedy skan powraca do indeksu, pamięta, że ​​wskaźnik, który ścigał, nie był już aktywny, i oznacza go jako martwy w indeksie. W ten sposób kolejne podobne zapytanie, które zostanie uruchomione, nie musi go ścigać ponownie. Więc jeśli ponownie uruchomisz dokładnie to samo zapytanie, prawdopodobnie zobaczysz, że dostęp do bufora spada bliżej tego, co przewidziałeś.

Możesz także VACUUMczęściej tabelę, która usunie martwe krotki z samej tabeli, a nie tylko z częściowego indeksu. Ogólnie rzecz biorąc, tabele z częściowym wskaźnikiem wysokiego obrotu prawdopodobnie skorzystają z bardziej agresywnej próżni niż poziom domyślny.

jjanes
źródło
Zobacz moją edycję - dla mnie wygląda to na buforowanie, a nie na mikropróżnienie.
dezso,
Twoje nowe liczby różnią się znacznie od starych (mniej więcej dwukrotnie), więc trudno jest zinterpretować ich znaczenie, nie widząc też nowych liczb dla rzeczywistych wierszy i rzędów filtrowanych dla skanowania indeksu.
jjanes
Dodano pełne plany, jak wyglądają dzisiaj. Liczba buforów, których dotyczy problem, znacznie wzrosła od piątku, podobnie jak liczba wierszy.
dezso,
Czy kręcisz się przy długich transakcjach? Jeśli tak, możliwe jest, że skanowanie indeksu nadal śledzi wiersze, które nie są dla niego widoczne (co powoduje dodatkowe trafienia w buforze), ale nie może ich jeszcze odciąć, ponieważ mogą być widoczne dla innej osoby ze starszym migawka.
jjanes
Nie mam - typowa transakcja zajmuje mniej niż sekundę. Czasami kilka sekund, ale nie dłużej.
dezso,