database/sql and Connection Pools

A service runs clean for three months and then one Tuesday the p99 goes to eleven seconds while the database CPU sits at four percent. Nothing was deployed. What changed is concurrency: a marketing push doubled the number of simultaneous requests, and the pool settings nobody wrote down finally mattered. The connections were there. The pool had a hundred of them open, most of them idle, and the requests were not short of capacity. They were short of configuration.

sql.DB is the thing everyone misreads on first contact. The name says database, the type is a struct you can pass around, and the first handler that uses it looks like it holds one connection to MySQL. It holds none until it needs one, and then it holds as many as it decides you need, up to a limit you never set. Everything in this lesson comes from taking that sentence seriously.

sql.Open returns a pool that has not dialled anything

The function that catches people is sql.Open, because its error return looks like a connection failure and is almost never one. It validates the driver name and parses the DSN; that is the whole job. No socket is opened, no handshake happens, and the error is nil even when MySQL is down. A program that opens the database, logs "connected", and then serves traffic will discover the outage on the first query instead of at startup.

Ping and PingContext are what turn that into a real check. They ask the pool for a connection, which dials one if there is none, and send a packet the server has to answer. Watch the counters either side of the call:

db, err := sql.Open("mysql", dsn)
if err != nil {
	log.Fatal(err) // wrong driver name or malformed DSN, not an outage
}
fmt.Println("after Open: ", db.Stats())

ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second)
defer cancel()
start := time.Now()
if err := db.PingContext(ctx); err != nil {
	log.Fatal(err)
}
fmt.Printf("PingContext took %v\n", time.Since(start).Round(time.Microsecond))
fmt.Println("after Ping: ", db.Stats())

after Open:  {0 0 0 0 0 0s 0 0 0}
PingContext took 1.592ms
after Ping:  {0 1 0 1 0 0s 0 0 0}
server version: 9.6.0

Nine zeroes before the ping and a one in the second position after it. That second number is OpenConnections, and the ping is the reason it exists. MySQL 9.6.0 answered in 1.6 milliseconds, so the pool paid one TCP connect and one authentication and now has a warm connection to reuse. A PingContext with a three-second deadline is a sensible startup check: fail fast and loudly at boot rather than on the first customer request.

Three settings decide what the pool does under load

Left alone, the pool has no upper bound, keeps two idle connections, and never retires one. That is a considered default for a script and a poor one for a service. Three calls change it, and each one exists because of a specific way production breaks:

db.SetMaxOpenConns(20)                  // cap on connections in use at once
db.SetMaxIdleConns(20)                  // cap on connections kept after use
db.SetConnMaxLifetime(5 * time.Minute)  // retire a connection after this long
db.SetConnMaxIdleTime(2 * time.Minute)  // retire one that has sat unused

The two most common mistakes are opposites. Setting MaxIdleConns below MaxOpenConns means the pool closes connections it just paid to open: in the run below, a burst of eight queries against an idle limit of one leaves MaxIdleClosed=7 after the first burst and 14 after the second. The pool never grows past one connection, and every burst pays the handshake again. Setting MaxOpenConns very high is the other mistake, and it is invisible until a bad day, because the database is the thing that runs out, not your process.

A cap is a queue, and the queue is visible in db.Stats

Sixteen concurrent queries that each take 200 milliseconds, once with the pool capped at four connections and once with Go's default of unlimited:

capped pool: SetMaxOpenConns(4), 16 concurrent 200ms queries
  wall clock            1.108s
  fastest / median / slowest query   288ms / 780ms / 1.108s
  peak open / peak in use            4 / 4
  wait count / wait duration         12 / 6.649s

unlimited pool: SetMaxOpenConns(0), 16 concurrent 200ms queries
  wall clock            281ms
  fastest / median / slowest query   247ms / 280ms / 281ms
  peak open / peak in use            16 / 16
  wait count / wait duration         0 / 0s

The capped run is slower and that is the point. Total wall clock is 1.1 seconds because four connections at 200 milliseconds each can only drain sixteen queries in four waves. The slowest request waited 1.087 seconds, and WaitDuration of 6.649 seconds is that waiting summed across all twelve requests that had to queue. The unlimited run finishes in 281 milliseconds with sixteen sockets open on the server at once. Multiply that by every instance behind your load balancer before deciding the cap is unnecessary.

Read those counters in a running service and the diagnosis is immediate. WaitCount rising while InUse equals MaxOpenConnections means requests are queueing for the database, which could be a slow query holding a connection, a cap set too low for the traffic, or one handler that forgot to return a connection. InUse pinned at the cap with WaitDuration climbing faster than the traffic is the signature of a leak, and the leak is the next section.

Query needs a Close and QueryRow does not

Query returns a *sql.Rows that holds a connection until you close it or read to the end of the result set. QueryRow returns a *sql.Row with no close method, because it closes the underlying rows as soon as Scan returns. That asymmetry is safe to ignore right up until it stops being safe, and then it takes the pool down silently.

// The bug, in full. Four concurrent requests against a pool capped at two.
func handlerQuery(db *sql.DB) (int, error) {
	rows, err := db.Query("SELECT id FROM accounts")
	if err != nil {
		return 0, err
	}
	// defer rows.Close() is missing here
	if rows.Next() {
		var got int
		if err := rows.Scan(&got); err != nil {
			return 0, err
		}
		return got, nil
	}
	return 0, rows.Err()
}

request 0: id=1
request 2: id=1
3s in: open=2 inUse=2 idle=0 waitCount=2 - nothing can progress
a new request gave up after 501ms with err=context deadline exceeded

Two requests leaked both connections in the pool, and the other two waited forever. The new request that arrived with a 500 millisecond deadline got context deadline exceeded, an error that reads like a slow database and is nothing of the sort. Worse, the process was not stuck: the garbage collector eventually finalises an unreachable *sql.Rows and returns the connection, so the symptom comes and goes with allocation timing. Delete one comment and the same four requests finish immediately:

all four requests finished
request 0: id=1
request 1: id=1
request 2: id=1
request 3: id=1

The habit that prevents all of it: if the method name is Query, QueryContext or Prepare, the next line closes what it returned. In a loop, do not defer the close inside the loop body, because the connections accumulate until the function returns. Close each one at the end of its iteration, or wrap the body in a function of its own.

A Ping, a ConnMaxLifetime and a closed Rows all have tests, but the one that catches everything is db.Stats() printed periodically from a background goroutine. It costs nothing and it is the only view you get into a component that otherwise fails by going quiet.

The pool is the shareable thing; a transaction is not

The documentation is explicit in one direction: sql.Open returns a *sql.DB that "is safe for concurrent use by multiple goroutines", and a *sql.Stmt carries the same guarantee. Everything a handler needs to share, it can share. Go's own documentation makes no such promise for *sql.Tx or *sql.Rows, and the reason is in the structure: both are bound to one connection, and one connection runs one statement at a time. Passing a transaction into a second goroutine while the first keeps using it interleaves two statements on one wire, and what the driver makes of that is not something you want to find out during an incident.

The rule to carry into the next two lessons is short. Share the *sql.DB as far as you like, and keep the *sql.Tx inside the function that began it, since it is a handle on one connection rather than on the pool.

Log the pool, or find out about it from a graph six hours late

Nothing in the previous section reports itself. A pool that has run out of usable connections is quiet by construction: no error is returned, no goroutine panics, and the database reports a normal number of queries because the queries stopped arriving. The only place the situation is visible is db.Stats(), and the only way it is visible at the right moment is if something prints it on a timer.

func logPool(ctx context.Context, db *sql.DB, every time.Duration) {
	t := time.NewTicker(every)
	defer t.Stop()
	for {
		select {
		case <-ctx.Done():
			return
		case <-t.C:
			s := db.Stats()
			log.Printf("db: open=%d inUse=%d idle=%d maxOpen=%d wait=%d waited=%v lifetimeClosed=%d",
				s.OpenConnections, s.InUse, s.Idle, s.MaxOpenConnections,
				s.WaitCount, s.WaitDuration.Round(time.Millisecond), s.MaxLifetimeClosed)
		}
	}
}

A snapshot once every thirty seconds costs four microseconds and answers the three questions you will actually have. Running that logger against four sequential 150 millisecond queries prints a line like this for every interval, and the shape is what matters rather than the numbers:

db: open=1 inUse=1 idle=0 maxOpen=4 wait=0 waited=0s lifetimeClosed=0
db: open=1 inUse=1 idle=0 maxOpen=4 wait=0 waited=0s lifetimeClosed=0
db: open=1 inUse=0 idle=1 maxOpen=4 wait=0 waited=0s lifetimeClosed=0

open - (idle + inUse) is the count of connections in transit, so a persistent gap there means connections are being opened and discarded rather than retained. inUse pinned at maxOpen with wait climbing means the cap is the bottleneck rather than the database, and lifetimeClosed advancing every interval means connections are being replaced faster than they are being used, which points at a lifetime that is too short for the workload.

The counters are also the cheapest way to prove a fix. A leak shows as inUse climbing by one per failed request and never coming back down; after the Close is added, the same load leaves inUse oscillating around the concurrency of the workload and WaitCount static. That difference, in one log line per interval, is worth more than any amount of reasoning about what the code should be doing.

db, err := sql.Open("mysql", dsn)
if err != nil {
	return err
}
db.SetMaxOpenConns(4)
db.SetMaxIdleConns(4)
db.SetConnMaxLifetime(time.Minute)

ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second)
defer cancel()
if err := db.PingContext(ctx); err != nil {
	return err
}