Riesige Nichtübereinstimmung zwischen der gemeldeten Indexgröße und der Anzahl der Puffer im Ausführungsplan

10

Die Angelegenheit

Wir haben eine Anfrage wie

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';

Da es häufig zu einer Zeitüberschreitung (nach 10 Minuten) kommt, habe ich mich entschlossen, das Problem zu untersuchen.

Die EXPLAIN (ANALYZE, BUFFERS)Ausgabe sieht folgendermaßen aus:

 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

Der Engpassknoten ist offensichtlich der Index-Scan. Sehen wir uns also die Indexdefinition an:

CREATE INDEX reservation_r_article_id_idx1 
    ON reservation USING btree (r_article_id)
 WHERE (r_status <> ALL (ARRAY['FULFILLED', 'CLOSED', 'CANCELED']));

Größen und Zeilennummern

Die Größe (gemeldet durch \di+oder durch Besuchen der physischen Datei) beträgt 36 MB. Da die Reservierungen normalerweise nur eine relativ kurze Zeit in allen oben nicht aufgeführten Status verbringen, werden viele Aktualisierungen durchgeführt, sodass der Index ziemlich aufgebläht ist (hier werden etwa 24 MB verschwendet) - dennoch ist die Größe relativ klein.

Die reservationTabelle ist ungefähr 3,8 GB groß und enthält ungefähr 40 Millionen Zeilen. Die Anzahl der noch nicht geschlossenen Reservierungen beträgt ca. 170.000 (die genaue Anzahl ist im obigen Index-Scan-Knoten angegeben).

Nun die Überraschung: Der Index-Scan meldet das Abrufen einer großen Menge von Puffern (dh 8-KB-Seiten):

Buffers: shared hit=200193 read=48853 dirtied=450 written=8

Die aus Cache und Festplatte (oder dem Betriebssystem-Cache) gelesenen Zahlen summieren sich auf 1,9 GB!

Worst-Case-Szenario

Andererseits würde das Worst-Case-Szenario, wenn sich jedes Tupel auf einer anderen Seite der Tabelle befindet, den Besuch von (21644 + 151549) + 4608 Seiten ausmachen (Gesamtzahl der aus der Tabelle abgerufenen Zeilen plus der Indexseitenzahl aus der physischen Seite) Größe). Dies ist immer noch nur unter 180.000 - weit unter den beobachteten fast 250.000.

Interessant (und vielleicht wichtig) ist, dass die Lesegeschwindigkeit der Festplatte bei etwa 2,2 MB / s liegt, was ganz normal ist, denke ich.

Na und?

Hat jemand eine Idee, woher diese Diskrepanz kommen kann?

Hinweis: Um klar zu sein, wir haben Ideen, was wir hier verbessern / ändern können, aber ich würde wirklich gerne die Zahlen verstehen, die ich bekommen habe - darum geht es bei der Frage.

Update: Überprüfung der Auswirkungen von Caching oder Mikrovakuum

Basierend auf der Antwort von jjanes habe ich überprüft, was passiert, wenn ich genau dieselbe Abfrage sofort erneut ausführe. Die Anzahl der betroffenen Puffer ändert sich nicht wirklich. (Um dies zu tun, habe ich die Abfrage auf das Nötigste vereinfacht, das das Problem immer noch anzeigt.) Folgendes sehe ich vom ersten Lauf an:

 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

und nach dem zweiten:

 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
postgresql index postgresql-9.3 execution-plan dezso
quelle
1
Wahrscheinlich irrelevant, aber brauchen Sie die Verbindung zu article? Es scheint, als ob alle beteiligten Spalten aus der reservationTabelle stammen und (vorausgesetzt) ​​es gibt eine FK, das Ergebnis sollte das gleiche sein.
Ypercubeᵀᴹ
Das ist eine sehr gute Frage. Und Sie haben Recht, es wird nicht benötigt - dies ist eine Abfrage, die bei der Überwachung durch ein anderes Team verwendet wird. Zumindest, wenn man sich den Abfrageplan ansieht, ist alles andere nur eine Dekoration für diesen fiesen Index-Scan :)
dezso
1
Lassen Sie mich hinzufügen, dass das Entfernen des Joins keinen großen Unterschied macht - der überblähte Index-Scan bleibt dort.
Dekso
Toast Tischzugang? Obwohl ich bezweifle, dass eine der Spalten, die Sie dort zeigen, geröstet wird. Wenn Sie zu Testzwecken einen inaktiven Klon der Datenbank haben, können Sie ihn ausführen pg_stat_reset(), dann die Abfrage ausführen und dann nachsehen pg_statio_user_tables, wo die Blöcke zugeordnet sind.
Jjanes

Antworten:

4

Ich denke, dass der Schlüssel hier die vielen Updates und das Aufblähen des Index ist.

Der Index enthält Zeiger auf Zeilen in der Tabelle, die nicht mehr aktiv sind. Dies sind die alten Versionen aktualisierter Zeilen. Die alten Zeilenversionen werden eine Weile beibehalten, um Abfragen mit einem alten Schnappschuss zu beantworten, und dann eine Weile länger, da niemand die Aufgabe übernehmen möchte, sie häufiger als nötig zu entfernen.

Beim Scannen des Index müssen diese Zeilen besucht werden, und dann wird festgestellt, dass sie nicht mehr sichtbar sind. Daher werden sie ignoriert. Die explain (analyze,buffers)Anweisung berichtet nicht explizit über diese Aktivität, außer durch Zählen der Puffer, die bei der Überprüfung dieser Zeilen gelesen / getroffen wurden.

Es gibt einen "Mikrovakuum" -Code für btrees, sodass der Scan, wenn er wieder zum Index zurückkehrt, daran erinnert, dass der verfolgte Zeiger nicht mehr aktiv war, und ihn im Index als tot markiert. Auf diese Weise muss die nächste ähnliche Abfrage, die ausgeführt wird, nicht erneut verfolgt werden. Wenn Sie also genau dieselbe Abfrage erneut ausführen, werden Sie wahrscheinlich feststellen, dass die Pufferzugriffe näher an Ihren Vorhersagen liegen.

Sie können auch VACUUMdie Tabelle öfter verwenden, um die toten Tupel aus der Tabelle selbst zu entfernen, nicht nur aus dem Teilindex. Im Allgemeinen profitieren Tabellen mit einem Teilindex mit hohem Umsatz wahrscheinlich von einem aggressiveren Vakuum als dem Standardniveau.

jjanes
quelle
Bitte beachten Sie meine Bearbeitung - für mich sieht es nach Caching aus, nicht nach Mikrovakuum.
Dekso
Ihre neuen Zahlen unterscheiden sich stark von Ihren alten (ungefähr doppelt), daher ist es schwierig zu interpretieren, was sie bedeuten, ohne auch die neuen Zahlen für tatsächliche Zeilen und Zeilen zu sehen, die für den Index-Scan gefiltert wurden.
Jjanes
Fügte die vollständigen Pläne hinzu, wie sie heute aussehen. Die Anzahl der betroffenen Puffer ist seit Freitag stark gestiegen, ebenso wie die Anzahl der Zeilen.
Dekso
Haben Sie langlebige Transaktionen? In diesem Fall ist es möglich, dass der Index-Scan immer noch Zeilen aufspürt, die für ihn nicht sichtbar sind (was zu zusätzlichen Puffertreffern führt), diese jedoch noch nicht mikrovakuumieren kann, da sie möglicherweise für eine andere Person mit einem älteren Namen sichtbar sind Schnappschuss.
Jjanes
Ich habe keine - die typische Transaktion dauert weniger als eine Sekunde. Gelegentlich einige Sekunden, aber nicht länger.
Dekso