Interpretation der Startzeit und unterschiedlicher Pläne für Postgres-Seq-Scans

Nov 28 2020

Als ich kürzlich eine Frage stellte , tauchten in meiner EXPLAIN ANALYZE-Ausgabe einige mysteriöse Startzeitkomponenten auf. Ich habe weiter gespielt und festgestellt, dass die Startzeit auf nahe 0 sinkt, wenn ich die Regex- WHEREKlausel entferne .

Ich habe das folgende Bash-Skript als Test ausgeführt:

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

Die erste Abfrage gibt eine Anzahl von ~ 30 Millionen zurück, und die zweite zählt nur 7 Zeilen. Sie werden auf einem PG 12.3-Lesereplikat in RDS mit minimaler anderer Aktivität ausgeführt. Beide Versionen benötigen ungefähr die gleiche Zeit, wie ich es erwarten würde. Hier ist eine Ausgabe gefiltert mit 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

Also ein paar Fragen:

  1. Was steckt in dieser Startkomponente der "tatsächlichen Zeit" im Regex-Scan und warum ist sie so viel größer? (10-20s gegen 0-1s)

  2. Obwohl "Kosten" und "Zeit" keine vergleichbaren Einheiten sind, scheint der Planer der Meinung zu sein, dass die Startkosten in allen Fällen 0 sein sollten - wird es getäuscht?

  3. Warum scheinen die Strategien anders zu sein? Beide Pläne erwähnen Partial Aggregate, aber die Regex-Abfrage besagt, dass die tatsächlichen Zeilen sind 2, aber die einfache Version sagt, dass die tatsächlichen Zeilen ~ 10 Millionen sind (ich denke, dies ist eine Art Durchschnitt zwischen 2 Arbeitern und 1 Leiter, summiert sich auf ~ 30 Millionen). Wenn ich dies selbst implementieren müsste, würde ich wahrscheinlich die Ergebnisse mehrerer count(*)Operationen addieren , anstatt Zeilen zusammenzuführen und zu zählen - geben die Pläne an, wie genau das funktioniert?

Damit ich nichts verstecke, finden Sie unten Vollversionen des Abfrageplans für jede:


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)

Antworten

3 LaurenzAlbe Nov 28 2020 at 03:30
  1. Das Geheimnis liegt in Rows Removed by Filter: 10115028:

    Der sequentielle Scan dauert 17 Sekunden, um die erste Ergebniszeile zu finden und zurückzugeben.

  2. Der Optimierer hat keine Ahnung, wie lange es dauert, bis die erste Zeile den Filter passiert. Da es für die Qualität des Plans keinen Unterschied macht, werden nur die Startkosten auf 0 gesetzt.

  3. Beide Pläne funktionieren gleich: Jeder der drei Prozesse durchsucht ein Drittel der Tabelle und zählt die Zeilen (die Partial Aggregate1 Zeile zurückgeben). Im ersten Fall zählt jeder Arbeiter 10 Millionen Zeilen.

    Diese drei Zahlen werden auf der Finalize AggregateBühne gesammelt und summiert .