Postgres並列クエリのEXPLAINで時間を合計する方法

Nov 27 2020

EXPLAINPostgres12.3でこれを理解するのに問題があります。

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

これは、16GBのメモリを搭載したサーバー上にある、3,000万行の22GBのテーブルです。クエリは7つの一致する行をカウントします。

出力は、I / Oに164秒が費やされたと解釈しますが、クエリ全体は65秒しかかかりませんでした。いくつかの並列ワーカーを二重に数えるかもしれないと思いましたがVERBOSE、追加しても、合計されていないようです。

2人の労働者のそれぞれが約55秒の読書に費やしたと言っているようです。合計が110秒の場合、164秒のI / Oを取得するにはどうすればよいですか？（このクエリはページがキャッシュされるときに最大10秒かかるので、実際の読み取り時間はここでは50秒からそれほど遠くないと思います、FWIW）

またParallel Seq Scan、32秒かかるように見えるのも混乱していますが、最終結果を得るにはさらに30秒以上残っています。7行が見つかったため、スキャン以外に行う作業はほとんどないと思います。このセクションを間違って読んでいますか？

                                                                       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

回答

1 LaurenzAlbe Nov 27 2020 at 14:21

以来は、parallel_leader_participationデフォルト値であるoff、シーケンシャルスキャンのリーダーの参加。ワーカープロセスのI / O時間は個別にリストされていますが、リーダーのI / O時間は、合計時間からワーカーの時間を差し引くことによってのみ見つけることができます。

並列シーケンシャルスキャンには、ほぼすべての時間で65026.980ミリ秒かかりました。最初の番号（31764.552）は起動時間、つまり最初の結果行が返されるまでにかかった時間です。ここで私が驚いたことは、起動時間が長いことです。