database/sql: Stmt.Exec is wasting database resources

[alexbrainman]

This new test

diff --git a/src/pkg/database/sql/sql_test.go b/src/pkg/database/sql/sql_test.go
--- a/src/pkg/database/sql/sql_test.go
+++ b/src/pkg/database/sql/sql_test.go
@@ -708,3 +708,21 @@
        t.Errorf("error = %q; want %q", err.Error(), want)
    }
 }
+
+func TestPrepareCount(t *testing.T) {
+   db := newTestDB(t, "people")
+   defer closeDB(t, db)
+   prepares0 := numPrepares(t, db)
+   stmt, err := db.Prepare("INSERT|people|name=?,age=?")
+   if err != nil {
+       t.Fatal(err)
+   }
+   defer stmt.Close()
+   _, err = stmt.Exec("Alice", 10)
+   if err != nil {
+       t.Fatal(err)
+   }
+   if prepares := numPrepares(t, db) - prepares0; prepares != 1 {
+       t.Errorf("executed %d Prepare statements; want 1", prepares)
+   }
+}

fails with

=== RUN TestPrepareCount
--- FAIL: TestPrepareCount (0.00 seconds)
    sql_test.go:726: executed -4 Prepare statements; want 1
FAIL
exit status 1
FAIL    database/sql    0.007s

[bradfitz]

Comment 1:

Wasting resources? Negative four seems pretty efficient to me.

[alexbrainman]

Comment 2:

You just don't want to look at it, Brad :-)
# hg diff .
diff -r 33d3e7bbd3ef src/pkg/database/sql/fakedb_test.go
--- a/src/pkg/database/sql/fakedb_test.go       Mon Feb 25 10:37:17 2013 +1100
+++ b/src/pkg/database/sql/fakedb_test.go       Tue Feb 26 12:13:51 2013 +1100
@@ -388,6 +388,7 @@
 }
 func (c *fakeConn) Prepare(query string) (driver.Stmt, error) {
+       fmt.Printf("*fakeConn(%p).Prepare(%s)\n", c, query)
        c.numPrepare++
        if c.db == nil {
                panic("nil c.db; conn = " + fmt.Sprintf("%#v", c))
diff -r 33d3e7bbd3ef src/pkg/database/sql/sql_test.go
--- a/src/pkg/database/sql/sql_test.go  Mon Feb 25 10:37:17 2013 +1100
+++ b/src/pkg/database/sql/sql_test.go  Tue Feb 26 12:13:51 2013 +1100
@@ -708,3 +708,21 @@
                t.Errorf("error = %q; want %q", err.Error(), want)
        }
 }
+
+func TestPrepareCount(t *testing.T) {
+       db := newTestDB(t, "people")
+       defer closeDB(t, db)
+       prepares0 := numPrepares(t, db)
+       stmt, err := db.Prepare("INSERT|people|name=?,age=?")
+       if err != nil {
+               t.Fatal(err)
+       }
+       defer stmt.Close()
+       _, err = stmt.Exec("Alice", 10)
+       if err != nil {
+               t.Fatal(err)
+       }
+       if prepares := numPrepares(t, db) - prepares0; prepares != 1 {
+               t.Errorf("executed %d Prepare statements; want 1", prepares)
+       }
+}
# go test -run=Prepare
*fakeConn(0x183457e0).Prepare(WIPE)
*fakeConn(0x183457e0).Prepare(CREATE|people|name=string,age=int32,photo=blob,dead=bool,bdate=datetime)
*fakeConn(0x183457e0).Prepare(INSERT|people|name=Alice,age=?,photo=APHOTO)
*fakeConn(0x183457e0).Prepare(INSERT|people|name=Bob,age=?,photo=BPHOTO)
*fakeConn(0x183457e0).Prepare(INSERT|people|name=Chris,age=?,photo=CPHOTO,bdate=?)
*fakeConn(0x183457e0).Prepare(INSERT|people|name=?,age=?)
*fakeConn(0x18345bc0).Prepare(INSERT|people|name=?,age=?)
--- FAIL: TestPrepareCount (0.00 seconds)
        sql_test.go:726: executed -4 Prepare statements; want 1
FAIL
exit status 1
FAIL    database/sql    0.007s
#
See how "INSERT|people|name=?,age=?" gets prepared twice (on two different connections)?
Why so?
Alex

[julienschmidt]

Comment 3:

Just wanted to open a new Issue, but this here seems highly related:
The bug seems to be introduced by 
http://code.google.com/p/go/source/detail?r=ddb9e6365e570c2619d88427176a465e8b76b4aa
http://code.google.com/p/go/source/browse/src/pkg/database/sql/sql.go#447 adds
dependency on stmt. The connection is never released again.
Output from the attached example:
go1.0.3:
>go run prepareBug.go
Prepare 1:
Prepare StmtID: 1 ConnID: 0
Close 1:
Close StmtID: 1 ConnID: 0
Prepare 2:
Prepare StmtID: 2 ConnID: 0
Query 1:
Query StmtID: 2 ConnID: 0
Query 2:
Query StmtID: 2 ConnID: 0
Close 2:
Close StmtID: 2 ConnID: 0
go-tip:
>go run prepareBug.go
Prepare 1:
Prepare StmtID: 1 ConnID: 0
Close 1:
Prepare 2:
Prepare StmtID: 1 ConnID: 1
Query 1:
Prepare StmtID: 1 ConnID: 2
Query StmtID: 1 ConnID: 2
Query 2:
Query StmtID: 1 ConnID: 2
Close 2:
Close StmtID: 1 ConnID: 2
The modified driver with debug output is available here:
https://github.com/Go-SQL-Driver/MySQL/tree/tip-prepare

Attachments:

1. prepareBug.go (736 bytes)

[bradfitz]

Comment 4:

Labels changed: added go1.1, removed priority-triage, go1.1maybe.

Owner changed to @bradfitz.

Status changed to Accepted.

[gopherbot]

Comment 5 by serbaut:

A related problem is that a database connection can have state, e.g. temporary tables,
transaction isolation settings and other variables. As I understand it each Query/Exec
may get a new/different database connection which breaks this state. For example in
mysql you can set variables like this:
db.Exec("set @foo=1")
db.Query("select @foo")
Not sure how this is supposed to work with database/sql.

[bradfitz]

Comment 6:

Re #5: use a transaction per-Conn state. That's unrelated to this bug.

[gopherbot]

Comment 7 by serbaut:

Sorry about that, just re-read the DB doc and realized transactions supports this and
clicked Delete at the same time you replied.

[bradfitz]

Comment 8:

Re #3: Julien, the stmt dep is removed at line 1030: return s.db.removeDep(s, s)

[bradfitz]

Comment 9:

Issue #4935 has been merged into this issue.

[bradfitz]

Comment 10:

Sent out https://golang.org/cl/7579045/ for review.

Status changed to Started.

[bradfitz]

Comment 11:

This issue was closed by revision 3cdf8ba.

Status changed to Fixed.