Grande disparité entre la taille d'index signalée et le nombre de tampons dans le plan d'exécution

Le problème

Nous avons une requête comme

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

Comme il se produit un délai d'attente (après 10 minutes) le plus souvent, j'ai décidé d'enquêter sur le problème.

La EXPLAIN (ANALYZE, BUFFERS)sortie ressemble à ceci:

 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

Le nœud goulot d'étranglement est évidemment l'analyse d'index. Voyons donc la définition de l'index:

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

Tailles et numéros de ligne

Sa taille (signalée par \di+ou en visitant le fichier physique) est de 36 Mo. Comme les réservations ne passent généralement qu'un temps relativement court dans tous les états non répertoriés ci-dessus, il y a beaucoup de mises à jour, donc l'index est assez gonflé (environ 24 Mo sont gaspillés ici) - mais la taille est relativement petite.

La reservationtable mesure environ 3,8 Go et contient environ 40 millions de lignes. Le nombre de réservations qui ne sont pas encore fermées est d'environ 170 000 (le nombre exact est indiqué dans le nœud d'analyse d'index ci-dessus).

Maintenant, la surprise: l'analyse de l'index signale extraire une énorme quantité de tampons (c'est-à-dire 8 pages de ko):

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

Les chiffres lus dans le cache et le disque (ou le cache du système d'exploitation) totalisent 1,9 Go!

Pire scénario

D'un autre côté, le pire des cas, lorsque chaque tuple se trouve sur une page différente de la table, représenterait la visite (21644 + 151549) + 4608 pages (nombre total de lignes extraites de la table plus le numéro de page d'index du physique Taille). Ce chiffre est encore inférieur à 180 000 - bien en deçà des près de 250 000 observés.

Intéressant (et peut-être important) est que la vitesse de lecture du disque est d'environ 2,2 Mo / s, ce qui est tout à fait normal, je suppose.

Et alors?

Quelqu'un a-t-il une idée de l'origine de cet écart?

Remarque: Pour être clair, nous avons des idées sur ce qu'il faut améliorer / changer ici, mais j'aimerais vraiment comprendre les chiffres que j'ai obtenus - c'est de cela qu'il s'agit.

Mise à jour: vérification de l'effet de la mise en cache ou du microvacuum

Sur la base de la réponse de jjanes , j'ai vérifié ce qui se passe lorsque je réexécute exactement la même requête immédiatement. Le nombre de tampons affectés ne change pas vraiment. (Pour ce faire, j'ai simplifié la requête à son strict minimum qui montre toujours le problème.) Voici ce que je vois de la première exécution:

 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

et après le second:

 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

Je pense que la clé ici est le lot de mises à jour et le ballonnement sur l'index.

L'index contient des pointeurs vers des lignes de la table qui ne sont plus «actives». Ce sont les anciennes versions des lignes mises à jour. Les anciennes versions de ligne sont conservées pendant un certain temps, pour satisfaire les requêtes avec un ancien instantané, puis conservées plus longtemps car personne ne veut faire le travail de les supprimer plus souvent que nécessaire.

Lors de la numérisation de l'index, il doit aller visiter ces lignes, puis remarque qu'elles ne sont plus visibles, donc les ignore. L' explain (analyze,buffers)instruction ne rend pas compte de cette activité de manière explicite, sauf par le comptage des tampons lus / atteints lors du processus d'inspection de ces lignes.

Il existe un code "microvacuum" pour btrees, de telle sorte que lorsque l'analyse revient à nouveau à l'index, il se souvient que le pointeur qu'il a poursuivi n'était plus actif et le marque comme mort dans l'index. De cette façon, la prochaine requête similaire qui est exécutée n'a pas besoin de la poursuivre à nouveau. Donc, si vous exécutez à nouveau la même requête exacte, vous verrez probablement les accès au tampon se rapprocher de ce que vous aviez prévu.

Vous pouvez également VACUUMla table plus souvent, qui nettoiera les tuples morts de la table elle-même, pas seulement de l'index partiel. En général, les tables avec un indice partiel de rotation élevé bénéficieront probablement d'un vide plus agressif que le niveau par défaut.