title: Slow query on Golang benchmark, but fast from psql
body: <p>I have the following benchmark in Go 1.19 and <a href="https://gorm.io/" rel="nofollow noreferrer">Gorm</a> with Postgresql 14.5:</p>
  <pre class="lang-golang prettyprint-override"><code>func BenchmarkAvailableShippingMethods(b *testing.B) {
          err := DB.Exec(&quot;DELETE FROM shipping_method_costs&quot;).Error
          if err != nil {
              b.Fatal(err)
          }
          err = DB.Exec(&quot;DELETE FROM shipping_methods&quot;).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(&quot;benchmark&quot;, func(b *testing.B) {
              b.ResetTimer()
              for i := 0; i &lt; b.N; i++ {
                  b.StartTimer()
                  availableShippingMethods, err := usr.AvailableShippingMethods(DB, user)
                  b.StopTimer()
                  if err != nil {
                      b.Fatal(err)
                  }
                  b.Logf(&quot;Available shipping methods found are %d&quot;, len(availableShippingMethods))
              }
          })
      })
  }
  
  </code></pre>
  <p>Now when I run the benchmark I can see the following logs:</p>
  <pre><code>...
  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 &quot;shipping_method_costs&quot; WHERE &quot;shipping_method_costs&quot;.&quot;shipping_method_id&quot; 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 &quot;shipping_methods&quot;.&quot;id&quot;,&quot;shipping_methods&quot;.&quot;user_id&quot;,&quot;shipping_methods&quot;.&quot;enabled&quot;,&quot;shipping_methods&quot;.&quot;name&quot;,&quot;shipping_methods&quot;.&quot;from_countries&quot;,&quot;shipping_methods&quot;.&quot;to_countries&quot;,&quot;shipping_methods&quot;.&quot;min_estimate_shipping_days&quot;,&quot;shipping_methods&quot;.&quot;max_estimate_shipping_days&quot;,&quot;shipping_methods&quot;.&quot;parcel&quot;,&quot;shipping_methods&quot;.&quot;tracked&quot;,&quot;shipping_methods&quot;.&quot;tracking_link&quot;,&quot;shipping_methods&quot;.&quot;free_shipping_threshold_cents&quot;,&quot;shipping_methods&quot;.&quot;free_shipping_threshold_quantity&quot;,&quot;shipping_methods&quot;.&quot;max_cart_subtotal_cents&quot;,&quot;shipping_methods&quot;.&quot;currency&quot;,&quot;shipping_methods&quot;.&quot;created_at&quot;,&quot;shipping_methods&quot;.&quot;updated_at&quot; FROM &quot;shipping_methods&quot; 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 @&gt; '&quot;IT&quot;' AND to_countries @&gt; '&quot;ES&quot;'
  
  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 &quot;shipping_method_costs&quot; WHERE &quot;shipping_method_costs&quot;.&quot;shipping_method_id&quot; 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 &quot;shipping_methods&quot;.&quot;id&quot;,&quot;shipping_methods&quot;.&quot;user_id&quot;,&quot;shipping_methods&quot;.&quot;enabled&quot;,&quot;shipping_methods&quot;.&quot;name&quot;,&quot;shipping_methods&quot;.&quot;from_countries&quot;,&quot;shipping_methods&quot;.&quot;to_countries&quot;,&quot;shipping_methods&quot;.&quot;min_estimate_shipping_days&quot;,&quot;shipping_methods&quot;.&quot;max_estimate_shipping_days&quot;,&quot;shipping_methods&quot;.&quot;parcel&quot;,&quot;shipping_methods&quot;.&quot;tracked&quot;,&quot;shipping_methods&quot;.&quot;tracking_link&quot;,&quot;shipping_methods&quot;.&quot;free_shipping_threshold_cents&quot;,&quot;shipping_methods&quot;.&quot;free_shipping_threshold_quantity&quot;,&quot;shipping_methods&quot;.&quot;max_cart_subtotal_cents&quot;,&quot;shipping_methods&quot;.&quot;currency&quot;,&quot;shipping_methods&quot;.&quot;created_at&quot;,&quot;shipping_methods&quot;.&quot;updated_at&quot; FROM &quot;shipping_methods&quot; 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 @&gt; '&quot;IT&quot;' AND to_countries @&gt; '&quot;ES&quot;'
        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
  </code></pre>
  <p>The big query to retrieve the <code>shipping_methods</code> records on this benchmark takes an average time of ~70ms. BUT if I run the same query (with <code>EXPLAIN(ANALYSE)</code>) on <code>psql</code> I can see this:</p>
  <pre><code> Nested Loop  (cost=20.92..77.41 rows=4 width=193) (actual time=0.237..0.278 rows=4 loops=1)
     -&gt;  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
     -&gt;  Nested Loop  (cost=20.50..68.93 rows=4 width=201) (actual time=0.222..0.262 rows=4 loops=1)
           -&gt;  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 @&gt; '&quot;IT&quot;'::jsonb) AND (to_countries @&gt; '&quot;ES&quot;'::jsonb))
                 Filter: enabled
                 Rows Removed by Filter: 7
                 Heap Blocks: exact=11
                 -&gt;  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 @&gt; '&quot;IT&quot;'::jsonb) AND (to_countries @&gt; '&quot;ES&quot;'::jsonb))
           -&gt;  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
  
  </code></pre>
  <p>The execution time is less than 1ms. How is possible? What am I missing? Is cache related issue?</p>
  <p>I've also noticed that if I add a <code>time.Sleep</code> of 1 minute before the <code>b.Run</code> call the query time goes from 70ms to 1ms (are indices calculated in background??).</p>