Interprétation du temps de démarrage et des différents plans pour les scans PostgreSQL

Nov 28 2020

En posant une question récente , certains composants mystérieux du temps de démarrage sont apparus dans ma sortie EXPLAIN ANALYZE. Je jouais plus loin et j'ai découvert que le temps de démarrage tombe à près de 0 si je supprime la WHEREclause regex .

J'ai exécuté le script bash suivant comme test:

for i in $(seq 1 10) do if (( $RANDOM % 2 == 0 ))
    then
        echo "Doing plain count"
        psql -e -c "EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2"
    else
        echo "Doing regex count"
        psql -e -c "EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2 WHERE page ~ 'foo'"
    fi
done

La première requête renvoie un nombre d'environ 30 millions et la seconde ne compte que 7 lignes. Ils fonctionnent sur une réplique en lecture PG 12.3 dans RDS avec une autre activité minimale. Les deux versions prennent à peu près le même temps, comme je m'y attendais. Voici une sortie filtrée avec grep:

Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.086..38622.215 rows=10114306 loops=3)
Doing regex count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3091955.34 rows=897 width=0) (actual time=16856.679..41398.062 rows=2 loops=3)
Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.162..39454.499 rows=10114306 loops=3)
Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.036..39213.171 rows=10114306 loops=3)
Doing regex count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3091955.34 rows=897 width=0) (actual time=12711.308..40015.734 rows=2 loops=3)
Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.244..39277.683 rows=10114306 loops=3)
Doing regex count
^CCancel request sent

Alors, quelques questions:

  1. Qu'est-ce qui entre dans ce composant de démarrage du «temps réel» dans l'analyse de regex, et pourquoi est-il tellement plus grand? (10-20s contre 0-1s)

  2. Bien que «coût» et «temps» ne soient pas des unités comparables, le planificateur semble penser que le coût de démarrage devrait être égal à 0 dans tous les cas - est-il dupe?

  3. Pourquoi les stratégies semblent-elles différentes? Les deux plans mentionnent Partial Aggregate, mais la requête regex indique que les lignes réelles sont 2, mais la version simple indique que les lignes réelles sont ~ 10 millions (je suppose que c'est une sorte de moyenne entre 2 travailleurs et 1 leader, totalisant ~ 30 millions). Si je devais l'implémenter moi-même, j'additionnerais probablement les résultats de plusieurs count(*)opérations, au lieu de fusionner des lignes et de compter - les plans indiquent-ils exactement comment cela se fait?

Donc, je ne cache rien, voici les versions complètes du plan de requête pour chacun:


EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2
                                                                       QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=3093171.59..3093171.60 rows=1 width=8) (actual time=39156.499..39156.499 rows=1 loops=1)
   ->  Gather  (cost=3093171.37..3093171.58 rows=2 width=8) (actual time=39156.356..39157.850 rows=3 loops=1)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial Aggregate  (cost=3092171.37..3092171.38 rows=1 width=8) (actual time=39154.405..39154.406 rows=1 loops=3)
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060587.90 rows=12633390 width=0) (actual time=0.033..38413.690 rows=10115030 loops=3)
 Planning Time: 7.968 ms
 Execution Time: 39157.942 ms
(8 rows)


EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2 WHERE page ~ 'foo'
                                                                   QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=3093173.83..3093173.84 rows=1 width=8) (actual time=39908.495..39908.495 rows=1 loops=1)
   ->  Gather  (cost=3093173.61..3093173.82 rows=2 width=8) (actual time=39908.408..39909.848 rows=3 loops=1)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial Aggregate  (cost=3092173.61..3092173.62 rows=1 width=8) (actual time=39906.317..39906.318 rows=1 loops=3)
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3092171.37 rows=897 width=0) (actual time=17250.058..39906.308 rows=2 loops=3)
                     Filter: (page ~ 'foo'::text)
                     Rows Removed by Filter: 10115028
 Planning Time: 0.803 ms
 Execution Time: 39909.921 ms
(10 rows)

Réponses

3 LaurenzAlbe Nov 28 2020 at 03:30
  1. Le secret est dans Rows Removed by Filter: 10115028:

    Il faut 17 secondes à l'analyse séquentielle pour trouver et renvoyer la première ligne de résultat.

  2. L'optimiseur n'a aucune idée du temps qu'il faut pour que la première ligne passe le filtre. Comme cela ne fait aucune différence pour la qualité du plan, il définit simplement le coût de démarrage à 0.

  3. Les deux plans fonctionnent de la même manière: chacun des trois processus scanne un tiers de la table et compte les lignes (celle Partial Aggregatequi renvoie 1 ligne). Dans le premier cas, 10 millions de lignes sont comptées par chaque travailleur.

    Ces trois nombres sont rassemblés et additionnés dans la Finalize Aggregatescène.