database/sql: Latency when calling DB.QueryContext()

[Kai Zhang]

Go version 1.8.3

In DB.QueryContext(), Go will close long live connection which exceeded the duration setted by  DB.SetConnMaxLifetime(), the code is below

database/sql/sql.go

 895 func (db *DB) conn(ctx context.Context, strategy connReuseStrategy) (*driverConn, error) {

 896     db.mu.Lock()

 897     if db.closed {

 898         db.mu.Unlock()

 899         return nil, errDBClosed

 900     }

 901     // Check if the context is expired.

 902     select {

 903     default:

 904     case <-ctx.Done():

 905         db.mu.Unlock()

 906         return nil, ctx.Err()

 907     }

 908     lifetime := db.maxLifetime

 909 

 910     // Prefer a free connection, if possible.

 911     numFree := len(db.freeConn)

 912     if strategy == cachedOrNewConn && numFree > 0 {

 913         conn := db.freeConn[0]

 914         copy(db.freeConn, db.freeConn[1:])

 915         db.freeConn = db.freeConn[:numFree-1]

 916         conn.inUse = true

 917         db.mu.Unlock()

 918         if conn.expired(lifetime) {

 919             conn.Close()

 920             return nil, driver.ErrBadConn

 921         }                                                                                                                                                       

 922         return conn, nil

 923     }

The problem is if driver.Close() has some handshake to tear down the connection, this may introduce unexpected latency. But the driver.Conn interface not mention this.

database/sql/driver/driver.go

 143 type Conn interface {

 144     // Prepare returns a prepared statement, bound to this connection.

 145     Prepare(query string) (Stmt, error)

 146 

 147     // Close invalidates and potentially stops any current

 148     // prepared statements and transactions, marking this

 149     // connection as no longer in use.

 150     //

 151     // Because the sql package maintains a free pool of

 152     // connections and only calls Close when there's a surplus of

 153     // idle connections, it shouldn't be necessary for drivers to

 154     // do their own connection caching.                                                                                                                         

 155     Close() error

 156 

 157     // Begin starts and returns a new transaction.

 158     //

 159     // Deprecated: Drivers should implement ConnBeginTx instead (or additionally).

 160     Begin() (Tx, error)

 161 }

There is already a goroutine to clean the connections, why still need a synchronous check? 

database/sql/sql.go

 750 func (db *DB) connectionCleaner(d time.Duration) {                                                                                                              

 751     const minInterval = time.Second

 752 

 753     if d < minInterval {

 754         d = minInterval

 755     }

 756     t := time.NewTimer(d)

 757 

 758     for {

 759         select {

 760         case <-t.C:

 761         case <-db.cleanerCh: // maxLifetime was changed or db was closed.

 762         }

 763 

 764         db.mu.Lock()

 765         d = db.maxLifetime

 766         if db.closed || db.numOpen == 0 || d <= 0 {

 767             db.cleanerCh = nil

 768             db.mu.Unlock()

 769             return

 770         }

 771 

 772         expiredSince := nowFunc().Add(-d)

 773         var closing []*driverConn

 774         for i := 0; i < len(db.freeConn); i++ {

 775             c := db.freeConn[i]

 776             if c.createdAt.Before(expiredSince) {

 777                 closing = append(closing, c)

 778                 last := len(db.freeConn) - 1

 779                 db.freeConn[i] = db.freeConn[last]

 780                 db.freeConn[last] = nil

 781                 db.freeConn = db.freeConn[:last]

 782                 i--

 783             }

 784         }

Is this by design or need to be fixed? 

[Daniel Theophanes]

I don't think this has anything to do with the Context method variants or Context related code.

This is just two different checks. One when the connection is returned, one periodically. You seemed to say this was introducing latency. Can you make some benchmarks with a real driver, one with the normal code and one with the sync check commented out?

Thanks, -Daniel

[Kai Zhang]

Thanks for the reply.

 

I don't think this has anything to do with the Context method variants or Context related code.

Yes, the DB.Query() method also has this problem. 

This is just two different checks. One when the connection is returned, one periodically. You seemed to say this was introducing latency. Can you make some benchmarks with a real driver, one with the normal code and one with the sync check commented out?

I found this problem when implement a sql driver for our private mysql proxy. Before disconnect from the proxy, the client need to send a message and wait for server reply.

I do this in driver.Close() method. That may block an online query request if the close operation in the synchronous check.

It happended frequently if  SetConnMaxLifetime() to a short duration, for example, 3 seconds. 

I also notice that in the mysql dirver (https://github.com/go-sql-driver/mysql), it will send packet to mysql server during driver.Close().  

https://github.com/go-sql-driver/mysql/blob/master/connection.go#L100

 97 func (mc *mysqlConn) Close() (err error) {

  98     // Makes Close idempotent

  99     if !mc.closed.IsSet() {

 100         err = mc.writeCommandPacket(comQuit)                                                                                                                    

 101     }

 102 

 103     mc.cleanup()

 104 

 105     return

 106 }

I will do a benchmark for the mysql driver later. 

[Kai Zhang]

here is the benchmark result for mysql driver:

k@k-ThinkPad-X270:sql$ go test -v -bench . --benchtime 60s -parallel 10

BenchmarkNoMaxLifetime-4   10000000     13480 ns/op

BenchmarkMaxLifetime1S-4   10000000     14356 ns/op

PASS

ok   _/home/k/Desktop/work/test/sql 303.967s

The benchmark code is here:

package main

import (

"database/sql"

"fmt"

"os"

"testing"

"time"

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

)

var db *sql.DB

func BenchmarkNoMaxLifetime(b *testing.B) {

db.SetConnMaxLifetime(0)

b.RunParallel(func(pb *testing.PB) {

var v string

for pb.Next() {

db.QueryRow("select 1").Scan(&v)

}

})

}

func BenchmarkMaxLifetime1S(b *testing.B) {

db.SetConnMaxLifetime(time.Duration(1 * time.Second))

b.RunParallel(func(pb *testing.PB) {

var v string

for pb.Next() {

db.QueryRow("select 1").Scan(&v)

}

})

}

func TestMain(m *testing.M) {

var err error

if db, err = sql.Open("mysql", "test:test@tcp(127.0.0.1:3306)/test"); err != nil {

fmt.Fprintf(os.Stderr, "sql.Open(): %v", err)

os.Exit(1)

}

os.Exit(m.Run())

}

[Kai Zhang]

Benchmark is not fair to this problem, it is the mean latency value.

This time  I wrote a simple test, and just log the time elapsed. 

Here is the code:

package main

import (

"database/sql"

"fmt"

"os"

"time"

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

)

var db *sql.DB

func RunNoMaxLifetime() {

db.SetConnMaxLifetime(0)

var v string

for i := 0; i < 10; i++ {

tBegin := time.Now()

db.QueryRow("select 1").Scan(&v)

fmt.Printf("max_lifetime=0, elapsed=%v\n", time.Since(tBegin))

time.Sleep(time.Second)

}

}

func RunMaxLifetime1S() {

db.SetConnMaxLifetime(time.Duration(1 * time.Second))

var v string

for i := 0; i < 10; i++ {

tBegin := time.Now()

db.QueryRow("select 1").Scan(&v)

fmt.Printf("max_lifetime=1s, elapsed=%v\n", time.Since(tBegin))

time.Sleep(time.Second)

}

}

func main() {

var err error

if db, err = sql.Open("mysql", "test:test@tcp(127.0.0.1:3306)/test"); err != nil {

fmt.Fprintf(os.Stderr, "sql.Open(): %v", err)

os.Exit(1)

}

RunNoMaxLifetime()

RunMaxLifetime1S()

}

here is the output:

max_lifetime=0, elapsed=328.687µs

max_lifetime=0, elapsed=336.997µs

max_lifetime=0, elapsed=224.982µs

max_lifetime=0, elapsed=343.504µs

max_lifetime=0, elapsed=447.579µs

max_lifetime=0, elapsed=330.273µs

max_lifetime=0, elapsed=332.782µs

max_lifetime=0, elapsed=277.991µs

max_lifetime=0, elapsed=391.225µs

max_lifetime=0, elapsed=373.826µs

max_lifetime=1s, elapsed=1.438923ms

max_lifetime=1s, elapsed=1.553653ms

max_lifetime=1s, elapsed=1.497325ms

max_lifetime=1s, elapsed=1.572134ms

max_lifetime=1s, elapsed=1.582973ms

max_lifetime=1s, elapsed=1.393672ms

max_lifetime=1s, elapsed=1.321443ms

max_lifetime=1s, elapsed=1.090508ms

max_lifetime=1s, elapsed=875.897µs

max_lifetime=1s, elapsed=1.685481ms

[Kai Zhang]

In my private sql driver implementation, I need to do some clean up during conn.Close().

That clean up may block the DB.Query() for a second. That lead to the latency.

Now I fix this problem by making conn.Close() do clean up asynchronously, so the conn.Close() can return fast.

Doing clean up synchronously during DB.Query() call, makes an assumption that the conn.Close() is fast.

And  Go sql driver developers need to be awared of this requirement.

[Al Corona]

Off topic question. But does anyone know how I can gain admin access on my work computer? 

[Robert Engels]

The internet. The gift that keeps on giving. 

On Nov 3, 2023, at 7:54 AM, Al Corona <alvaroco...@gmail.com> wrote:

Off topic question. But does anyone know how I can gain admin access on my work computer? 

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/c5f07284-32a9-4bc9-954c-edc7a8913843n%40googlegroups.com.