como somar os tempos em EXPLAIN para consulta paralela do Postgres
Estou tendo problemas para entender isso EXPLAINno Postgres 12.3:
EXPLAIN (ANALYZE, VERBOSE, BUFFERS) SELECT count(1) FROM mytable WHERE page ~ 'foo';
Esta é uma tabela de 22 GB com 30 milhões de linhas, em um servidor com 16 GB de memória. A consulta conta 7 linhas correspondentes.
Eu interpreto a saída dizendo que 164 segundos foram gastos em E / S, mas a consulta inteira levou apenas 65 segundos. Achei que poderia ser a contagem dupla de alguns workers paralelos, mas quando adiciono VERBOSE, também não parece que soma.
Parece que cada um dos 2 trabalhadores passou cerca de 55 segundos lendo. Se isso totaliza 110 segundos, como faço para chegar a 164 segundos de E / S? (Como esta consulta leva cerca de 10 segundos quando as páginas são armazenadas em cache, estou supondo que o tempo real de leitura não está muito longe de 50 segundos aqui, FWIW)
Também estou confuso sobre como o programa Parallel Seq Scanparece levar 32 segundos, mas ainda há mais 30 segundos restantes para obter o resultado final. Eu acho que por causa das 7 linhas que ele encontra, quase não há trabalho a fazer além da varredura. Estou lendo esta seção errado?
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
Respostas
Como parallel_leader_participationestá em seu valor padrão off, o líder participa da varredura sequencial. Os tempos de E / S dos processos de trabalho são listados individualmente, mas o tempo de E / S do líder só pode ser encontrado subtraindo os tempos dos trabalhadores do tempo total.
A varredura sequencial paralela levou 65026.980 milissegundos, quase todo o tempo. O primeiro número (31764.552) é o tempo de inicialização, ou seja, o tempo que levou até que a primeira linha do resultado fosse retornada. Se algo me surpreende aqui, é o alto tempo de inicialização.