(Fwd) Strange memory leak (?) with DBI ? DBD::Pg

----- Forwarded message from Troy Davis -----

x-pobox-client-address: 216.37.68.82
x-pobox-client-name: cafeautism.net
Date: Sat, 20 Oct 2007 11:22:42 -0500
From: Troy Davis
To: Tim.Bunce@pobox.com
Subject: Strange memory leak (?) with DBI


Hello Tim,

I've been trying to track down the source of mysteriously missing memory in
my mod_perl2 environment. I've boiled part of the problem down to the
following, and was wondering if you might be able to explain what's going
on. Consider the following:

---snip---
use DBI;

while (1) {
$dbh = DBI->connect('DBI:Pg:', 'db_name', 'db_pass',
{ RaiseError => 1 } );

# Just pick some random ID; I've verified 1-124 are all there.
my $id = int rand(124);

# The database is Postgres and the "blob" column is of type bytea.
# This field in the database is always 901120 bytes long.
my ($contents) = $dbh->selectrow_array('
SELECT blob FROM blobs WHERE id = ?
', undef, $id);

$dbh->disconnect;
}
---snip---

If I run the above script while doing the following in another console:

while [ 1 ]; do free; ps u -C perl; echo; sleep 3; done

Then the following happens. Watch the VSZ counter for the perl process:

---snip---
total used free shared buffers cached
Mem: 516856 317948 198908 0 72056 176496
-/+ buffers/cache: 69396 447460
Swap: 979924 4840 975084
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1165 39.5 1.0 85276 5340 pts/1 S+ 11:15 0:02 perl foo

total used free shared buffers cached
Mem: 516856 321792 195064 0 72068 176504
-/+ buffers/cache: 73220 443636
Swap: 979924 4840 975084
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1165 40.7 1.1 134492 5772 pts/1 S+ 11:15 0:03 perl foo

total used free shared buffers cached
Mem: 516856 321304 195552 0 72072 176504
-/+ buffers/cache: 72728 444128
Swap: 979924 4840 975084
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1165 43.5 1.0 213052 5660 pts/1 S+ 11:15 0:06 perl foo

total used free shared buffers cached
Mem: 516856 318708 198148 0 72080 176500
-/+ buffers/cache: 70128 446728
Swap: 979924 4840 975084
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1165 41.7 1.1 268320 5972 pts/1 S+ 11:15 0:07 perl foo

total used free shared buffers cached
Mem: 516856 318840 198016 0 72084 176504
-/+ buffers/cache: 70252 446604
Swap: 979924 4840 975084
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1165 42.1 1.5 314396 7756 pts/1 S+ 11:15 0:08 perl foo
---snip---

This will continue indefinitely until it runs out of memory (under
Apache/mod_perl2, Apache eventually dies with "Out of memory!", though again
the above is completely independent of Apache). However, I don't understand
why this is, as there's plenty of both physical memory and swap free the
whole time.

This is happening on a Debian etch box. Here are all the relevant package
versions I thought you would want to see:

ii libdbd-pg-perl 1.49-2
ii libdbi-perl 1.53-1
ii perl-base 5.8.8-7
ii postgresql-8.1 8.1.9-0etch1

I checked the changelog for DBI and nothing that was fixed in versions >1.53
jumped out at me as being related to this. I'd have to go through a fair
bit of contorting to get 1.59 working on this box, but if you suspect that
this is already been fixed, then let me know.

Thank you for any help you might be able to offer.

--
Troy Davis
tdavis@tdavis.org
http://www.tdavis.org/

----- End forwarded message -----
----- Forwarded message from Troy Davis -----

x-pobox-client-address: 216.37.68.82
x-pobox-client-name: cafeautism.net
Date: Sat, 20 Oct 2007 11:36:45 -0500
From: Troy Davis
To: Tim.Bunce@pobox.com
Subject: Re: Strange memory leak (?) with DBI

On Sat, Oct 20, 2007 at 11:22:42AM -0500, Troy Davis wrote:
> I've been trying to track down the source of mysteriously missing memory in
> my mod_perl2 environment. I've boiled part of the problem down to the
> following, and was wondering if you might be able to explain what's going
> on. Consider the following:
>
> ---snip---

Sorry, I should have clarified that the script that followed is being run
from a console with regular old perl, completely independent of
Apache/mod_perl2.

--
Troy Davis
tdavis@tdavis.org
http://www.tdavis.org/

----- End forwarded message -----
----- Forwarded message from Troy Davis -----

x-pobox-client-address: 216.37.68.82
x-pobox-client-name: cafeautism.net
Date: Sun, 21 Oct 2007 14:08:30 -0500
From: Troy Davis
To: Tim.Bunce@pobox.com
Subject: Re: Strange memory leak (?) with DBI

On Sat, Oct 20, 2007 at 11:22:42AM -0500, Troy Davis wrote:
> I've been trying to track down the source of mysteriously missing memory
> in my mod_perl2 environment. I've boiled part of the problem down to the
> following, and was wondering if you might be able to explain what's going
> on. Consider the following:

I wanted to let you know that I was also able to repeat this problem on
Ubuntu Gutsy. The relevant version numbers in this case were:

ii libdbd-pg-perl 1.49-2build1
ii libdbi-perl 1.57-1
ii perl-base 5.8.8-7ubuntu
ii postgresql 8.2.5-1.1

--
Troy Davis
tdavis@tdavis.org
http://www.tdavis.org/

----- End forwarded message -----

Re: (Fwd) Strange memory leak (?) with DBI ? DBD::Pg

On Sun, Oct 21, 2007 at 09:48:44PM +0100, Tim Bunce wrote:
> Hello Tim,

I somehow missed the section of the docs that said to email the list, not
Tim. :-)

Tim added the "? DBD::Pg" to the subject. I didn't even think to check out
DBD::Pg's open bugs. Turns out this has already been found and solved by
someone else:

http://rt.cpan.org/Public/Bug/Display.html?id=21392

The patch there fixed my problem.

--
Troy Davis
tdavis@tdavis.org
http://www.tdavis.org/

Re: (Fwd) Strange memory leak (?) with DBI ? DBD::Pg

--------------080906010903060001030105
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Tim Bunce wrote:
> ----- Forwarded message from Troy Davis -----
> # The database is Postgres and the "blob" column is of type bytea.

As Troy mentioned BYTEA, I remembered I often noticed memory leaks when
dealing with this kind of columns, so I hacked his test a "little bit"
(check the attachment - it requires GTop, as I was too lazy to grep
/proc/self/status) and run it against a PostgreSQL v8.2.5 server, using
DBD::Pg v1.49 (DBI v1.59):

$ ./leak_pgsql.pl
vsz: 8581120 rss: 3710976 [before connect]
vsz: 12308480 rss: 5136384 [after connecting]
vsz: 12308480 rss: 5144576 [after creating table (TEXT)]
vsz: 12308480 rss: 5152768 [after preparing insert]
vsz: 16515072 rss: 8347648 [after inserting]
vsz: 15462400 rss: 7303168 [after droping INSERT sth]
vsz: 18616320 rss: 9420800 [after executing select (TEXT / #1)]
vsz: 19668992 rss: 10477568 [after fetching data (TEXT / #1)]
vsz: 17563648 rss: 8372224 [after droping SELECT sth (after 10 iterations)]
vsz: 18616320 rss: 9424896 [after inserting]
vsz: 17563648 rss: 8372224 [after droping INSERT sth]
vsz: 18616320 rss: 9424896 [after executing select (BYTEA / #1)]
vsz: 21774336 rss: 10485760 [after fetching data (BYTEA / #1)]
vsz: 23879680 rss: 10493952 [after fetching data (BYTEA / #2)]
vsz: 25985024 rss: 10502144 [after fetching data (BYTEA / #3)]
vsz: 28090368 rss: 10510336 [after fetching data (BYTEA / #4)]
vsz: 30195712 rss: 10518528 [after fetching data (BYTEA / #5)]
vsz: 32301056 rss: 10526720 [after fetching data (BYTEA / #6)]
vsz: 34406400 rss: 10534912 [after fetching data (BYTEA / #7)]
vsz: 36511744 rss: 10543104 [after fetching data (BYTEA / #8)]
vsz: 38617088 rss: 10551296 [after fetching data (BYTEA / #9)]
vsz: 40722432 rss: 10559488 [after fetching data (BYTEA / #10)]
vsz: 38617088 rss: 8454144 [after droping SELECT sth (after 10 iterations)]
vsz: 34414592 rss: 6348800 [the end]

Looks like fetching BYTEA columns leaks, but not TEXT.

++ BTW, I run a similar test against a MySQL v5.0.45 server using DBD::mysql
v4.005 (DBI v1.59) - no leaks occurred.

'HTH
- --
Marius Feraru
-----BEGIN PGP SIGNATURE-----

iD8DBQFHHBXMtZHp/AYZiNkRAplfAJ0WRP25rSmzrLyodLYcbH/LiENmwQCg jGqJ
E/8XgF7wgZxEoBd4Dfk8Pvc=
=N2Zd
-----END PGP SIGNATURE-----

--------------080906010903060001030105
Content-Type: application/x-perl;
name="leak_pgsql.pl"
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="leak_pgsql.pl"

#!/usr/bin/perl
use strict;
use warnings;
use Carp;
use DBI;
use GTop;
#use Devel::Leak;

my $gtop = GTop->new;
my ($prev_vsz, $prev_rss) = (0,0);
sub mem_stats {
my $msg = shift || q{};
my $pmem = $gtop->proc_mem($$);
my ($vsz, $rss) = ($pmem->vsize, $pmem->rss);
return if $prev_vsz == $vsz && $prev_rss == $rss;
($prev_vsz, $prev_rss) = ($vsz, $rss);
printf "vsz: %8d rss: %8d [%s]\n", $vsz, $rss, $msg;
}

mem_stats('before connect');

my $dbh
= DBI->connect( 'DBI:Pg:dbname=test', 'test', q{}, { RaiseError => 1 } )
or confess $DBI::errstr;
mem_stats('after connecting');

sub bake_table {
my $data_type = shift;

$dbh->do('DROP TABLE IF EXISTS leak_test');
$dbh->do("CREATE TABLE leak_test (id INT, data $data_type)");
mem_stats("after creating table ($data_type)");

my $sth = $dbh->prepare('INSERT INTO leak_test (id,data) VALUES(?,?)');
mem_stats('after preparing insert');

$sth->execute( 1, 'a' x 2**20 );
mem_stats('after inserting');

undef $sth;
mem_stats('after droping INSERT sth');
}

for my $type (qw[TEXT BYTEA]) {
bake_table($type);

my $sth = $dbh->prepare('SELECT data FROM leak_test WHERE id = ?');
mem_stats("after preparing select ($type)");

my $i = 0;
while ( $i++ < 10 ) {
$sth->execute(1);
mem_stats("after executing select ($type / #$i)");
#my $handle; Devel::Leak::NoteSV($handle);
$sth->fetchrow_arrayref;
#Devel::Leak::CheckSV($handle);
mem_stats("after fetching data ($type / #$i)");
}

undef $sth;
$i--;
mem_stats("after droping SELECT sth (after $i iterations)");
}

$dbh->disconnect;
mem_stats('the end');

--------------080906010903060001030105--