Re: Why is a hash join preferred when it does not fit in work_mem

Hello again, I am back with new experiments.

First of all, I have a concrete set of steps that replicate the
slowness of the hash join that I described. If you have a system with
spinning disks lying around, I would appreciate if you can verify the
scenario. Can you also replicate it in different kind of systems?

CREATE TABLE descriptions (description_id serial PRIMARY KEY, description text);
INSERT INTO descriptions (description_id, description)
SELECT s, repeat(encode(sha512(s::text::bytea), 'hex'), 4)
FROM generate_series(0,1200300) AS s;
CREATE TABLE descriptions_in_books (description_id integer REFERENCES descriptions(description_id), book_id integer);
INSERT INTO descriptions_in_books (description_id, book_id)
SELECT s % 1200300, s
FROM generate_series(0,5200300) AS s;

SET work_mem TO '1MB';
SET hash_mem_multiplier = 1.0;
SET track_io_timing TO on;

EXPLAIN (ANALYZE,VERBOSE,BUFFERS,SETTINGS) SELECT * FROM descriptions NATURAL JOIN descriptions_in_books;
SET enable_hashjoin TO off;
EXPLAIN (ANALYZE,VERBOSE,BUFFERS,SETTINGS) SELECT * FROM descriptions NATURAL JOIN descriptions_in_books;

The first JOIN query uses a hash join with Batches: 1024 and takes 622s!
For the longest part, I can see the disk writing most of the time around
1-2 MB/s, so I have to assume it's not writing sequentially.

The second identical JOIN uses a merge join that completes in 14s. The I/O
happens in a much higher rate (10x maybe), so I'm assuming it's mostly
sequential.

Another observation is that the hash join deteriorates as the length of
the TEXT column grows. In fact, if I fill it with only 32 char long
strings, then the hash join is split in only 128 batches, and it completes
almost as fast as the merge join. Could it be that the cost estimation
is underestimating the I/O pattern related to splitting in batches?

Here are the measurements:

Hash Join (cost=192450.84..401456.02 rows=5200486 width=524) (actual time=344516.004..621725.562 rows=5200301 loops=1)
Output: descriptions.description_id, descriptions.description, descriptions_in_books.book_id
Inner Unique: true
Hash Cond: (descriptions_in_books.description_id = descriptions.description_id)
Buffers: shared hit=15586 read=93161, temp read=97829 written=97829
I/O Timings: shared/local read=1402.597, temp read=229252.170 write=371508.313
-> Seq Scan on public.descriptions_in_books (cost=0.00..75015.86 rows=5200486 width=8) (actual time=0.068..1819.629 rows=5200301 loops=1)
Output: descriptions_in_books.book_id, descriptions_in_books.description_id
Buffers: shared hit=32 read=22979
I/O Timings: shared/local read=249.910
-> Hash (cost=97739.04..97739.04 rows=1200304 width=520) (actual time=343268.470..343268.471 rows=1200301 loops=1)
Output: descriptions.description_id, descriptions.description
Buckets: 2048 Batches: 1024 Memory Usage: 686kB
Buffers: shared hit=15554 read=70182, temp written=78538
I/O Timings: shared/local read=1152.687, temp write=338883.205
-> Seq Scan on public.descriptions (cost=0.00..97739.04 rows=1200304 width=520) (actual time=0.028..2278.791 rows=1200301 loops=1)
Output: descriptions.description_id, descriptions.description
Buffers: shared hit=15554 read=70182
I/O Timings: shared/local read=1152.687
Settings: hash_mem_multiplier = '1', work_mem = '1MB'
Planning Time: 0.303 ms
Execution Time: 622495.279 ms
(22 rows)

SET enable_hashjoin TO off;

Merge Join (cost=868411.87..1079330.96 rows=5200301 width=524) (actual time=6091.932..13304.924 rows=5200301 loops=1)
Output: descriptions.description_id, descriptions.description, descriptions_in_books.book_id
Merge Cond: (descriptions.description_id = descriptions_in_books.description_id)
Buffers: shared hit=67 read=111962 written=1, temp read=45806 written=46189
I/O Timings: shared/local read=1007.043 write=28.575, temp read=344.937 write=794.483
-> Index Scan using descriptions_pkey on public.descriptions
(cost=0.43..116919.99 rows=1200304 width=520) (actual time=0.028..1596.387 rows=1200301 loops=1)
Output: descriptions.description_id, descriptions.description
Buffers: shared hit=3 read=89015 written=1
I/O Timings: shared/local read=834.732 write=28.575
-> Materialize (cost=868408.84..894410.35 rows=5200301 width=8) (actual time=6091.892..9171.796 rows=5200301 loops=1)
Output: descriptions_in_books.book_id, descriptions_in_books.description_id
Buffers: shared hit=64 read=22947, temp read=45806 written=46189
I/O Timings: shared/local read=172.311, temp read=344.937 write=794.483
-> Sort (cost=868408.84..881409.60 rows=5200301 width=8) (actual time=6091.885..7392.828 rows=5200301 loops=1)
Output: descriptions_in_books.book_id, descriptions_in_books.description_id
Sort Key: descriptions_in_books.description_id
Sort Method: external merge Disk: 91632kB
Buffers: shared hit=64 read=22947, temp read=45806 written=46189
I/O Timings: shared/local read=172.311, temp read=344.937 write=794.483
-> Seq Scan on public.descriptions_in_books (cost=0.00..75014.01 rows=5200301 width=8) (actual time=0.031..1617.520 rows=5200301 loops=1)
Output: descriptions_in_books.book_id, descriptions_in_books.description_id
Buffers: shared hit=64 read=22947
I/O Timings: shared/local read=172.311
Settings: enable_hashjoin = 'off', hash_mem_multiplier = '1', work_mem = '1MB'
Planning:
Buffers: shared hit=10 read=9
I/O Timings: shared/local read=90.112
Planning Time: 90.774 ms
Execution Time: 13955.462 ms
(29 rows)

Regards,
Dimitris