PostgreSQL：EXPLAIN ANALYZE实际时间与规划时间差异过大问题咨询

问题描述 #

部分查询的执行时间随请求量增加持续变长。高负载下执行EXPLAIN ANALYZE后，规划时间约9秒，执行时间仅1秒，但所有actual time相加总和远达不到9秒，且查询无多循环情况。以下是EXPLAIN ANALYZE结果：

Nested Loop Left Join  (cost=26304.72..35480113.45 rows=624544385412 width=1843) (actual time=0.277..0.284 rows=1 loops=1)
  ->  Nested Loop  (cost=26304.15..907648.85 rows=320874 width=1495) (actual time=0.215..0.218 rows=1 loops=1)
        ->  Index Scan using idx_info_part_13_test_id on test_part_13 "Model"  (cost=0.69..8.71 rows=1 width=976) (actual time=0.140..0.142 rows=1 loops=1)
              Index Cond: ((test_id)::text = 'sjbvas6dsad4sad7asda7sd567as5f7dsdf75sdfsdf6sdf5sfas78d6fdsdsada'::text)
        ->  Bitmap Heap Scan on outputs_p_33 "Model"  (cost=26303.46..904431.40 rows=320874 width=519) (actual time=0.060..0.061 rows=1 loops=1)
              Recheck Cond: ((test_id)::text = 'sjbvas6dsad4sad7asda7sd567as5f7dsdf75sdfsdf6sdf5sfas78d6fdsdsada'::text)
              Heap Blocks: exact=1
              ->  Bitmap Index Scan on pk_test_p_33  (cost=0.00..26223.24 rows=320874 width=0) (actual time=0.055..0.055 rows=1 loops=1)
                    Index Cond: ((test_id)::text = 'sjbvas6dsad4sad7asda7sd567as5f7dsdf75sdfsdf6sdf5sfas78d6fdsdsada'::text)
  ->  Append  (cost=0.56..107.54 rows=20 width=348) (actual time=0.046..0.049 rows=1 loops=1)
        ->  Index Scan using addresses_part_0_address_id_idx on addresses_part_0 "ModelType"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_1_address_id_idx on addresses_part_1 "ModelType_1"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_2_address_id_idx on addresses_part_2 "ModelType_2"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_3_address_id_idx on addresses_part_3 "ModelType_3"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_4_address_id_idx on addresses_part_4 "ModelType_4"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_5_address_id_idx on addresses_part_5 "ModelType_5"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_6_address_id_idx on addresses_part_6 "ModelType_6"  (cost=0.56..5.37 rows=1 width=348) (actual time=0.042..0.042 rows=1 loops=1)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_7_address_id_idx on addresses_part_7 "ModelType_7"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_8_address_id_idx on addresses_part_8 "ModelType_8"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_9_address_id_idx on addresses_part_9 "ModelType_9"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_10_address_id_idx on addresses_part_10 "ModelType_10"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_11_address_id_idx on addresses_part_11 "ModelType_11"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_12_address_id_idx on addresses_part_12 "ModelType_12"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_13_address_id_idx on addresses_part_13 "ModelType_13"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_14_address_id_idx on addresses_part_14 "ModelType_14"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_15_address_id_idx on addresses_part_15 "ModelType_15"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_16_address_id_idx on addresses_part_16 "ModelType_16"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_17_address_id_idx on addresses_part_17 "ModelType_17"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_18_address_id_idx on addresses_part_18 "ModelType_18"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
        ->  Index Scan using addresses_part_19_address_id_idx on addresses_part_19 "ModelType_19"  (cost=0.56..5.37 rows=1 width=348) (never executed)
              Index Cond: ((address_id)::text = ("Model".address_id)::text)
Planning Time: 9127.562 ms
Execution Time: 1.090 ms

原因分析 #

1. 规划与执行阶段的统计范围完全分离 #

actual time仅统计执行阶段的耗时，规划阶段的大量工作不会被计入其中：

• 分区元数据遍历：查询涉及20个addresses_part分区，规划器需要逐个读取每个分区的表结构、索引定义、统计信息等元数据，高负载下元数据的访问可能因锁竞争或缓存失效变慢。
• 多计划评估：规划器会尝试多种连接顺序、扫描策略，计算每种计划的成本，这个过程在多分区场景下计算量会大幅增加，尤其是统计信息复杂时。
• 统计信息加载：规划器需要加载表和索引的统计数据来估算行数与成本，若统计信息需从磁盘读取或在共享缓存中竞争获取，高负载下会显著增加耗时。

2. 高负载放大规划阶段的资源竞争 #

高负载场景下，数据库CPU、内存、IO资源被大量请求占用：

• 规划阶段需要CPU进行成本计算和计划评估，此时CPU可能被其他查询的执行阶段占满，导致规划进程频繁等待调度。
• 共享内存中的元数据缓存（如表缓存、索引缓存）可能被其他查询操作驱逐，规划器需重新从磁盘读取元数据，增加IO等待时长。

3. 分区表的规划固有开销 #

使用Append节点的分区表，规划器需要为每个分区单独生成扫描计划并评估成本，即便大部分分区最终不会执行（如结果中19个分区标记为never executed），规划阶段仍需完成全部流程，这部分开销全部计入规划时间，但不会体现在执行阶段的actual time中。

解决方案建议 #

• 启用pg_stat_statements扩展，跟踪查询的规划与执行时间趋势，确认是否仅特定查询出现规划时间飙升。
• 定期执行ANALYZE命令更新分区表的统计信息，帮助规划器快速生成合理计划。
• 若查询参数变化不大，调整plan_cache_mode为force_generic_plan，强制使用通用计划避免重复规划。
• 优化分区策略，减少不必要的分区数量，或使用声明式分区替代传统分区表，降低元数据处理开销。
• 检查数据库资源使用情况，确保高负载下有足够CPU和内存分配给规划进程。

内容的提问来源于stack exchange，提问作者Dragos Cazangiu