> On Jul 7, 2018, at 12:03 AM, Amit Kapila <amit.kapil...@gmail.com> wrote: > > On Sat, Jul 7, 2018 at 7:45 AM, Amit Kapila <amit.kapil...@gmail.com > <mailto:amit.kapil...@gmail.com>> wrote: >> On Sat, Jul 7, 2018 at 12:44 AM, Robert Haas <robertmh...@gmail.com> wrote: >>> On Fri, Jul 6, 2018 at 9:44 AM, Amit Kapila <amit.kapil...@gmail.com> wrote: >>>> I have tried this idea, but it doesn't completely solve the problem. >>>> The problem is that nodes below LIMIT won't get a chance to accumulate >>>> the stats as they won't be able to call InstrStopNode. >>> >>> I'm not sure I understand. Why not? I see that we'd need to insert >>> an extra call to InstrStopNode() if we were stopping the node while it >>> was running, because then InstrStartNode() would have already been >>> done, but the corresponding call to InstrStopNode() would not have >>> been done. But I'm not sure how that would happen in this case. Can >>> you explain further? >>> >> >> Okay, let me try. The code flow is that for each node we will call >> InstrStartNode()->ExecProcNodeReal()->InstrStopNode(). Now let's say >> we have to execute a plan Limit->Gather-> Parallel SeqScan. In this, >> first for Limit node, we will call InstrStartNode() and >> ExecProcNodeReal() and then for Gather we will call InstrStartNode(), >> ExecProcNodeReal() and InstrStopNode(). Now, Limit node decides that >> it needs to shutdown all the nodes (ExecShutdownNode) and after that >> it will call InstrStopNode() for Limit node. So, in this flow after >> shutting down nodes, we never get chance for Gather node to use stats >> collected during ExecShutdownNode. >> > > I went ahead and tried the solution which I had mentioned yesterday, > that is to allow ExecShutdownNode to count stats. Apart from fixing > this problem, it will also fix the problem with Gather Merge as > reported by Adrien [1], because now Gather Merge will also get a > chance to count stats after shutting down workers. > > Note that, I have changed the location of InstrStartParallelQuery in > ParallelQueryMain so that the buffer usage stats are accumulated only > for the plan execution which is what we do for instrumentation > information as well. If we don't do that, it will count some > additional stats for ExecutorStart which won't match with what we have > in Instrumentation structure of each node.
I tried running the below on both 11beta2 and HEAD with the patch
applied:
CREATE UNLOGGED TABLE t1 (c1 int);
INSERT INTO t1 SELECT generate_series(1,100000000);
/** restart PostgreSQL */
EXPLAIN (analyze,buffers,timing off,costs off)
SELECT count(*) FROM t1;
/** repeat above two queries */
I have identical postgresql.conf files on both instances as well.
11beta2
======
buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
from t1;
QUERY PLAN
--------------------------------------------------------------------------
Finalize Aggregate (actual rows=1 loops=1)
Buffers: shared read=63175
-> Gather (actual rows=7 loops=1)
Workers Planned: 6
Workers Launched: 6
Buffers: shared read=63175
-> Partial Aggregate (actual rows=1 loops=7)
Buffers: shared read=442478
-> Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
Buffers: shared read=442478
Planning Time: 1.422 ms
Execution Time: 3214.407 ms
(12 rows)
buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
from t1;
QUERY PLAN
--------------------------------------------------------------------------
Finalize Aggregate (actual rows=1 loops=1)
Buffers: shared hit=27 read=64960
-> Gather (actual rows=7 loops=1)
Workers Planned: 6
Workers Launched: 6
Buffers: shared hit=27 read=64960
-> Partial Aggregate (actual rows=1 loops=7)
Buffers: shared hit=224 read=442254
-> Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
Buffers: shared hit=224 read=442254
Planning Time: 0.080 ms
Execution Time: 3774.091 ms
(12 rows)
HEAD
=====
buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
from t1;
QUERY PLAN
--------------------------------------------------------------------------
Finalize Aggregate (actual rows=1 loops=1)
Buffers: shared read=442478
-> Gather (actual rows=7 loops=1)
Workers Planned: 6
Workers Launched: 6
Buffers: shared read=442478
-> Partial Aggregate (actual rows=1 loops=7)
Buffers: shared read=442478
-> Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
Buffers: shared read=442478
Planning Time: 1.594 ms
Execution Time: 6207.799 ms
(12 rows)
buffers=# explain (analyze,buffers,timing off,costs off) select count(*)
from t1;
QUERY PLAN
--------------------------------------------------------------------------
Finalize Aggregate (actual rows=1 loops=1)
Buffers: shared hit=224 read=442254
-> Gather (actual rows=7 loops=1)
Workers Planned: 6
Workers Launched: 6
Buffers: shared hit=224 read=442254
-> Partial Aggregate (actual rows=1 loops=7)
Buffers: shared hit=224 read=442254
-> Parallel Seq Scan on t1 (actual rows=14285714 loops=7)
Buffers: shared hit=224 read=442254
Planning Time: 0.074 ms
Execution Time: 5006.395 ms
(12 rows)
Notice the “read” numbers just before the “Finalize Aggregate” is much
higher, and there appears to be a performance hit.
Jonathan
signature.asc
Description: Message signed with OpenPGP
