database/sql: prepare command is always sent again when executing a statement on a DB pool with multiple open connections

[nishaad78]

What did you do?

Executing a prepared sql query on a DB connection pool with at least 2 open connections always sends the Prepare command on two connections.

For reproducing the error, first enable general logging in your MySQL DB:

SET GLOBAL general_log = 'ON';
SET GLOBAL log_output = 'table';

Now, connect to your mysql DB:

package main

import (
	"sync"

	"database/sql"
	_ "github.com/go-sql-driver/mysql"
)

db, err := sql.Open("mysql", "***:***@/***")
if err != nil {
    panic(err.Error())
}
defer db.Close()

db.SetMaxIdleConns(10)
db.SetMaxOpenConns(10)

Then run some concurrent sql commands to make sure the pool has more than one open connection:

var wg = &sync.WaitGroup{}
for i := 0; i < 2; i++ {
	wg.Add(1)
	go func(i int) {
		var stmt, err = db.Prepare("SELECT * FROM mytable WHERE id = ?")
		if err != nil {
			panic(err.Error())
		}
		defer stmt.Close()
		_, err = stmt.Exec(1)
		if err != nil {
			panic(err.Error())
		}
		wg.Done()
	}(i)
}
wg.Wait()

Now that we have at least two open connections, run a prepare and execute command on the DB:

var stmt, err = db.Prepare("SELECT * FROM mytable WHERE id = ?")
if err != nil {
	panic(err.Error())
}
defer stmt.Close()
_, err = stmt.Exec(2)
if err != nil {
	panic(err.Error())
}

What did you expect to see?

mysql> SELECT thread_id,command_type,argument FROM mysql.general_log;

+-----------+--------------+------------------------------------------+
| thread_id | command_type | argument                                 |
+-----------+--------------+------------------------------------------+
|        78 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        77 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        78 | Execute      | SELECT * FROM mytable WHERE id = 1       |
|        77 | Execute      | SELECT * FROM mytable WHERE id = 1       |
|        78 | Close stmt   | 
|        77 | Close stmt   |                
|        78 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        78 | Execute      | SELECT * FROM mytable WHERE id = 2       |
|        78 | Close stmt   |                       
|        78 | Quit         |                            
|        77 | Quit         |                        
+-----------+--------------+------------------------------------------+

What did you see instead?

mysql> SELECT thread_id,command_type,argument FROM mysql.general_log;

+-----------+--------------+------------------------------------------+
| thread_id | command_type | argument                                 |
+-----------+--------------+------------------------------------------+
|        38 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        38 | Execute      | SELECT * FROM mytable WHERE id = 1       |
|        38 | Close stmt   |   
|        37 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        38 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        38 | Execute      | SELECT * FROM mytable WHERE id = 1       |
|        38 | Close stmt   |  
|        37 | Close stmt   | 
|        37 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        38 | Prepare      | SELECT * FROM mytable WHERE id = ?       |
|        38 | Execute      | SELECT * FROM mytable WHERE id = 2       |
|        38 | Close stmt   |        
|        38 | Quit         |
|        37 | Close stmt   |    
|        37 | Quit         |
+-----------+--------------+------------------------------------------+

System details

mysql  Ver 8.0.16 for Linux on x86_64 (MySQL Community Server - GPL)

go version go1.12.5 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/najani/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/najani/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
GOROOT/bin/go version: go version go1.12.5 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.12.5
uname -v: Darwin Kernel Version 18.2.0: Fri Oct  5 19:41:49 PDT 2018; root:xnu-4903.221.2~2/RELEASE_X86_64
ProductName:	Mac OS X
ProductVersion:	10.14.1
BuildVersion:	18B75
lldb --version: lldb-1000.11.38.2
  Swift-4.2

[nishaad78]

After investigation, we found that the connStmt func never finds the connection the prepare command was sent on because db.conn func that it is calling is implemented as a LIFO, meaning that the connection just used for prepare will be the last one returned if nothing else happened in between prepare and execute.
ref: https://github.com/golang/go/blob/master/src/database/sql/sql.go#L2461-L2478

We tested this hypothesis by implementing a function that iterated over DB.freeConn and Stmt.css to find a match. This fixed this issue and we will open a PR.

[gopherbot]

Change https://golang.org/cl/179298 mentions this issue: database/sql: run prepare & execute commands on the same conn from DB pool

[kardianos]

@nishaad78 I can review the CL for your for Go1.14 (we are still in a freeze for 1.13).

For your use case, have you considered using a dedicated Conn() and calling prepare and execute on a single Conn?

[nishaad78]

Yes, we are going to switch to a dedicated connection for our use case. However, we still think this behaviour should be fixed without having to use one since Prepare() can be run on the DB pool.

…

________________________________ From: Daniel Theophanes <notifications@github.com> Sent: Thursday, May 30, 2019 2:31:57 AM To: golang/go Cc: Nishaad Ajani; Mention Subject: Re: [golang/go] database/sql: prepare command is always sent again when executing a statement on a DB pool with multiple open connections (#32298) @nishaad78<https://github.com/nishaad78> I can review the CL for your for Go1.14 (we are still in a freeze for 1.13). For your use case, have you considered using a dedicated Conn() and calling prepare and execute on a single Conn? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#32298?email_source=notifications&email_token=AB7ZYNLVOXQTWMVKIXYSYTTPX3DZ3A5CNFSM4HQI6NUKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODWQHQ2Q#issuecomment-497055850>, or mute the thread<https://github.com/notifications/unsubscribe-auth/AB7ZYNIYC6ADB3BHBAOSUWTPX3DZ3ANCNFSM4HQI6NUA>.

[nishaad78]

@kardianos could this qualify for a minor for 1.12?

[kardianos]

@nishaad78 Assuming it is merged, no, it would (still) not qualify for a minor point release.