Re: Possible database handle leak in DBI?

On 05/12/12 03:33, Duncan McEwan wrote:
> Hi,
>
>> So to summarize, you are seeing that sometimes connect_cached uses
>> a previous entry, and sometimes it does not, right? ...
>> ... When the connect_cached fails with a false negative, it is because
>> the CachedKids hash is empty, when it should have at least one existing
>> item, right?
>
> Good summary!  Yes, the problem only occurs occasionally.  Based on the
> debugging I have in DBI.pm, out of approx 160,000 calls to connect_cached()
> over the last 2 days, the problem occurred around 360 times.
>
>> I'd bump up the trace level to at least 3 ...
>
> I had thought about turning on DBI tracing but I was a bit worried about
> the amount of output that would be generated.  But having just read the
> "TRACING" section of the DBI pod I see that I can also specify that I only
> want to trace the connection process, so maybe it won't be so bad.  I'll try
> it and find out!

If you mean the CON trace flag I think you are going to be disappointed. Although DBI defines this trace flag you'll get very little out of it. There is only one DBD which I know (DBD::ODBC) which adds anything for CON tracing. When I connect using CON tracing and DBD::mysql I get:

$ perl -le 'use DBI; DBI->trace(DBI->parse_trace_flag('CON'));my $h = DBI->connect_cached("dbi:mysql:database=test");$h->disconnect; $h = undef;$h = DBI->connect_cached("dbi:mysql:database=test");'

     -> default_user in DBD::_::dr for DBD::mysql::dr (DBI::dr=HASH(0x8f7d180)~0x8f7d2f0 undef undef HASH(0x8f8c130))
     <- default_user= ( undef undef ) [2 items] at DBI.pm line 646
     -> connect_cached in DBD::_::dr for DBD::mysql::dr (DBI::dr=HASH(0x8f7d180)~0x8f7d2f0 'database=test' undef **** HASH(0x8f8c130))
     <- connect_cached= ( DBI::db=HASH(0x9018e80) ) [1 items] at DBI.pm line 658
     -> connected in DBD::_::db for DBD::mysql::db (DBI::db=HASH(0x9018e80)~0x9018f70 'dbi:mysql:database=test' undef **** HASH(0x8eed1a8))
     <- connected= ( undef ) [1 items] at DBI.pm line 720
     -> disconnect for DBD::mysql::db (DBI::db=HASH(0x9018e80)~0x9018f70)
     <- disconnect= ( 1 ) [1 items] at -e line 1
     -> default_user in DBD::_::dr for DBD::mysql::dr (DBI::dr=HASH(0x8f7d180)~0x8f7d2f0 undef undef HASH(0x9018d00))
     <- default_user= ( undef undef ) [2 items] at DBI.pm line 646
     -> connect_cached in DBD::_::dr for DBD::mysql::dr (DBI::dr=HASH(0x8f7d180)~0x8f7d2f0 'database=test' undef **** HASH(0x9018d00))
     <- connect_cached= ( DBI::db=HASH(0x8f80ab0) ) [1 items] at DBI.pm line 658
     -> connected in DBD::_::db for DBD::mysql::db (DBI::db=HASH(0x8f80ab0)~0x8f80b10 'dbi:mysql:database=test' undef **** HASH(0x9019530))
     <- connected= ( undef ) [1 items] at DBI.pm line 720
     -> disconnect_all for DBD::mysql::dr (DBI::dr=HASH(0x8f7d180)~0x8f7d2f0)
     <- disconnect_all= ( ) [0 items] (not implemented) at DBI.pm line 737
     >> DESTROY DBI::dr=HASH(0x8f7d2f0) clearing 1 CachedKids

which apart from the clearing 1 CachedKids I don't think tells you much.

If you add/change tracing whilst you are debugging and you think it is useful please feed it back.

>> or at least check out the clear_cached_kids function inside of DBI.xs
>> and get some debugging there to see who is clearing that cache ...
>
> Delving into the C code was also something I was hoping to avoid, but if
> turning on DBI connection tracing doesn't reveal anything I'll have a
> look at that.

It is not that bad. The clear_cached_kids is in DBI.xs and the tracing code is fairly straight forward. Bear in mind you might have to rebuild DBD::mysql after some changes to DBI.

>
>> As far as DBI itself, I
>> think only destroying a handle will call that function, and that
>> function is the only thing that will empty out {CachedKids}.
>
> Sounds reasonable.  I'll see if debugging or code inspection reveals any
> way that a handle could be destroyed without the connection being closed.
>
>> The other thing to consider is the web app. I know that Apache::DBI/
>> modperl has a lot of special rules regarding connecting and reconnecting:
>> it's possible your fastcgi does as well.  You might also want to poke
>> around with the mysql_auto_reconnect setting; it's possible it is on and
>> causing issues.
>
> Yes - I did see a test for the GATEWAY_INTERFACE env variable in
> DBD::mysql::connect() which causes the mysql_auto_reconnect setting to be
> turned on.  That was the only reference I found (in the perl code at least)
> to that environment variable.  From what I could make out, if MOD_PERL is set
> a whole different connection procedure is invoked using Apache::DBI::connect,
> but that doesn't seem to be the case if running under fastcgi.
>
> Anyway, thanks for the pointers.  I'll report back with any extra information
> I find.
>
> Duncan

Martin
-- 
Martin J. Evans
Easysoft Limited
http://www.easysoft.com