jak sumować czasy w EXPLAIN dla zapytania równoległego Postgres
Mam problem ze zrozumieniem tego EXPLAINw Postgres 12.3:
EXPLAIN (ANALYZE, VERBOSE, BUFFERS) SELECT count(1) FROM mytable WHERE page ~ 'foo';
To jest tabela 22 GB z 30 milionami wierszy na serwerze z pamięcią 16 GB. Zapytanie liczy 7 pasujących wierszy.
Interpretuję dane wyjściowe jako stwierdzenie, że 164 sekundy zostały wydane na I / O, ale całe zapytanie zajęło tylko 65 sekund. Pomyślałem, że może to być podwójne liczenie niektórych równoległych pracowników, ale kiedy dodam VERBOSE, to też nie wydaje się sumować.
Wygląda na to, że każdy z 2 pracowników spędził na czytaniu ~ 55 sekund. Jeśli suma to 110 sekund, jak mogę uzyskać 164 sekundy I / O? (Ponieważ to zapytanie zajmuje ~ 10 sekund, gdy strony są buforowane, domyślam się, że rzeczywisty czas czytania nie jest zbyt daleko od 50 sekund tutaj, FWIW)
Jestem również zdezorientowany, jak Parallel Seq Scanwydaje się, że zajmuje to 32 sekundy, ale zostało jeszcze ponad 30 sekund, aby uzyskać ostateczny wynik. Myślę, że ze względu na 7 wierszy, które znajdzie, tak naprawdę nie ma prawie żadnej pracy do wykonania poza skanowaniem. Czy źle czytam ten rozdział?
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------
Finalize Aggregate (cost=3092377.14..3092377.15 rows=1 width=8) (actual time=65028.818..65028.818 rows=1 loops=1)
Output: count(1)
Buffers: shared hit=75086 read=2858433 dirtied=1
I/O Timings: read=164712.060
-> Gather (cost=3092376.92..3092377.13 rows=2 width=8) (actual time=65028.732..65030.093 rows=3 loops=1)
Output: (PARTIAL count(1))
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=75086 read=2858433 dirtied=1
I/O Timings: read=164712.060
-> Partial Aggregate (cost=3091376.92..3091376.93 rows=1 width=8) (actual time=65026.990..65026.990 rows=1 loops=3)
Output: PARTIAL count(1)
Buffers: shared hit=75086 read=2858433 dirtied=1
I/O Timings: read=164712.060
Worker 0: actual time=65026.164..65026.164 rows=1 loops=1
Buffers: shared hit=25002 read=952587
I/O Timings: read=54906.994
Worker 1: actual time=65026.264..65026.264 rows=1 loops=1
Buffers: shared hit=25062 read=954370 dirtied=1
I/O Timings: read=54889.244
-> Parallel Seq Scan on public.ui_events_v2 (cost=0.00..3091374.68 rows=896 width=0) (actual time=31764.552..65026.980 rows=2 loops=3)
Filter: (ui_events_v2.page ~ 'foo'::text)
Rows Removed by Filter: 10112272
Buffers: shared hit=75086 read=2858433 dirtied=1
I/O Timings: read=164712.060
Worker 0: actual time=16869.988..65026.156 rows=2 loops=1
Buffers: shared hit=25002 read=952587
I/O Timings: read=54906.994
Worker 1: actual time=64091.539..65026.258 rows=1 loops=1
Buffers: shared hit=25062 read=954370 dirtied=1
I/O Timings: read=54889.244
Planning Time: 0.333 ms
Execution Time: 65030.133 ms
Odpowiedzi
Ponieważ parallel_leader_participationjest to wartość domyślna off, lider uczestniczy w skanowaniu sekwencyjnym. Czasy we / wy procesów roboczych są wymienione indywidualnie, ale czas we / wy lidera można znaleźć tylko odejmując czasy pracowników od czasu całkowitego.
Równoległe skanowanie sekwencyjne trwało 65026,980 milisekund, prawie przez cały czas. Pierwsza liczba (31764,552) to czas uruchamiania, czyli czas potrzebny do zwrócenia pierwszego wiersza wyniku. Jeśli coś mnie tu zaskoczy, to tak długi czas uruchamiania.