为什么collection.InsertOne插入第一个元素这么慢？

Question

I'm testing the new official MongoDB driver for Go, and I noticed that the first call to collection.InsertOne always takes a ton of time, while all subsequent calls to it are blazingly fast. Why? And how to avoid this disruptive behavior?

package main

import (
    "context"
    "log"
    "time"

    "go.mongodb.org/mongo-driver/mongo"
    "go.mongodb.org/mongo-driver/mongo/options"
)

type Trainer struct {
    Name string
    Age  int
    City string
}

func main() {

    t1 := time.Now()

    // Set client options
    clientOptions := options.Client().ApplyURI("mongodb://localhost:27017")

    log.Println("Setting client options took", time.Now().Sub(t1))
    t1 = time.Now()

    // Connect to MongoDB
    client, err := mongo.Connect(context.TODO(), clientOptions)
    if err != nil {
        log.Fatal(err)
    }

    log.Println("Connecting took", time.Now().Sub(t1))
    t1 = time.Now()

    // Some dummy data to add to the Database
    ash := Trainer{"Ash", 30, "Pallet Town"}

    // Get a handle for your collection
    collection := client.Database("test").Collection("trainers")
    // Insert a single document

    log.Println("Getting the collection took", time.Now().Sub(t1))
    t1 = time.Now()

    for i := 0; i < 10; i++ {
        _, err := collection.InsertOne(context.TODO(), ash)
        if err != nil {
            log.Fatal(err)
        }
        log.Println("Inserting document took", time.Now().Sub(t1))
        t1 = time.Now()
    }

    err = client.Disconnect(context.TODO())

}

I expected all insert operations to take milliseconds or nanoseconds, while the first one takes about 0.6 seconds. Here's the log with timing:

2019/07/31 17:41:39 Setting client options took 0s
2019/07/31 17:41:39 Connecting took 0s
2019/07/31 17:41:39 Getting the collection took 0s
2019/07/31 17:41:40 Inserting document took 606.0339ms
2019/07/31 17:41:40 Inserting document took 0s
2019/07/31 17:41:40 Inserting document took 0s
2019/07/31 17:41:40 Inserting document took 0s
2019/07/31 17:41:40 Inserting document took 0s
2019/07/31 17:41:40 Inserting document took 0s
2019/07/31 17:41:40 Inserting document took 875.2µs
2019/07/31 17:41:40 Inserting document took 0s
2019/07/31 17:41:40 Inserting document took 0s
2019/07/31 17:41:40 Inserting document took 0s

Answer 1

Just to close out the question from the comments:

The MongoDB driver uses a lazy connection. See the MongoDB docs, specifically:

Calling Connect does not block for server discovery. If you wish to know if a MongoDB server has been found and connected to, use the Ping method:

ctx, _ = context.WithTimeout(context.Background(), 2*time.Second)
err = client.Ping(ctx, readpref.Primary())

This will force a connect and remove the insert delay from your first insert.