Inaccurate buffers output for cold cache queries
- Dominant language
- C
- Stars
- 12.8k
- Forks
- 794
- Avg merge
- 2d 14h
- Merged PRs (30d)
- 31
Description
EXPLAIN (ANALYZE,BUFFERS) shows information indicating that it read from shared buffers even when this is demonstrably false. I do not know if this means that there are larger issues with shared buffer usage.
Steps to reproduce:
1. Create simple table and load data. I used 2GB of data (4GB loaded) in a 3 column table, all columns random 5 digit integers.
2. Stop Postgres on workers and coordinator
3. Run `echo 3 > /proc/sys/vm/drop_caches` to invalidate PG cache
4. Restart all machines to remove OS level caching
5. Run EXPLAIN (ANALYZE,BUFFERS) for simple aggregate query
6. Note shared hit in buffers
7. Repeat steps 2-4
8. Run corresponding aggregate on one worker
9. Note that there is a 100% cache miss.
Coordinator explain plan:
```
citus=> explain (analyze,buffers) select count(*) from random_test ;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=0.00..0.00 rows=0 width=0) (actual time=16230.954..16230.955 rows=1 loops=1)
Buffers: shared hit=18
-> Custom Scan (Citus Adaptive) (cost=0.00..0.00 rows=0 width=0) (actual time=16230.936..16230.940 rows=32 loops=1)
Task Count: 32
Tasks Shown: One of 32
-> Task
Node: host=ec2-3-233-55-61.compute-1.amazonaws.com port=5432 dbname=citus
-> Finalize Aggregate (cost=33533.85..33533.86 rows=1 width=8) (actual time=208.790..208.790 rows=1 loops=1)
Buffers: shared hit=14230 read=2339
I/O Timings: read=11.574
-> Gather (cost=33533.64..33533.85 rows=2 width=8) (actual time=206.965..208.828 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=14230 read=2339
I/O Timings: read=11.574
-> Partial Aggregate (cost=32533.64..32533.65 rows=1 width=8) (actual time=202.308..202.309 rows=1 loops=3)
Buffers: shared hit=14230 read=2339
I/O Timings: read=11.574
-> Parallel Seq Scan on random_test_102040 random_test (cost=0.00..29340.71 rows=1277171 width=0) (actual time=0.017..109.718 rows=1021737 loops=3)
Buffers: shared hit=14230 read=2339
I/O Timings: read=11.574
Planning Time: 0.071 ms
Execution Time: 208.877 ms
Buffers: shared hit=18
Planning Time: 0.516 ms
Execution Time: 16230.994 ms
(26 rows)
```
Corresponding worker explain plan after buffers are re-reset:
```
citus=# explain (analyze,buffers) select count(*) from random_test_102049;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------
-----------------------------------------
Finalize Aggregate (cost=34776.49..34776.50 rows=1 width=8) (actual time=1048.802..1048.802 rows=1 loops=1)
Buffers: shared read=17202
I/O Timings: read=2704.315
-> Gather (cost=34776.28..34776.49 rows=2 width=8) (actual time=1047.305..1048.850 rows=3 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared read=17202
I/O Timings: read=2704.315
-> Partial Aggregate (cost=33776.28..33776.29 rows=1 width=8) (actual time=1042.933..1042.934 rows=1
loops=3)
Buffers: shared read=17202
I/O Timings: read=2704.315
-> Parallel Seq Scan on random_test_102049 (cost=0.00..30461.42 rows=1325942 width=0) (actual t
ime=0.606..981.423 rows=1060754 loops=3)
Buffers: shared read=17202
I/O Timings: read=2704.315
Planning Time: 1.670 ms
Execution Time: 1048.937 ms
(16 rows)
```
Contributor guide
Assessment
This issue has not been assessed yet.