Interpretacja czasu uruchamiania i różnych planów skanowania sekwencyjnego Postgres

Nov 28 2020

Zadając ostatnie pytanie , w moim wyjściu EXPLAIN ANALYZE pojawiły się tajemnicze składniki czasu uruchamiania. Grałem dalej i odkryłem, że czas uruchamiania spada do blisko 0, jeśli usunę WHEREklauzulę regex .

W ramach testu uruchomiłem następujący skrypt bash:

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

Pierwsze zapytanie zwraca liczbę ~ 30 milionów, a drugie liczy tylko 7 wierszy. Działają na replice odczytu PG 12.3 w RDS przy minimalnej innej aktywności. Obie wersje zajmują mniej więcej tyle samo czasu, jak się spodziewałem. Oto niektóre dane wyjściowe przefiltrowane za pomocą 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

A więc kilka pytań:

  1. Co wchodzi w skład tego startowego składnika „czasu rzeczywistego” podczas skanowania wyrażeń regularnych i dlaczego jest on o wiele większy? (10–20 s przeciwko 0–1 s)

  2. Chociaż „koszt” i „czas” nie są porównywalne, wydaje się, że planista uważa, że ​​koszt początkowy powinien wynosić 0 we wszystkich przypadkach - czy można go oszukać?

  3. Dlaczego strategie wydają się inne? Oba plany wspominają Partial Aggregate, ale zapytanie regex mówi, że rzeczywiste wiersze to 2, ale zwykła wersja mówi, że rzeczywiste wiersze to ~ 10 milionów (wydaje mi się, że jest to jakaś średnia między 2 pracownikami a 1 liderem, w sumie ~ 30 milionów). Gdybym miał to zaimplementować sam, prawdopodobnie zsumowałbym wyniki kilku count(*)operacji, zamiast scalać wiersze i zliczać - czy plany wskazują, jak dokładnie to robi?

Więc niczego nie ukrywam, poniżej są pełne wersje planu zapytań dla każdego:


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)

Odpowiedzi

3 LaurenzAlbe Nov 28 2020 at 03:30
  1. Sekret tkwi w Rows Removed by Filter: 10115028:

    Znalezienie i zwrócenie pierwszego wiersza wyników zajmuje skanowanie sekwencyjne 17 sekund.

  2. Optymalizator nie ma pojęcia, ile czasu minie, zanim pierwszy wiersz przejdzie przez filtr. Ponieważ nie ma to żadnego znaczenia dla jakości planu, po prostu ustawia koszt uruchomienia na 0.

  3. Oba plany działają tak samo: każdy z trzech procesów skanuje jedną trzecią tabeli i zlicza wiersze ( Partial Aggregatezwraca 1 wiersz). W pierwszym przypadku każdego pracownika zlicza 10 milionów wierszy.

    Te trzy liczby są zbierane i sumowane na Finalize Aggregateetapie.