how to sum times in EXPLAIN for Postgres parallel query

Question

I'm having trouble understanding this EXPLAIN on Postgres 12.3:

EXPLAIN (ANALYZE, VERBOSE, BUFFERS) SELECT count(1) FROM mytable WHERE page ~ 'foo';

This is a 22GB table with 30 million rows, on a server with 16GB memory. The query counts 7 matching rows.

I interpret the output as saying 164 seconds was spent on I/O, yet the whole query only took 65 seconds. I thought it might be double counting some parallel workers, but when I add VERBOSE, it doesn't seem to add up either.

It looks like it's saying each of 2 workers spent ~55 seconds reading. If that sums to 110 seconds, how do I get to 164 seconds of I/O? (Since this query takes ~10 seconds when pages are cached, I'm guessing the actual time reading isn't too far from 50 seconds here, FWIW)

I'm also confused how the Parallel Seq Scan seems to take 32 seconds, but then there's still another 30+ seconds left to get the final result. I would think that because of the 7 rows it finds, there's really almost no work to do besides the scan. Am I reading this section wrong?

                                                                       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

Answer 1

Since parallel_leader_participation is at its default value off, the leader participates in the sequential scan. The I/O times of the worker processes are listed individually, but the I/O time of the leader can only be found by subtracting the workers' times from the total time.

The parallel sequential scan took 65026.980 milliseconds, almost all of the time. The fist number (31764.552) is the startup time, that is the time it took until the first result row was returned. If anything surprises me here, it is that high startup time.