Início / dba / Perguntas / 280418
Accepted
dcc310
Asked: 2020-11-27 21:04:18 +0800 CST

como somar tempos em EXPLAIN para consulta paralela Postgres

  • 772

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 como dizendo que 164 segundos foram gastos em E/S, mas toda a consulta levou apenas 65 segundos. Eu pensei que poderia ser uma contagem dupla de alguns trabalhadores paralelos, mas quando eu adiciono VERBOSE, também não parece somar.

Parece que está dizendo que cada um dos 2 trabalhadores passou ~ 55 segundos lendo. Se isso somar 110 segundos, como chego a 164 segundos de E/S? (Como essa consulta leva ~ 10 segundos quando as páginas são armazenadas em cache, acho que a leitura do tempo real não está muito longe de 50 segundos aqui, FWIW)

Também estou confuso como Parallel Seq Scanparece levar 32 segundos, mas ainda faltam mais 30 segundos 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
postgresql explain

1 respostas

  1. Best Answer

    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 65.026,980 milissegundos, quase o tempo todo. O primeiro número (31764.552) é o tempo de inicialização, que é o tempo que levou até que a primeira linha de resultado fosse retornada. Se alguma coisa me surpreende aqui, é esse alto tempo de inicialização.

    • 1

relate perguntas