From 277047f52ae36f9364bf6d593931ee8732d96cb3 Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Thu, 25 Apr 2013 14:45:56 -0700 Subject: database/sql: fix driver Conn refcounting with prepared statements The refcounting of driver Conns was completedly busted and would leak (be held open forever) with any reasonable load. This was a significant regression from Go 1.0. The core of this patch is removing one line: s.db.addDep(dc, s) A database conn (dc) is a resource that be re-created any time (but cached for speed) should not be held open forever with a dependency refcount just because the Stmt (s) is alive (which typically last for long periods of time, like forever). The meat of the patch is new tests. In fixing the real issue, a lot of tests then failed due to the fakedb_test.go's paranoia about closing a fakeConn while it has open fakeStmts on it. I could've ignored that, but that's been a problem in the past for other bugs. Instead, I now track per-Conn open statements and close them when the the conn closes. The proper way to do this would've been making *driverStmt a finalCloser and using the dep mechanism, but it was much more invasive. Added a TODO instead. I'd like to give a way for drivers to opt-out of caring about driver.Stmt closes before a driver.Conn close, but that's a TODO for the future, and that TODO is added in this CL. I know this is very late for Go 1.1, but database/sql is currently nearly useless without this. I'd like to believe all these database/sql bugs in the past release cycle are the result of increased usage, number of drivers, and good feedback from increasingly-capable Go developers, and not the result of me sucking. It's also hard with all the real drivers being out-of-tree, so I'm having to add more and more hooks to fakedb_test.go to simulate things which real drivers end up doing. Fixes #5323 R=golang-dev, snaury, gwenn.kahz, google, r CC=golang-dev https://golang.org/cl/8836045 --- src/pkg/database/sql/sql_test.go | 183 +++++++++++++++++++++++++++++++++++++-- 1 file changed, 178 insertions(+), 5 deletions(-) (limited to 'src/pkg/database/sql/sql_test.go') diff --git a/src/pkg/database/sql/sql_test.go b/src/pkg/database/sql/sql_test.go index 37fdd2795e..e6cc667fa9 100644 --- a/src/pkg/database/sql/sql_test.go +++ b/src/pkg/database/sql/sql_test.go @@ -43,6 +43,7 @@ type testOrBench interface { Errorf(string, ...interface{}) Fatal(...interface{}) Error(...interface{}) + Logf(string, ...interface{}) } func newTestDB(t testOrBench, name string) *DB { @@ -59,6 +60,11 @@ func newTestDB(t testOrBench, name string) *DB { exec(t, db, "INSERT|people|name=Bob,age=?,photo=BPHOTO", 2) exec(t, db, "INSERT|people|name=Chris,age=?,photo=CPHOTO,bdate=?", 3, chrisBirthday) } + if name == "magicquery" { + // Magic table name and column, known by fakedb_test.go. + exec(t, db, "CREATE|magicquery|op=string,millis=int32") + exec(t, db, "INSERT|magicquery|op=sleep,millis=10") + } return db } @@ -80,6 +86,16 @@ func closeDB(t testOrBench, db *DB) { t.Errorf("Error closing fakeConn: %v", err) } }) + for i, dc := range db.freeConn { + if n := len(dc.openStmt); n > 0 { + // Just a sanity check. This is legal in + // general, but if we make the tests clean up + // their statements first, then we can safely + // verify this is always zero here, and any + // other value is a leak. + t.Errorf("while closing db, freeConn %d/%d had %d open stmts; want 0", i, len(db.freeConn), n) + } + } err := db.Close() if err != nil { t.Fatalf("error closing DB: %v", err) @@ -95,6 +111,51 @@ func numPrepares(t *testing.T, db *DB) int { return db.freeConn[0].ci.(*fakeConn).numPrepare } +func (db *DB) numDeps() int { + db.mu.Lock() + defer db.mu.Unlock() + return len(db.dep) +} + +// Dependencies are closed via a goroutine, so this polls waiting for +// numDeps to fall to want, waiting up to d. +func (db *DB) numDepsPollUntil(want int, d time.Duration) int { + deadline := time.Now().Add(d) + for { + n := db.numDeps() + if n <= want || time.Now().After(deadline) { + return n + } + time.Sleep(50 * time.Millisecond) + } +} + +func (db *DB) numFreeConns() int { + db.mu.Lock() + defer db.mu.Unlock() + return len(db.freeConn) +} + +func (db *DB) dumpDeps(t *testing.T) { + for fc := range db.dep { + db.dumpDep(t, 0, fc, map[finalCloser]bool{}) + } +} + +func (db *DB) dumpDep(t *testing.T, depth int, dep finalCloser, seen map[finalCloser]bool) { + seen[dep] = true + indent := strings.Repeat(" ", depth) + ds := db.dep[dep] + for k := range ds { + t.Logf("%s%T (%p) waiting for -> %T (%p)", indent, dep, dep, k, k) + if fc, ok := k.(finalCloser); ok { + if !seen[fc] { + db.dumpDep(t, depth+1, fc, seen) + } + } + } +} + func TestQuery(t *testing.T) { db := newTestDB(t, "people") defer closeDB(t, db) @@ -131,7 +192,7 @@ func TestQuery(t *testing.T) { // And verify that the final rows.Next() call, which hit EOF, // also closed the rows connection. - if n := len(db.freeConn); n != 1 { + if n := db.numFreeConns(); n != 1 { t.Fatalf("free conns after query hitting EOF = %d; want 1", n) } if prepares := numPrepares(t, db) - prepares0; prepares != 1 { @@ -806,8 +867,11 @@ func TestMaxIdleConns(t *testing.T) { } } -// golang.org/issue/5046 -func TestCloseConnBeforeStmts(t *testing.T) { +// golang.org/issue/5323 +func TestStmtCloseDeps(t *testing.T) { + if testing.Short() { + t.Skip("skipping in short mode") + } defer setHookpostCloseConn(nil) setHookpostCloseConn(func(_ *fakeConn, err error) { if err != nil { @@ -815,7 +879,112 @@ func TestCloseConnBeforeStmts(t *testing.T) { } }) + db := newTestDB(t, "magicquery") + defer closeDB(t, db) + + driver := db.driver.(*fakeDriver) + + driver.mu.Lock() + opens0 := driver.openCount + closes0 := driver.closeCount + driver.mu.Unlock() + openDelta0 := opens0 - closes0 + + stmt, err := db.Prepare("SELECT|magicquery|op|op=?,millis=?") + if err != nil { + t.Fatal(err) + } + + // Start 50 parallel slow queries. + const ( + nquery = 50 + sleepMillis = 25 + nbatch = 2 + ) + var wg sync.WaitGroup + for batch := 0; batch < nbatch; batch++ { + for i := 0; i < nquery; i++ { + wg.Add(1) + go func() { + defer wg.Done() + var op string + if err := stmt.QueryRow("sleep", sleepMillis).Scan(&op); err != nil && err != ErrNoRows { + t.Error(err) + } + }() + } + // Sleep for twice the expected length of time for the + // batch of 50 queries above to finish before starting + // the next round. + time.Sleep(2 * sleepMillis * time.Millisecond) + } + wg.Wait() + + if g, w := db.numFreeConns(), 2; g != w { + t.Errorf("free conns = %d; want %d", g, w) + } + + if n := db.numDepsPollUntil(4, time.Second); n > 4 { + t.Errorf("number of dependencies = %d; expected <= 4", n) + db.dumpDeps(t) + } + + driver.mu.Lock() + opens := driver.openCount - opens0 + closes := driver.closeCount - closes0 + driver.mu.Unlock() + openDelta := (driver.openCount - driver.closeCount) - openDelta0 + + if openDelta > 2 { + t.Logf("open calls = %d", opens) + t.Logf("close calls = %d", closes) + t.Logf("open delta = %d", openDelta) + t.Errorf("db connections opened = %d; want <= 2", openDelta) + db.dumpDeps(t) + } + + if len(stmt.css) > nquery { + t.Errorf("len(stmt.css) = %d; want <= %d", len(stmt.css), nquery) + } + + if err := stmt.Close(); err != nil { + t.Fatal(err) + } + + if g, w := db.numFreeConns(), 2; g != w { + t.Errorf("free conns = %d; want %d", g, w) + } + + if n := db.numDepsPollUntil(2, time.Second); n > 2 { + t.Errorf("number of dependencies = %d; expected <= 2", n) + db.dumpDeps(t) + } + + db.SetMaxIdleConns(0) + + if g, w := db.numFreeConns(), 0; g != w { + t.Errorf("free conns = %d; want %d", g, w) + } + + if n := db.numDepsPollUntil(0, time.Second); n > 0 { + t.Errorf("number of dependencies = %d; expected 0", n) + db.dumpDeps(t) + } +} + +// golang.org/issue/5046 +func TestCloseConnBeforeStmts(t *testing.T) { db := newTestDB(t, "people") + defer closeDB(t, db) + + defer setHookpostCloseConn(nil) + setHookpostCloseConn(func(_ *fakeConn, err error) { + if err != nil { + t.Errorf("Error closing fakeConn: %v; from %s", err, stack()) + db.dumpDeps(t) + t.Errorf("DB = %#v", db) + } + }) stmt, err := db.Prepare("SELECT|people|name|") if err != nil { @@ -830,6 +999,9 @@ func TestCloseConnBeforeStmts(t *testing.T) { t.Errorf("conn shouldn't be closed") } + if n := len(dc.openStmt); n != 1 { + t.Errorf("driverConn num openStmt = %d; want 1", n) + } err = db.Close() if err != nil { t.Errorf("db Close = %v", err) @@ -837,8 +1009,8 @@ func TestCloseConnBeforeStmts(t *testing.T) { if !dc.closed { t.Errorf("after db.Close, driverConn should be closed") } - if dc.ci == nil { - t.Errorf("after db.Close, driverConn should still have its Conn interface") + if n := len(dc.openStmt); n != 0 { + t.Errorf("driverConn num openStmt = %d; want 0", n) } err = stmt.Close() @@ -888,6 +1060,7 @@ func manyConcurrentQueries(t testOrBench) { if err != nil { t.Fatal(err) } + defer stmt.Close() var wg sync.WaitGroup wg.Add(numReqs) -- cgit v1.3