Go基准测试中查询缓慢，但psql执行相同查询极快的问题排查

在Go 1.19、Gorm与PostgreSQL 14.5环境下开展基准测试：先清空shipping_method_costs和shipping_methods表，批量创建10万条shipping_methods记录，随后调用AvailableShippingMethods方法查询符合条件的配送方式。基准测试中，查询shipping_methods的SQL平均耗时约70ms，但在psql中用EXPLAIN(ANALYSE)执行相同查询时，执行时间仅0.323ms。另外，若在b.Run前添加1分钟time.Sleep，基准测试中的查询时间会降至1ms。请问这一差异的原因是什么？是否与缓存或后台索引计算有关？

基准测试代码 #

func BenchmarkAvailableShippingMethods(b *testing.B) {
        err := DB.Exec("DELETE FROM shipping_method_costs").Error
        if err != nil {
            b.Fatal(err)
        }
        err = DB.Exec("DELETE FROM shipping_methods").Error
        if err != nil {
            b.Fatal(err)
        }

        user := factories.ItalianUser(DB)
        factories.CreateManyShippingMethods(DB, 100_000, user.ID) // create 100000 records in bulk

        // time.Sleep(time.Minute)

        b.Run("benchmark", func(b *testing.B) {
            b.ResetTimer()
            for i := 0; i < b.N; i++ {
                b.StartTimer()
                availableShippingMethods, err := usr.AvailableShippingMethods(DB, user)
                b.StopTimer()
                if err != nil {
                    b.Fatal(err)
                }
                b.Logf("Available shipping methods found are %d", len(availableShippingMethods))
            }
        })
    })
}

基准测试SQL耗时日志 #

[71.786ms] [rows:4] SELECT "shipping_methods"."id","shipping_methods"."user_id","shipping_methods"."enabled","shipping_methods"."name","shipping_methods"."from_countries","shipping_methods"."to_countries","shipping_methods"."min_estimate_shipping_days","shipping_methods"."max_estimate_shipping_days","shipping_methods"."parcel","shipping_methods"."tracked","shipping_methods"."tracking_link","shipping_methods"."free_shipping_threshold_cents","shipping_methods"."free_shipping_threshold_quantity","shipping_methods"."max_cart_subtotal_cents","shipping_methods"."currency","shipping_methods"."created_at","shipping_methods"."updated_at" FROM "shipping_methods" INNER JOIN user_shipping_methods ON user_shipping_methods.shipping_method_id = shipping_methods.id INNER JOIN users ON user_shipping_methods.user_id = users.id WHERE users.id = 200054 AND enabled = 't' AND from_countries @> '"IT"' AND to_countries @> '"ES"'

psql执行计划结果 #

Nested Loop  (cost=20.92..77.41 rows=4 width=193) (actual time=0.237..0.278 rows=4 loops=1)
   ->  Index Only Scan using users_pkey on users  (cost=0.42..8.44 rows=1 width=4) (actual time=0.011..0.012 rows=1 loops=1)
         Index Cond: (id = 200054)
         Heap Fetches: 1
   ->  Nested Loop  (cost=20.50..68.93 rows=4 width=201) (actual time=0.222..0.262 rows=4 loops=1)
         ->  Bitmap Heap Scan on shipping_methods  (cost=20.08..51.18 rows=4 width=193) (actual time=0.136..0.160 rows=4 loops=1)
               Recheck Cond: ((from_countries @> '"IT"'::jsonb) AND (to_countries @> '"ES"'::jsonb))
               Filter: enabled
               Rows Removed by Filter: 7
               Heap Blocks: exact=11
               ->  Bitmap Index Scan on shipping_methods_enabled_from_countries_to_countries_idx1  (cost=0.00..20.08 rows=8 width=0) (actual time=0.128..0.128 rows=11 loops=1)
                     Index Cond: ((from_countries @> '"IT"'::jsonb) AND (to_countries @> '"ES"'::jsonb))
         ->  Index Only Scan using user_shipping_methods_user_id_shipping_method_id_idx on user_shipping_methods  (cost=0.42..4.44 rows=1 width=16) (actual time=0.024..0.024 rows=1 loops=4)
               Index Cond: ((user_id = 200054) AND (shipping_method_id = shipping_methods.id))
               Heap Fetches: 0
 Planning Time: 0.444 ms
 Execution Time: 0.323 ms

• 磁盘IO与缓存预热差异：批量插入10万条数据后，相关的表数据页、索引页都存储在磁盘上，尚未加载到PostgreSQL的shared_buffers或操作系统的页缓存中。基准测试直接执行查询时，需要从磁盘读取这些数据，磁盘IO的高耗时直接导致查询平均70ms。添加1分钟sleep后，操作系统会自动将高频访问的磁盘页缓存到内存，后续查询直接从内存读取，耗时降至1ms。而psql执行时，要么基准测试已经完成了缓存预热，要么间隔时间足够让缓存生效，因此执行时间仅0.323ms。

• PostgreSQL后台统计信息更新：批量插入大量数据后，PostgreSQL的autovacuum进程需要时间更新表的统计信息（用于查询优化器生成最优计划）。刚插入数据时，优化器可能基于旧统计信息执行，但sleep过程中autovacuum完成统计更新，确保优化器选择最优索引执行计划，进一步提升查询效率。

• 索引碎片后台整理：批量插入数据会导致索引产生碎片，PostgreSQL的后台进程会在空闲时间（比如sleep的1分钟内）对索引进行整理，减少后续查询时的索引遍历开销，这也是sleep后查询提速的辅助因素。

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