Re: Parallel Seq Scan

On 13 November 2015 at 03:39, Amit Kapila <amit(dot)kapila16(at)gmail(dot)com> wrote:
> On Thu, Nov 12, 2015 at 9:05 PM, Thom Brown <thom(at)linux(dot)com> wrote:
>>
>> On 12 November 2015 at 15:23, Amit Kapila <amit(dot)kapila16(at)gmail(dot)com> wrote:
>> > On Wed, Nov 11, 2015 at 11:29 PM, Pavel Stehule
>> > <pavel(dot)stehule(at)gmail(dot)com>
>> > wrote:
>> >>
>> >> Hi
>> >>
>> >> I have a first query
>> >>
>> >> I looked on EXPLAIN ANALYZE output and the numbers of filtered rows are
>> >> differen
>> >>
>> >
>> > Thanks for the report. The reason for this problem is that
>> > instrumentation
>> > information from workers is getting aggregated multiple times. In
>> > ExecShutdownGatherWorkers(), we call ExecParallelFinish where it
>> > will wait for workers to finish and then accumulate stats from workers.
>> > Now ExecShutdownGatherWorkers() could be called multiple times
>> > (once we read all tuples from workers, at end of node) and it should be
>> > ensured that repeated calls should not try to redo the work done by
>> > first
>> > call.
>> > The same is ensured for tuplequeues, but not for parallel executor info.
>> > I think we can safely assume that we need to call ExecParallelFinish()
>> > only
>> > when there are workers started by the Gathers node, so on those lines
>> > attached patch should fix the problem.
>>
>> That fixes the count issue for me, although not the number of buffers
>> hit,
>>
>
> The number of shared buffers hit could be different across different runs
> because the read sequence of parallel workers can't be guaranteed, also
> I don't think same is even guaranteed for Seq Scan node, the other
> operations
> in parallel could lead to different number, however the actual problem was
> that in one of the plans shown by you [1], the Buffers hit at Gather node
> (175288) is lesser than the Buffers hit at Parallel Seq Scan node (241201).
> Do you still (after applying above patch) see that Gather node is showing
> lesser hit buffers than Parallel Seq Scan node?

Hmm... that's odd, I'm not seeing the problem now, so maybe I'm mistaken there.

> [1]
> # explain (analyse, buffers, timing, verbose, costs) select count(*)
> from js where content->'tags'->>'title' like '%design%';
> QUERY
> PLAN
> ------------------------------------------------------------------------------------------------------------------------------------
> Aggregate (cost=132489.34..132489.35 rows=1 width=0) (actual
> time=382.987..382.987 rows=1 loops=1)
> Output: count(*)
> Buffers: shared hit=175288
> -> Gather (cost=1000.00..132488.34 rows=401 width=0) (actual
> time=382.983..382.983 rows=0 loops=1)
> Output: content
> Number of Workers: 1
> Buffers: shared hit=175288
> -> Parallel Seq Scan on public.js (cost=0.00..131448.24
> rows=401 width=0) (actual time=379.407..1141.437 rows=0 loops=1)
> Output: content
> Filter: (((js.content -> 'tags'::text) ->>
> 'title'::text) ~~ '%design%'::text)
> Rows Removed by Filter: 1724810
> Buffers: shared hit=241201
> Planning time: 0.104 ms
> Execution time: 403.045 ms
> (14 rows)
>
> Time: 403.596 ms
>
>> or the actual time taken.
>>
>
> Exactly what time you are referring here, Execution Time or actual time
> shown on Parallel Seq Scan node and what problem do you see with
> the reported time?

I'm referring to the Parallel Seq Scan actual time, showing
"379.407..1141.437" with 1 worker, but the total execution time shows
403.045. If one worker is taking over a second, how come the whole
query was less than half a second?

Thom