Azure PostgreSQL单服务器Bitmap Heap Scan读I/O耗时过长问题排查

环境与背景 #

• 部署环境：Azure PostgreSQL单服务器（Basic规格），PostgreSQL 11
• 硬件配置：2vCore、4GB内存、1TB存储，IOPS为Variable
• 表结构：10张非日志表（Unlogged table），每张表0.5-10亿行数据，采用范围+哈希二级分区（10个范围分区×10个哈希分区=100个分区）
• 数据导入：从CSV文件批量导入，查询依赖的id列已创建B-tree索引

查询性能表现 #

1. 首次查询耗时集中在磁盘I/O #

测试查询的耗时几乎全部来自磁盘读取阶段：

postgres=> EXPLAIN (ANALYZE, BUFFERS) select count(*) from table_id4 where id=244730;
                                                                          QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=7458.09..7458.10 rows=1 width=8) (actual time=21141.393..21141.396 rows=1 loops=1)
   Buffers: shared read=2256
   I/O Timings: read=21096.814
   ->  Append  (cost=41.26..7452.66 rows=2171 width=0) (actual time=197.168..21138.495 rows=2247 loops=1)
         Buffers: shared read=2256
         I/O Timings: read=21096.814
         ->  Bitmap Heap Scan on table_id4_r2_h5  (cost=41.26..7441.80 rows=2171 width=0) (actual time=197.167..21137.471 rows=2247 loops=1)
               Recheck Cond: (id = 244730)
               Heap Blocks: exact=2247
               Buffers: shared read=2256
               I/O Timings: read=21096.814
               ->  Bitmap Index Scan on table_id4_r2_h5_id_idx  (cost=0.00..40.72 rows=2171 width=0) (actual time=117.586..117.586 rows=2247 loops=1)
                     Index Cond: (id = 244730)
                     Buffers: shared read=9
                     I/O Timings: read=116.929
 Planning Time: 2.882 ms
 Execution Time: 21141.449 ms
(17 rows)

2. 调整执行计划后仍偶发缓慢 #

执行ANALYZE table_name更新统计信息，并设置set enable_bitmapscan= OFF;后，查询计划切换为Index Only Scan，但仍存在大量磁盘I/O（Heap Fetches等于返回行数），耗时依旧很高：

postgres=> EXPLAIN (ANALYZE, BUFFERS) select count(*) from table_id2 where id=179863;
                                                                                       QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=5528.78..5528.79 rows=1 width=8) (actual time=24273.748..24273.749 rows=1 loops=1)
   Buffers: shared read=1943
   I/O Timings: read=24218.684
   ->  Append  (cost=0.42..5523.93 rows=1940 width=0) (actual time=83.735..24271.326 rows=1959 loops=1)
         Buffers: shared read=1943
         I/O Timings: read=24218.684
         ->  Index Only Scan using table_id2_r10_h5_id_idx on table_id2_r10_h5  (cost=0.42..5514.23 rows=1940 width=0) (actual time=83.734..24270.157 rows=1959 loops=1)
               Index Cond: (id = 179863)
               Heap Fetches: 1959
               Buffers: shared read=1943
               I/O Timings: read=24218.684
 Planning Time: 3.254 ms
 Execution Time: 24273.787 ms
(13 rows)

3. 查询时间波动极大，缓存后恢复正常 #

批量随机查询时，耗时从几百毫秒到几十秒波动：

FOR idx IN SELECT (random()*total_IDs)::int AS id from generate_series (1,10)
LOOP ... 
select count(*) from table_id4 where id=idx;  
...
END LOOP;
NOTICE:   id: 321158 count#: 2154,   time: 46.734967s
NOTICE:   id: 487596 count#: 2238,   time: 0.968759s
NOTICE:   id: 548334 count#: 2180,   time: 1.062516s
NOTICE:   id: 404978 count#: 2179,   time: 29.750295s
NOTICE:   id: 370904 count#: 2123,   time: 22.203384s
NOTICE:   id: 228857 count#: 2223,   time: 29.094126s
NOTICE:   id: 327134 count#: 2169,   time: 24.750242s
NOTICE:   id: 372101 count#: 2180,   time: 28.062825s
NOTICE:   id: 341814 count#: 2130,   time: 30.250353s
NOTICE:   id: 248316 count#: 2195,   time: 32.375377s

但重复查询同一id时，耗时恢复至毫秒级：

psql -c " ...
select count(*) from table_id4 where id=321158;
select count(*) from table_id4 where id=487596;
select count(*) from table_id4 where id=548334;
select count(*) from table_id4 where id=404978;
select count(*) from table_id4 where id=370904;
select count(*) from table_id4 where id=228857;
"
Time: 5267.168 ms (00:05.267)
Time: 171.925 ms
Time: 24.942 ms
Time: 11.387 ms
Time: 6.753 ms
Time: 17.573 ms

关键观察 #

• 原库（同Basic规格，600GB存储）同表查询耗时<1秒，其EXPLAIN显示Buffers: shared hit=4479 read=21，缓存命中率远高于当前库
• 当前库资源充足：存储使用率55%、内存使用率30%、CPU使用率<5%
• 部分参数配置：shared_buffers=512MB，work_mem已从4MB调整为256MB无改善

疑问 #

1. 为何当前库冷查询耗时远超原库，且查询波动极大？
2. 在执行可能耗时数天的REINDEX或VACUUM操作前，问题根源是什么？
3. 将表改为LOGGED或执行ENABLE TRIGGER ALL是否能改善性能？

内容的提问来源于stack exchange，提问作者Happy Life