I have the following benchmark in Go 1.19 and Gorm with Postgresql 14.5:
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))
}
})
})
}
Now when I run the benchmark I can see the following logs:
...
2022/09/21 06:32:31 /Users/pioz/Code/go/src/github.com/pioz/ct/usr/shipping_method.go:141
[0.265ms] [rows:12] SELECT * FROM "shipping_method_costs" WHERE "shipping_method_costs"."shipping_method_id" IN (3204275,3231642,3270298,3276705)
2022/09/21 06:32:31 /Users/pioz/Code/go/src/github.com/pioz/ct/usr/shipping_method.go:141
[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"'
2022/09/21 06:32:31 /Users/pioz/Code/go/src/github.com/pioz/ct/usr/shipping_method.go:141
[0.410ms] [rows:12] SELECT * FROM "shipping_method_costs" WHERE "shipping_method_costs"."shipping_method_id" IN (3204275,3231642,3270298,3276705)
2022/09/21 06:32:31 /Users/pioz/Code/go/src/github.com/pioz/ct/usr/shipping_method.go:141
[70.845ms] [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"'
15 73876214 ns/op
--- BENCH: BenchmarkAvailableShippingMethods/benchmark-10
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
shipping_method_test.go:419: Available shipping methods found are 4
... [output truncated]
PASS
The big query to retrieve the shipping_methods records on this benchmark takes an average time of ~70ms. BUT if I run the same query (with EXPLAIN(ANALYSE)) on psql I can see this:
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
The execution time is less than 1ms. How is possible? What am I missing? Is cache related issue?
I've also noticed that if I add a time.Sleep of 1 minute before the b.Run call the query time goes from 70ms to 1ms (are indices calculated in background??).