From: Tomas Vondra <tomas.vondra@2ndquadrant.com>
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Jeff Davis <pgsql@j-davis.com>
Cc: pgsql-hackers <pgsql-hackers@postgresql.org>
Subject: Re: Trouble with hashagg spill I/O pattern and costing
Date: Tue, 26 May 2020 16:15:24 +0200
Message-ID: <20200526141524.ohtvrp23vxosgivl@development> (raw)
In-Reply-To: <CA+hUKG+q3Ma+sTKn2316Ofof6u21hh0cGJHcJ-fAnLxw=LXevw@mail.gmail.com>
References: <20200519175320.tl4qm6le5dbg2pcf@development>
<acad6f2ba8d560b9dfa9a564c7b7d3162abf8347.camel@j-davis.com>
<20200521191318.gw3xjivrxracvzmg@development>
<8619437df796903e64c8479e299d13ebacb5fbe0.camel@j-davis.com>
<20200521214122.6opovye4mnbqczlc@development>
<20200525021045.dilgcsmgiu4l5jpa@development>
<20200525121722.6wzcelweefyuwg54@development>
<2df2e0728d48f498b9d6954b5f9080a34535c385.camel@j-davis.com>
<20200525225909.aifxjm53hw4xyzxd@development>
<CA+hUKG+q3Ma+sTKn2316Ofof6u21hh0cGJHcJ-fAnLxw=LXevw@mail.gmail.com>
On Tue, May 26, 2020 at 05:02:41PM +1200, Thomas Munro wrote:
>On Tue, May 26, 2020 at 10:59 AM Tomas Vondra
><tomas.vondra@2ndquadrant.com> wrote:
>> On Mon, May 25, 2020 at 12:49:45PM -0700, Jeff Davis wrote:
>> >Do you think the difference in IO patterns is due to a difference in
>> >handling reads vs. writes in the kernel? Or do you think that 128
>> >blocks is not enough to amortize the cost of a seek for that device?
>>
>> I don't know. I kinda imagined it was due to the workers interfering
>> with each other, but that should affect the sort the same way, right?
>> I don't have any data to support this, at the moment - I can repeat
>> the iosnoop tests and analyze the data, of course.
>
>About the reads vs writes question: I know that reading and writing
>two interleaved sequential "streams" through the same fd confuses the
>read-ahead/write-behind heuristics on FreeBSD UFS (I mean: w(1),
>r(42), w(2), r(43), w(3), r(44), ...) so the performance is terrible
>on spinning media. Andrew Gierth reported that as a problem for
>sequential scans that are also writing back hint bits, and vacuum.
>However, in a quick test on a Linux 4.19 XFS system, using a program
>to generate interleaving read and write streams 1MB apart, I could see
>that it was still happily generating larger clustered I/Os. I have no
>clue for other operating systems. That said, even on Linux, reads and
>writes still have to compete for scant IOPS on slow-seek media (albeit
>hopefully in larger clustered I/Os)...
>
True. I've repeated the tests with collection of iosnoop stats, both for
the good (partitioned hashagg) and bad (complete hashagg in each worker)
plans. Ignoring the fact that the bad plan does much more I/O in general
(about 32GB write + 35GB reads vs. 5.4GB + 7.6GB), request size stats
are almost exactly the same:
1) good plan (partitioned hashagg, ~180 seconds)
type | bytes | count | pct
------+---------+-------+-------
RA | 131072 | 39392 | 71.62
RA | 8192 | 5666 | 10.30
RA | 16384 | 3080 | 5.60
RA | 32768 | 2888 | 5.25
RA | 65536 | 2870 | 5.22
RA | 262144 | 710 | 1.29
W | 1310720 | 3138 | 32.01
W | 360448 | 633 | 6.46
W | 688128 | 538 | 5.49
W | 692224 | 301 | 3.07
W | 364544 | 247 | 2.52
W | 696320 | 182 | 1.86
W | 8192 | 164 | 1.67
W | 700416 | 116 | 1.18
W | 368640 | 102 | 1.04
2) bad plan (complete hashagg, ~500 seconds)
type | bytes | count | pct
------+---------+--------+--------
RA | 131072 | 258924 | 68.54
RA | 8192 | 31357 | 8.30
RA | 16384 | 27596 | 7.31
RA | 32768 | 26434 | 7.00
RA | 65536 | 26415 | 6.99
RM | 4096 | 532 | 100.00
W | 1310720 | 15346 | 34.64
W | 8192 | 911 | 2.06
W | 360448 | 816 | 1.84
W | 16384 | 726 | 1.64
W | 688128 | 545 | 1.23
W | 32768 | 544 | 1.23
W | 40960 | 486 | 1.10
W | 524288 | 457 | 1.03
So in both cases, majority of read requests (~70%) are 128kB, with
additional ~25% happening in request larger than 8kB. In terms of I/O,
that's more than 90% of read I/O.
There is some difference in the "I/O delta" stats, showing how far the
queued I/O requests are. The write stats look almost exactly the same,
but for reads it looks like this:
1) good plan
type | block_delta | count | pct
------+-------------+-------+-------
RA | 256 | 7555 | 13.74
RA | 64 | 2297 | 4.18
RA | 32 | 685 | 1.25
RA | 128 | 613 | 1.11
RA | 16 | 612 | 1.11
2) bad plans
type | block_delta | count | pct
------+-------------+-------+-------
RA | 64 | 18817 | 4.98
RA | 30480 | 9778 | 2.59
RA | 256 | 9437 | 2.50
Ideally this should match the block size stats (it's in sectors, so 256
is 128kB). Unfortunately this does not work all that great - even for
the "good" plan it's only about 14% vs. 70% (of 128kB blocks). In the
serial plan (disabled parallelism) this was ~70% vs. 75%, much closer.
Anyway, I think this shows that the read-ahead works pretty well even
with multiple workers - otherwise there wouldn't be that many 128kB
requests. The poor correlation with 128kB deltas is unfortunate, but I
don't think we can really fix that.
This was on linux (5.6.0) with ext4, but I don't think the filesystem
matters that much - the read-ahead happens in page cache I think.
>Jumping over large interleaving chunks with no prefetching from other
>tapes *must* produce stalls though... and if you crank up the read
>ahead size to be a decent percentage of the contiguous chunk size, I
>guess you must also waste I/O bandwidth on unwanted data past the end
>of each chunk, no?
>
>In an off-list chat with Jeff about whether Hash Join should use
>logtape.c for its partitions too, the first thought I had was that to
>be competitive with separate files, perhaps you'd need to write out a
>list of block ranges for each tape (rather than just next pointers on
>each block), so that you have the visibility required to control
>prefetching explicitly. I guess that would be a bit like the list of
>physical extents that Linux commands like filefrag(8) and xfs_bmap(8)
>can show you for regular files. (Other thoughts included worrying
>about how to make it allocate and stream blocks in parallel queries,
>...!?#$)
I was wondering how useful would it be to do explicit prefetch too.
I'm not familiar with logtape internals but IIRC the blocks are linked
by each block having a pointer to the prev/next block, which means we
can't prefetch more than one block ahead I think. But maybe I'm wrong,
or maybe fetching even just one block ahead would help ...
regards
--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=9628616.99..9628617.00 rows=1 width=32) (actual time=186382.616..186382.616 rows=1 loops=1)
-> Aggregate (cost=9628616.99..9628617.00 rows=1 width=32) (actual time=186382.615..186382.615 rows=1 loops=1)
-> Nested Loop (cost=8846746.78..9628472.06 rows=57973 width=8) (actual time=117876.966..186370.093 rows=17275 loops=1)
Join Filter: (part.p_partkey = lineitem.l_partkey)
-> Hash Join (cost=8846746.21..9257862.40 rows=5798 width=40) (actual time=117874.862..158676.425 rows=6431 loops=1)
Hash Cond: (lineitem_1.l_partkey = part.p_partkey)
-> Finalize HashAggregate (cost=8694720.67..9036167.83 rows=5518338 width=36) (actual time=116983.030..157039.065 rows=6400000 loops=1)
Group Key: lineitem_1.l_partkey
Planned Partitions: 16
Peak Memory Usage: 237713 kB
Disk Usage: 2574336 kB
HashAgg Batches: 528
-> Gather (cost=4392829.42..7929051.27 rows=33110028 width=36) (actual time=34827.589..90325.640 rows=44196557 loops=1)
Workers Planned: 6
Workers Launched: 6
-> Partial HashAggregate (cost=4391829.42..4617048.47 rows=5518338 width=36) (actual time=34870.679..92227.836 rows=6313794 loops=7)
Group Key: lineitem_1.l_partkey
Planned Partitions: 16
Peak Memory Usage: 131217 kB
Disk Usage: 739328 kB
HashAgg Batches: 208
-> Parallel Seq Scan on lineitem lineitem_1 (cost=0.00..3919360.17 rows=31997917 width=9) (actual time=1.011..11798.355 rows=27428650 loops=7)
-> Hash (cost=151941.49..151941.49 rows=6724 width=4) (actual time=891.150..891.150 rows=6431 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 291kB
-> Gather (cost=1000.00..151941.49 rows=6724 width=4) (actual time=1.533..889.103 rows=6431 loops=1)
Workers Planned: 5
Workers Launched: 5
-> Parallel Seq Scan on part (cost=0.00..150269.09 rows=1345 width=4) (actual time=2.381..878.871 rows=1072 loops=6)
Filter: ((p_brand = 'Brand#22'::bpchar) AND (p_container = 'LG BOX'::bpchar))
Rows Removed by Filter: 1065595
-> Index Scan using idx_lineitem_part_supp on lineitem (cost=0.57..63.77 rows=12 width=17) (actual time=1.541..4.303 rows=3 loops=6431)
Index Cond: (l_partkey = lineitem_1.l_partkey)
Filter: (l_quantity < ((0.2 * avg(lineitem_1.l_quantity))))
Rows Removed by Filter: 27
Planning Time: 0.364 ms
Execution Time: 186599.047 ms
(36 rows)
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=9810135.83..9810135.85 rows=1 width=32) (actual time=496902.294..496902.295 rows=1 loops=1)
-> Finalize Aggregate (cost=9810135.83..9810135.85 rows=1 width=32) (actual time=496902.292..496902.292 rows=1 loops=1)
-> Gather (cost=9810135.30..9810135.81 rows=5 width=32) (actual time=485494.442..496905.736 rows=6 loops=1)
Workers Planned: 5
Workers Launched: 5
-> Partial Aggregate (cost=9809135.30..9809135.31 rows=1 width=32) (actual time=489336.187..489336.187 rows=1 loops=6)
-> Nested Loop (cost=9541561.76..9809106.31 rows=11595 width=8) (actual time=482245.584..489334.183 rows=2879 loops=6)
Join Filter: (part.p_partkey = lineitem.l_partkey)
-> Hash Join (cost=9541561.19..9734958.81 rows=1160 width=40) (actual time=482243.642..484209.161 rows=1072 loops=6)
Hash Cond: (part.p_partkey = lineitem_1.l_partkey)
-> Parallel Seq Scan on part (cost=0.00..150269.09 rows=1345 width=4) (actual time=0.350..217.852 rows=1072 loops=6)
Filter: ((p_brand = 'Brand#22'::bpchar) AND (p_container = 'LG BOX'::bpchar))
Rows Removed by Filter: 1065595
-> Hash (cost=9429468.96..9429468.96 rows=5518338 width=36) (actual time=482108.072..482108.072 rows=6400000 loops=6)
Buckets: 2097152 Batches: 4 Memory Usage: 92933kB
-> HashAggregate (cost=8354071.53..9374285.58 rows=5518338 width=36) (actual time=254740.191..480275.566 rows=6400000 loops=6)
Group Key: lineitem_1.l_partkey
Planned Partitions: 16
Peak Memory Usage: 139409 kB
Disk Usage: 5098496 kB
HashAgg Batches: 1424
-> Seq Scan on lineitem lineitem_1 (cost=0.00..5519256.04 rows=191987504 width=9) (actual time=0.104..31016.587 rows=192000551 loops=6)
-> Index Scan using idx_lineitem_part_supp on lineitem (cost=0.57..63.77 rows=12 width=17) (actual time=1.775..4.777 rows=3 loops=6431)
Index Cond: (l_partkey = lineitem_1.l_partkey)
Filter: (l_quantity < ((0.2 * avg(lineitem_1.l_quantity))))
Rows Removed by Filter: 27
Planning Time: 0.385 ms
Execution Time: 497025.491 ms
(28 rows)
Attachments:
[image/png] patched-bad-plan.png (152.4K, ../20200526141524.ohtvrp23vxosgivl@development/2-patched-bad-plan.png)
download | view image
[image/png] patched-good-plan.png (104.3K, ../20200526141524.ohtvrp23vxosgivl@development/3-patched-good-plan.png)
download | view image
[text/plain] good-plan.txt (3.5K, ../20200526141524.ohtvrp23vxosgivl@development/4-good-plan.txt)
download | inline:
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=9628616.99..9628617.00 rows=1 width=32) (actual time=186382.616..186382.616 rows=1 loops=1)
-> Aggregate (cost=9628616.99..9628617.00 rows=1 width=32) (actual time=186382.615..186382.615 rows=1 loops=1)
-> Nested Loop (cost=8846746.78..9628472.06 rows=57973 width=8) (actual time=117876.966..186370.093 rows=17275 loops=1)
Join Filter: (part.p_partkey = lineitem.l_partkey)
-> Hash Join (cost=8846746.21..9257862.40 rows=5798 width=40) (actual time=117874.862..158676.425 rows=6431 loops=1)
Hash Cond: (lineitem_1.l_partkey = part.p_partkey)
-> Finalize HashAggregate (cost=8694720.67..9036167.83 rows=5518338 width=36) (actual time=116983.030..157039.065 rows=6400000 loops=1)
Group Key: lineitem_1.l_partkey
Planned Partitions: 16
Peak Memory Usage: 237713 kB
Disk Usage: 2574336 kB
HashAgg Batches: 528
-> Gather (cost=4392829.42..7929051.27 rows=33110028 width=36) (actual time=34827.589..90325.640 rows=44196557 loops=1)
Workers Planned: 6
Workers Launched: 6
-> Partial HashAggregate (cost=4391829.42..4617048.47 rows=5518338 width=36) (actual time=34870.679..92227.836 rows=6313794 loops=7)
Group Key: lineitem_1.l_partkey
Planned Partitions: 16
Peak Memory Usage: 131217 kB
Disk Usage: 739328 kB
HashAgg Batches: 208
-> Parallel Seq Scan on lineitem lineitem_1 (cost=0.00..3919360.17 rows=31997917 width=9) (actual time=1.011..11798.355 rows=27428650 loops=7)
-> Hash (cost=151941.49..151941.49 rows=6724 width=4) (actual time=891.150..891.150 rows=6431 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 291kB
-> Gather (cost=1000.00..151941.49 rows=6724 width=4) (actual time=1.533..889.103 rows=6431 loops=1)
Workers Planned: 5
Workers Launched: 5
-> Parallel Seq Scan on part (cost=0.00..150269.09 rows=1345 width=4) (actual time=2.381..878.871 rows=1072 loops=6)
Filter: ((p_brand = 'Brand#22'::bpchar) AND (p_container = 'LG BOX'::bpchar))
Rows Removed by Filter: 1065595
-> Index Scan using idx_lineitem_part_supp on lineitem (cost=0.57..63.77 rows=12 width=17) (actual time=1.541..4.303 rows=3 loops=6431)
Index Cond: (l_partkey = lineitem_1.l_partkey)
Filter: (l_quantity < ((0.2 * avg(lineitem_1.l_quantity))))
Rows Removed by Filter: 27
Planning Time: 0.364 ms
Execution Time: 186599.047 ms
(36 rows)
[text/plain] bad-plan.txt (3.1K, ../20200526141524.ohtvrp23vxosgivl@development/5-bad-plan.txt)
download | inline:
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=9810135.83..9810135.85 rows=1 width=32) (actual time=496902.294..496902.295 rows=1 loops=1)
-> Finalize Aggregate (cost=9810135.83..9810135.85 rows=1 width=32) (actual time=496902.292..496902.292 rows=1 loops=1)
-> Gather (cost=9810135.30..9810135.81 rows=5 width=32) (actual time=485494.442..496905.736 rows=6 loops=1)
Workers Planned: 5
Workers Launched: 5
-> Partial Aggregate (cost=9809135.30..9809135.31 rows=1 width=32) (actual time=489336.187..489336.187 rows=1 loops=6)
-> Nested Loop (cost=9541561.76..9809106.31 rows=11595 width=8) (actual time=482245.584..489334.183 rows=2879 loops=6)
Join Filter: (part.p_partkey = lineitem.l_partkey)
-> Hash Join (cost=9541561.19..9734958.81 rows=1160 width=40) (actual time=482243.642..484209.161 rows=1072 loops=6)
Hash Cond: (part.p_partkey = lineitem_1.l_partkey)
-> Parallel Seq Scan on part (cost=0.00..150269.09 rows=1345 width=4) (actual time=0.350..217.852 rows=1072 loops=6)
Filter: ((p_brand = 'Brand#22'::bpchar) AND (p_container = 'LG BOX'::bpchar))
Rows Removed by Filter: 1065595
-> Hash (cost=9429468.96..9429468.96 rows=5518338 width=36) (actual time=482108.072..482108.072 rows=6400000 loops=6)
Buckets: 2097152 Batches: 4 Memory Usage: 92933kB
-> HashAggregate (cost=8354071.53..9374285.58 rows=5518338 width=36) (actual time=254740.191..480275.566 rows=6400000 loops=6)
Group Key: lineitem_1.l_partkey
Planned Partitions: 16
Peak Memory Usage: 139409 kB
Disk Usage: 5098496 kB
HashAgg Batches: 1424
-> Seq Scan on lineitem lineitem_1 (cost=0.00..5519256.04 rows=191987504 width=9) (actual time=0.104..31016.587 rows=192000551 loops=6)
-> Index Scan using idx_lineitem_part_supp on lineitem (cost=0.57..63.77 rows=12 width=17) (actual time=1.775..4.777 rows=3 loops=6431)
Index Cond: (l_partkey = lineitem_1.l_partkey)
Filter: (l_quantity < ((0.2 * avg(lineitem_1.l_quantity))))
Rows Removed by Filter: 27
Planning Time: 0.385 ms
Execution Time: 497025.491 ms
(28 rows)
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: tomas.vondra@2ndquadrant.com, thomas.munro@gmail.com, pgsql@j-davis.com
Subject: Re: Trouble with hashagg spill I/O pattern and costing
In-Reply-To: <20200526141524.ohtvrp23vxosgivl@development>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox