code review 8836045: database/sql: fix driver Conn refcounting with prepared...

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 Issue 5323

[bradfitz, 2013-04-24 19:45:40]

Hello golang-dev@googlegroups.com,

I'd like you to review this change to
https://go.googlecode.com/hg/

[snaury, 2013-04-24 20:34:42]

On 2013/04/24 19:45:40, bradfitz wrote:
> I'd like you to review this change to
> https://go.googlecode.com/hg/

Looks good, though what's missing is css cleanup (marked TODO). As it stands,
driver connections will be closed, but pointers to them will linger in Stmt.css.
And depending on the rate of requests it may amount to something significant:
even if we don't count sizes of driver.Conn and driver.Stmt the size of css
alone is connStmt+driverConn=8+16+8+8+16+~16 = at least 72 bytes per entry on
amd64, which at 1000 qps will cause 72kb/s leak. Do you plan to fix it after Go
1.1, or is it maybe better to include in the patch sooner?

[bradfitz, 2013-04-24 23:17:23]

Hello golang-dev@googlegroups.com, snaury@gmail.com (cc:
golang-dev@googlegroups.com),

Please take another look.

[bradfitz, 2013-04-24 23:17:53]

On Wed, Apr 24, 2013 at 1:34 PM, <snaury@gmail.com> wrote:

> On 2013/04/24 19:45:40, bradfitz wrote:
>
>> I'd like you to review this change to
>> https://go.googlecode.com/hg/
>>
>
> Looks good, though what's missing is css cleanup (marked TODO). As it
> stands, driver connections will be closed, but pointers to them will
> linger in Stmt.css. And depending on the rate of requests it may amount
> to something significant: even if we don't count sizes of driver.Conn
> and driver.Stmt the size of css alone is
> connStmt+driverConn=8+16+8+8+**16+~16 = at least 72 bytes per entry on
> amd64, which at 1000 qps will cause 72kb/s leak. Do you plan to fix it
> after Go 1.1, or is it maybe better to include in the patch sooner?
>

Done. PTAL.

Could you also load test it, if you have time?  I'll try to tonight as well.

[bradfitz, 2013-04-25 02:23:14]

[+julienschmidt, golang-nuts]

Could database/sql users please test with this patch and report back?

I'd like to get as much testing and visibility on this before Go 1.1.



On Wed, Apr 24, 2013 at 4:17 PM, Brad Fitzpatrick <bradfitz@golang.org>wrote:

> On Wed, Apr 24, 2013 at 1:34 PM, <snaury@gmail.com> wrote:
>
>> On 2013/04/24 19:45:40, bradfitz wrote:
>>
>>> I'd like you to review this change to
>>> https://go.googlecode.com/hg/
>>>
>>
>> Looks good, though what's missing is css cleanup (marked TODO). As it
>> stands, driver connections will be closed, but pointers to them will
>> linger in Stmt.css. And depending on the rate of requests it may amount
>> to something significant: even if we don't count sizes of driver.Conn
>> and driver.Stmt the size of css alone is
>> connStmt+driverConn=8+16+8+8+**16+~16 = at least 72 bytes per entry on
>> amd64, which at 1000 qps will cause 72kb/s leak. Do you plan to fix it
>> after Go 1.1, or is it maybe better to include in the patch sooner?
>>
>
> Done. PTAL.
>
> Could you also load test it, if you have time?  I'll try to tonight as
> well.
>
>

[snaury, 2013-04-25 05:56:36]

Needs some changes. For example, under load with concurrency 50 (I added a
goroutine in database/sql which shows css behavior every second):

Before changes: Stmt: css = 14895 elements (14895 cap)
After css shrink: Stmt: css = 12123 elements (14895 cap)
After errConnClosed: Stmt: css = 49 elements (64 cap)

https://codereview.appspot.com/8836045/diff/8001/src/pkg/database/sql/sql.go
File src/pkg/database/sql/sql.go (right):

https://codereview.appspot.com/8836045/diff/8001/src/pkg/database/sql/sql.go#...
src/pkg/database/sql/sql.go:518: return nil, errConnBusy
Should return errConnClosed here!

https://codereview.appspot.com/8836045/diff/8001/src/pkg/database/sql/sql.go#...
src/pkg/database/sql/sql.go:1127: s.css[i] = s.css[len(s.css)-1]
Please add s.css = s.css[:len(s.css)-1], without which it doesn't actually
shrink.

[snaury, 2013-04-25 05:58:36]

On 2013/04/25 05:56:36, snaury wrote:
> Before changes: Stmt: css = 14895 elements (14895 cap)
> After css shrink: Stmt: css = 12123 elements (14895 cap)
> After errConnClosed: Stmt: css = 49 elements (64 cap)

Oops, too much editing, numbers got really screwed up:

Before changes: Stmt: css = 12123 elements (14895 cap)
After errConnClosed: Stmt: css = 12123 elements (14895 cap)
After css shrink: Stmt: css = 49 elements (64 cap)

[bradfitz, 2013-04-25 07:17:06]

Wow, embarrassing.

As penance, I've added more tests and fixed a couple other bugs (openStmt
leaks introduced in this CL), for which there are now also new tests.

I also fixed a text flakiness issue found during long runs of various
GOMAXPROCS settings.  And things still pass with go test -race.

PTAL



On Wed, Apr 24, 2013 at 10:58 PM, <snaury@gmail.com> wrote:

> On 2013/04/25 05:56:36, snaury wrote:
>
>> Before changes: Stmt: css = 14895 elements (14895 cap)
>> After css shrink: Stmt: css = 12123 elements (14895 cap)
>> After errConnClosed: Stmt: css = 49 elements (64 cap)
>>
>
> Oops, too much editing, numbers got really screwed up:
>
> Before changes: Stmt: css = 12123 elements (14895 cap)
> After errConnClosed: Stmt: css = 12123 elements (14895 cap)
> After css shrink: Stmt: css = 49 elements (64 cap)
>
>
https://codereview.appspot.**com/8836045/<https://codereview.appspot.com/8836...
>

[bradfitz, 2013-04-25 07:17:14]

Hello golang-dev@googlegroups.com, snaury@gmail.com (cc:
golang-dev@googlegroups.com),

Please take another look.

[gwenn, 2013-04-25 17:55:29]

Seems good to me (with sqlite driver).

On Thursday, April 25, 2013 4:23:14 AM UTC+2, bradfitz wrote:
>
> [+julienschmidt, golang-nuts]
>
> Could database/sql users please test with this patch and report back?
>
> I'd like to get as much testing and visibility on this before Go 1.1.
>
>
>
> On Wed, Apr 24, 2013 at 4:17 PM, Brad Fitzpatrick
<brad...@golang.org<javascript:>
> > wrote:
>
>> On Wed, Apr 24, 2013 at 1:34 PM, <sna...@gmail.com <javascript:>> wrote:
>>
>>> On 2013/04/24 19:45:40, bradfitz wrote:
>>>
>>>> I'd like you to review this change to
>>>> https://go.googlecode.com/hg/
>>>>
>>>
>>> Looks good, though what's missing is css cleanup (marked TODO). As it
>>> stands, driver connections will be closed, but pointers to them will
>>> linger in Stmt.css. And depending on the rate of requests it may amount
>>> to something significant: even if we don't count sizes of driver.Conn
>>> and driver.Stmt the size of css alone is
>>> connStmt+driverConn=8+16+8+8+**16+~16 = at least 72 bytes per entry on
>>> amd64, which at 1000 qps will cause 72kb/s leak. Do you plan to fix it
>>> after Go 1.1, or is it maybe better to include in the patch sooner?
>>>
>>
>> Done. PTAL.
>>
>> Could you also load test it, if you have time?  I'll try to tonight as 
>> well.
>>
>>
>

[snaury, 2013-04-25 19:01:34]

LGTM, but see comments

https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go
File src/pkg/database/sql/sql.go (right):

https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go...
src/pkg/database/sql/sql.go:695: si, err := dc.prepareLocked(query)
I didn't notice this before, but isn't this redundant? Since these prepared
statements are temporary they will always be gone before driverConn is closed,
so no need to track them in driverConn. I may be wrong though...

https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go...
src/pkg/database/sql/sql.go:759: si, err := dc.prepareLocked(query)
Same here

https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go...
src/pkg/database/sql/sql.go:999: si, err := dc.prepareLocked(query)
Same here

[bradfitz, 2013-04-25 19:09:05]

Yeah, I was debating consistency vs. performance (not tracking them) on
those ephemeral prepareLocked/closeStatement calls.  I'll revert those
cases and rethink it later, if/when I move more into driverStatement.

One sec.



On Thu, Apr 25, 2013 at 12:01 PM, <snaury@gmail.com> wrote:

> LGTM, but see comments
>
>
> https://codereview.appspot.**com/8836045/diff/20001/src/**
>
pkg/database/sql/sql.go<https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go>
> File src/pkg/database/sql/sql.go (right):
>
> https://codereview.appspot.**com/8836045/diff/20001/src/**
>
pkg/database/sql/sql.go#**newcode695<https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go#newcode695>
> src/pkg/database/sql/sql.go:**695: si, err := dc.prepareLocked(query)
> I didn't notice this before, but isn't this redundant? Since these
> prepared statements are temporary they will always be gone before
> driverConn is closed, so no need to track them in driverConn. I may be
> wrong though...
>
> https://codereview.appspot.**com/8836045/diff/20001/src/**
>
pkg/database/sql/sql.go#**newcode759<https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go#newcode759>
> src/pkg/database/sql/sql.go:**759: si, err := dc.prepareLocked(query)
> Same here
>
> https://codereview.appspot.**com/8836045/diff/20001/src/**
>
pkg/database/sql/sql.go#**newcode999<https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go#newcode999>
> src/pkg/database/sql/sql.go:**999: si, err := dc.prepareLocked(query)
> Same here
>
>
https://codereview.appspot.**com/8836045/<https://codereview.appspot.com/8836...
>

[bradfitz, 2013-04-25 19:19:35]

Hello golang-dev@googlegroups.com, snaury@gmail.com, gwenn.kahz@gmail.com (cc:
golang-dev@googlegroups.com),

Please take another look.

[snaury, 2013-04-25 19:23:05]

On 2013/04/25 19:19:35, bradfitz wrote:
> Please take another look.

LGTM

[bradfitz, 2013-04-25 19:25:56]

R=r



On Thu, Apr 25, 2013 at 12:23 PM, <snaury@gmail.com> wrote:

> On 2013/04/25 19:19:35, bradfitz wrote:
>
>> Please take another look.
>>
>
> LGTM
>
>
https://codereview.appspot.**com/8836045/<https://codereview.appspot.com/8836...
>

[julienschmidt, 2013-04-25 19:26:59]

As far as I can tell, this SGTM
All my tests pass and the performance seems to be okay, too.


On 2013/04/25 19:19:35, bradfitz wrote:
> Hello mailto:golang-dev@googlegroups.com, mailto:snaury@gmail.com,
mailto:gwenn.kahz@gmail.com (cc:
> mailto:golang-dev@googlegroups.com),
> 
> Please take another look.

[r, 2013-04-25 20:09:16]

LGTM
fingers crossed

https://codereview.appspot.com/8836045/diff/8001/src/pkg/database/sql/fakedb_...
File src/pkg/database/sql/fakedb_test.go (right):

https://codereview.appspot.com/8836045/diff/8001/src/pkg/database/sql/fakedb_...
src/pkg/database/sql/fakedb_test.go:38: mu         sync.Mutex // guards all 4
fields
"3 following fields"?

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql.go
File src/pkg/database/sql/sql.go (right):

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql.go...
src/pkg/database/sql/sql.go:234: // TODO(bradfitz): let drivers opt-out of
caring about
s/-/ / (it's a verb not an adjective)

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql_te...
File src/pkg/database/sql/sql_test.go (right):

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql_te...
src/pkg/database/sql/sql_test.go:917: // the batch of 50 queries above to finish
in
s/ in$//

[bradfitz, 2013-04-25 21:46:10]

*** Submitted as https://code.google.com/p/go/source/detail?r=45c12efb4635 ***

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 Issue 5323

R=golang-dev, snaury, gwenn.kahz, google, r
CC=golang-dev
https://codereview.appspot.com/8836045

https://codereview.appspot.com/8836045/diff/8001/src/pkg/database/sql/fakedb_...
File src/pkg/database/sql/fakedb_test.go (right):

https://codereview.appspot.com/8836045/diff/8001/src/pkg/database/sql/fakedb_...
src/pkg/database/sql/fakedb_test.go:38: mu         sync.Mutex // guards all 4
fields
On 2013/04/25 20:09:16, r wrote:
> "3 following fields"?

Done.

https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go
File src/pkg/database/sql/sql.go (right):

https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go...
src/pkg/database/sql/sql.go:695: si, err := dc.prepareLocked(query)
On 2013/04/25 19:01:34, snaury wrote:
> I didn't notice this before, but isn't this redundant? Since these prepared
> statements are temporary they will always be gone before driverConn is closed,
> so no need to track them in driverConn. I may be wrong though...

Done.

https://codereview.appspot.com/8836045/diff/20001/src/pkg/database/sql/sql.go...
src/pkg/database/sql/sql.go:759: si, err := dc.prepareLocked(query)
On 2013/04/25 19:01:34, snaury wrote:
> Same here

Done.

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql.go
File src/pkg/database/sql/sql.go (right):

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql.go...
src/pkg/database/sql/sql.go:234: // TODO(bradfitz): let drivers opt-out of
caring about
On 2013/04/25 20:09:17, r wrote:
> s/-/ / (it's a verb not an adjective)

Done.

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql_te...
File src/pkg/database/sql/sql_test.go (right):

https://codereview.appspot.com/8836045/diff/20002/src/pkg/database/sql/sql_te...
src/pkg/database/sql/sql_test.go:917: // the batch of 50 queries above to finish
in
On 2013/04/25 20:09:17, r wrote:
> s/ in$//

Done.

[brainman, 2013-04-26 02:07:29]

Cannot see any problems with http://code.google.com/p/odbc/

Alex

[mtnngw_gmail.com, 2013-04-26 21:49:22]

With Tip and with just before the change:

$ go version
go version devel +5e23075b0970 Fri Apr 26 11:42:58 2013 -0700 darwin/amd64

//*sql.DB connection pool size = 20
BenchmarkCreate        1000        609021 ns/op
BenchmarkRead        2000        379022 ns/op
BenchmarkDelete        5000        296088 ns/op

// no connection pool
BenchmarkCreate         100       6199264 ns/op
BenchmarkRead         200       4424808 ns/op
BenchmarkDelete         500       3396262 ns/op


$ go version
go version devel +1d079908dd84 Thu Apr 25 18:47:12 2013 +0200 darwin/amd64

//*sql.DB connection pool size = 20
BenchmarkCreate        1000        609492 ns/op
BenchmarkRead        2000        386040 ns/op
BenchmarkDelete        5000        299545 ns/op


This is a rMBP, SSD, 2.6 Ghz Intel Core i7, 16 GB memory.
PostgreSQL 9.2.4
github.com/lib/pq

With a home brewed connection pool, I get basically the same performance.  
If I don't recycle my sql.DB pointers, I get 10x worse.

With *sql.DB connection pool size set to 50, I get "pq: sorry, too many 
clients already." in both versions.

For me, it seems that w/ respect to postgres, (and the github/lib/pq 
driver) everything is the same...

[kardia, 2013-04-26 23:43:33]

Hi Matt N,

Is it possible to show your code? I'd be interested to see it. 

Thanks,
-Daniel


On Friday, April 26, 2013 2:49:21 PM UTC-7, Matt N wrote:
>
> With Tip and with just before the change:
>
> $ go version
> go version devel +5e23075b0970 Fri Apr 26 11:42:58 2013 -0700 darwin/amd64
>
> //*sql.DB connection pool size = 20
> BenchmarkCreate        1000        609021 ns/op
> BenchmarkRead        2000        379022 ns/op
> BenchmarkDelete        5000        296088 ns/op
>
> // no connection pool
> BenchmarkCreate         100       6199264 ns/op
> BenchmarkRead         200       4424808 ns/op
> BenchmarkDelete         500       3396262 ns/op
>
>
> $ go version
> go version devel +1d079908dd84 Thu Apr 25 18:47:12 2013 +0200 darwin/amd64
>
> //*sql.DB connection pool size = 20
> BenchmarkCreate        1000        609492 ns/op
> BenchmarkRead        2000        386040 ns/op
> BenchmarkDelete        5000        299545 ns/op
>
>
> This is a rMBP, SSD, 2.6 Ghz Intel Core i7, 16 GB memory.
> PostgreSQL 9.2.4
> github.com/lib/pq
>
> With a home brewed connection pool, I get basically the same performance.  
> If I don't recycle my sql.DB pointers, I get 10x worse.
>
> With *sql.DB connection pool size set to 50, I get "pq: sorry, too many 
> clients already." in both versions.
>
> For me, it seems that w/ respect to postgres, (and the github/lib/pq 
> driver) everything is the same...
>
>