cómo sumar tiempos en EXPLAIN para la consulta paralela de Postgres
Tengo problemas para entender esto EXPLAINen Postgres 12.3:
EXPLAIN (ANALYZE, VERBOSE, BUFFERS) SELECT count(1) FROM mytable WHERE page ~ 'foo';
Se trata de una tabla de 22 GB con 30 millones de filas, en un servidor con 16 GB de memoria. La consulta cuenta 7 filas coincidentes.
Interpreto que la salida dice que se gastaron 164 segundos en E / S, pero toda la consulta solo tomó 65 segundos. Pensé que podría ser contar dos veces algunos trabajadores paralelos, pero cuando agrego VERBOSE, tampoco parece cuadrar.
Parece que dice que cada uno de los 2 trabajadores pasó ~ 55 segundos leyendo. Si eso suma 110 segundos, ¿cómo llego a 164 segundos de E / S? (Dado que esta consulta toma ~ 10 segundos cuando las páginas se almacenan en caché, supongo que la lectura del tiempo real no está muy lejos de los 50 segundos aquí, FWIW)
También estoy confundido de cómo Parallel Seq Scanparece que toma 32 segundos, pero luego quedan otros 30 segundos para obtener el resultado final. Creo que debido a las 7 filas que encuentra, casi no hay trabajo que hacer además del escaneo. ¿Estoy leyendo mal esta sección?
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
Respuestas
Dado que parallel_leader_participationestá en su valor predeterminado off, el líder participa en el escaneo secuencial. Los tiempos de E / S de los procesos de los trabajadores se enumeran individualmente, pero el tiempo de E / S del líder solo se puede encontrar restando los tiempos de los trabajadores del tiempo total.
El escaneo secuencial paralelo tomó 65026,980 milisegundos, casi todo el tiempo. El primer número (31764.552) es el tiempo de inicio, es decir, el tiempo que tomó hasta que se devolvió la primera fila de resultados. Si algo me sorprende aquí, es ese alto tiempo de inicio.