FD leaks while interacting with DB

prabakar.bhatt has asked for the wisdom of the Perl Monks concerning the following question:

We are seeing FD leak in our application while using Oracle DB. FD leaks are happening for files ocius.msb. We dont see the FD leaks while using with simple stand alone application.

debug.pl 8588 root 48r REG 253,0 27648 1325248 oracle/rdbms/mesg/ocius.msb

debug.pl 8588 root 49r REG 253,0 27648 1325248 oracle/rdbms/mesg/ocius.msb

debug.pl 8588 root 50r REG 253,0 27648 1325248 oracle/rdbms/mesg/ocius.msb

debug.pl 8588 root 51r REG 253,0 27648 1325248 oracle/rdbms/mesg/ocius.msb

 Perl Vesrion: 5.10.x 
       DBD : 1.80
       DBI : 1.643
[download]

Stand alone application code where leak is not seen

#!/use/bin/perl

use strict ;
use DBI;

my $count = 0;

sub showtime () {
print "Starting loop \n";
while ( $count < 50 ) {

   $count++;
   print "Inside loop \n";
   my $dbh = DBI->connect("DBI:Oracle:host=localhost;port=1521;sid=syn
+o",'xyx','xyx',{PrintError => 1, RaiseError => 1, ora_envhp => 0});
   my $cmd = "grep  VmRSS /proc/$$/status";
   print`$cmd`;
   sleep(1);
   $dbh->disconnect or warn "Disconnection failed: $DBI::errstr\n";

}
print "Ending script \n";
}

showtime
[download]

Our application opens a DEBUG file to capture DB errro/warnings. content of the DB file is displayed below.

Start debug file
    DBI 1.643-ithread default trace level set to 0x0/4 (pid 2349 pi 7f
+c7300692a0) at access_database.pm line 280 via (eval 18) line 10
    -> DBI->connect(dbi:Oracle:temip_syno_ip_read, temipsyno, ****, HA
+SH(0x7fc7307d4158))
    -> DBI->install_driver(Oracle) for linux perl=5.010001 pid=2349 ru
+id=514 euid=514
       install_driver: DBD::Oracle version 1.80 loaded from /usr/opt/t
+emip/alarm_beautifier/perl/lib/site_perl/5.10.1/x86_64-linux-thread-m
+ulti/DBD/Oracle.pm
    -> STORE in DBD::_::common for DBD::Oracle::dr (DBI::dr=HASH(0x7fc
+7307f7270)~0x7fc7307f71c8 'ShowErrorStatement' 1) thr#7fc7300692a0
    STORE DBI::dr=HASH(0x7fc7307f71c8) 'ShowErrorStatement' => 1
    <- STORE= 1 at /usr/opt/temip/alarm_beautifier/perl/lib/site_perl/
+5.10.1/x86_64-linux-thread-multi/DBD/Oracle.pm line 77 via  at (eval 
+18) line 10
    <- install_driver= DBI::dr=HASH(0x7fc7307f7270)
    -> connect for DBD::Oracle::dr (DBI::dr=HASH(0x7fc7307f7270)~0x7fc
+7307f71c8 'temip_syno_ip_read' 'temipsyno' **** HASH(0x7fc73051d478))
+ thr#7fc7300692a0
           charset id=1, name=US7ASCII, ncharset id=1, name=US7ASCII (
+csid: utf8=0 al32utf8=0)
    <- connect= DBI::db=HASH(0x7fc73088dee8) at /usr/opt/temip/alarm_b
+eautifier/perl/lib/site_perl/5.10.1/x86_64-linux-thread-multi/DBI.pm 
+line 679 via  at (eval 18) line 10
    -> STORE for DBD::Oracle::db (DBI::db=HASH(0x7fc73088ddf8)~INNER '
+RaiseError' 1) thr#7fc7300692a0
    STORE DBI::db=HASH(0x7fc73088ddf8) 'RaiseError' => 1
    <- STORE= 1 at /usr/opt/temip/alarm_beautifier/perl/lib/site_perl/
+5.10.1/x86_64-linux-thread-multi/DBI.pm line 731 via  at (eval 18) li
+ne 10
    -> STORE for DBD::Oracle::db (DBI::db=HASH(0x7fc73088ddf8)~INNER '
+PrintError' 1) thr#7fc7300692a0
    STORE DBI::db=HASH(0x7fc73088ddf8) 'PrintError' => 1
    <- STORE= 1 at /usr/opt/temip/alarm_beautifier/perl/lib/site_perl/
+5.10.1/x86_64-linux-thread-multi/DBI.pm line 731 via  at (eval 18) li
+ne 10
    -> STORE for DBD::Oracle::db (DBI::db=HASH(0x7fc73088ddf8)~INNER '
+AutoCommit' 1) thr#7fc7300692a0
    <- STORE= 1 at /usr/opt/temip/alarm_beautifier/perl/lib/site_perl/
+5.10.1/x86_64-linux-thread-multi/DBI.pm line 731 via  at (eval 18) li
+ne 10
    -> STORE for DBD::Oracle::db (DBI::db=HASH(0x7fc73088ddf8)~INNER '
+Username' 'temipsyno') thr#7fc7300692a0
    STORE DBI::db=HASH(0x7fc73088ddf8) 'Username' => 'temipsyno'
    <- STORE= 1 at /usr/opt/temip/alarm_beautifier/perl/lib/site_perl/
+5.10.1/x86_64-linux-thread-multi/DBI.pm line 734 via  at /usr/opt/tem
+ip/alarm_beautifier/bin//access_database.pm line 354
    -> connected in DBD::_::db for DBD::Oracle::db (DBI::db=HASH(0x7fc
+73088dee8)~0x7fc73088ddf8 'dbi:Oracle:temip_syno_ip_read' 'temipsyno'
+ **** HASH(0x7fc7307d4158)) thr#7fc7300692a0
    <- connected= undef at /usr/opt/temip/alarm_beautifier/perl/lib/si
+te_perl/5.10.1/x86_64-linux-thread-multi/DBI.pm line 741 via  at (eva
+l 18) line 10
    <- connect= DBI::db=HASH(0x7fc73088dee8)
    -> STORE for DBD::Oracle::db (DBI::db=HASH(0x7fc73088ddf8)~INNER '
+dbi_connect_closure' CODE(0x7fc73088a900)) thr#7fc7300692a0
    STORE DBI::db=HASH(0x7fc73088ddf8) 'dbi_connect_closure' => CODE(0
+x7fc73088a900)
    <- STORE= 1 at /usr/opt/temip/alarm_beautifier/perl/lib/site_perl/
+5.10.1/x86_64-linux-thread-multi/DBI.pm line 750 via  at /usr/opt/tem
+ip/alarm_beautifier/bin//access_database.pm line 354
    -> STORE for DBD::Oracle::db (DBI::db=HASH(0x7fc73088ddf8)~INNER '
+LongReadLen' 128) thr#7fc7300692a0
    STORE DBI::db=HASH(0x7fc73088ddf8) 'LongReadLen' => 128
    <- STORE= 1 at /usr/opt/temip/alarm_beautifier/bin//access_databas
+e.pm line 390 via  at (eval 18) line 10
    -> STORE for DBD::Oracle::db (DBI::db=HASH(0x7fc73088ddf8)~INNER '
+LongTruncOk' 1) thr#7fc7300692a0
    STORE DBI::db=HASH(0x7fc73088ddf8) 'LongTruncOk' => 1
    <- STORE= 1 at access_database.pm line 391 via  at (eval 18) line 
+10
    -> prepare for DBD::Oracle::db (DBI::db=HASH(0x7fc73088dee8)~0x7fc
+73088ddf8 'select  spec, ipaddr0 from ip  where rownum = '1'') thr#7f
+c7300692a0
        dbd_st_prepare'd sql SELECT ( auto_lob1, check_sql1)
        dbd_describe SELECT (EXPLICIT, lb 128)...
Describe col #1 type=1(VARCHAR)
Described col  1: dbtype 1(VARCHAR), scale 0, prec 2048, nullok 0, nam
+e ENTITY_SPEC
                  : dbsize 2048, char_used 0, char_size 2048, csid 1, 
+csform 1(SQLCS_IMPLICIT), disize 2048
        fbh 1: 'ENTITY_SPEC'    NO null , otype   1->  5, dbsize 2048/
+2049, p2048.s0
Describe col #2 type=2(NVARCHAR2)
Described col  2: dbtype 2(NVARCHAR2), scale 0, prec 3, nullok 1, name
+ IPADDR0
                  : dbsize 22, char_used 0, char_size 0, csid 0, csfor
+m 0(0), disize 171
        fbh 2: 'IPADDR0'        NULLable, otype   2->  5, dbsize 22/17
+2, p3.s0
        cache settings DB Handle RowCacheSize=0,Statement Handle RowCa
+cheSize=0, OCI_ATTR_PREFETCH_ROWS=60, OCI_ATTR_PREFETCH_MEMORY=0, Row
+s per Fetch=60, Multiple Row Fetch=On
        calling OCIAttrSet OCI_ATTR_CHARSET_FORM with csform=1 (SQLCS_
+IMPLICIT)
        dbd_describe'd 2 columns (row bytes: 2070 max, 1028 est avg, c
+ache: 0)
    <- prepare= DBI::st=HASH(0x7fc7307f6a90) at access_database.pm lin
+e 453 via  at access_database.pm line 423
    -> $DBI::err (*) FETCH from lasth=HASH
    <- $DBI::err= undef
    -> execute for DBD::Oracle::st (DBI::st=HASH(0x7fc7307f6a90)~0x7fc
+7307f6c70) thr#7fc7300692a0
   dbd_st_execute SELECT (out0, lob0)...
Statement Execute Mode is 0 (DEFAULT)
        rs_array_init:imp_sth->rs_array_size=60, rs_array_idx=0, prefe
+tch_rows=0, rs_array_status=SUCCESS
        dbd_st_execute SELECT returned (SUCCESS, rpc0, fn4, out0)
    <- execute= '0E0' at access_database.pm line 470 via  at access_da
+tabase.pm line 467
    -> $DBI::err (*) FETCH from lasth=HASH
    <- $DBI::err= undef
    -> fetchrow_array for DBD::Oracle::st (DBI::st=HASH(0x7fc7307f6a90
+)~0x7fc7307f6c70) thr#7fc7300692a0
        dbd_st_fetch 2 fields...
...Fetched 1 rows
        dbd_st_fetched 2 fields with status of 0(SUCCESS)
        field #1 with rc=0(OK)
        field #2 with rc=0(OK)
    <- fetchrow_array= ( 'OSI_SYSTEM ossvm42_ns:.sanity_osi1' '10' ) [
+2 items] row1 at access_database.pm line 492 via  at access_database.
+pm line 423
    -> fetchrow_array for DBD::Oracle::st (DBI::st=HASH(0x7fc7307f6a90
+)~0x7fc7307f6c70) thr#7fc7300692a0
        dbd_st_fetch 2 fields...
        dbd_st_fetch no-more-data, fetch count=0
    <- fetchrow_array= ( ) [0 items] row1 at access_database.pm line 4
+99 via  at access_database.pm line 423
    <> DESTROY(DBI::st=HASH(0x7fc7307f6a90)) ignored for outer handle 
+(inner DBI::st=HASH(0x7fc7307f6c70) has ref cnt 1)
    -> DESTROY for DBD::Oracle::st (DBI::st=HASH(0x7fc7307f6c70)~INNER
+) thr#7fc7300692a0
    <- DESTROY= undef at access_database.pm line 423 via  at access_da
+tabase.pm line 423
    dbih_clearcom 0x7fc7307f6c70 (com 0x7fc73091cff0, type 3) done.
[download]

Comment on FD leaks while interacting with DB Select or Download Code

Replies are listed 'Best First'.
Re: FD leaks while interacting with DB by roboticus (Chancellor) on Apr 13, 2020 at 16:47 UTC
prabakar.bhatt: I don't know how you're expecting us to help without better information. You give us the source code to a tiny script that you say doesn't give any problems, so there's no real need to look at that. You next give us a debug log from DBI for an unrelated program that obviously does more and different things. While debug logs are nice, there are no references to file opens/closes, so I don't see how it's useful to help you track down an FD leak. It's kind of like you asking "Hey, I'm trying to figure out why my hard drive got filled up by my program. Here's the source code to a totally different program, and I have an NVidia GTX970 video card. So how do I fix it?" What I would want to see would be the source code to the app that is failing along with the DBI log. But I wouldn't want to wade through hundreds of lines of irrelevent code. So I'd suggest making a copy of your application, and then start chopping out pieces that aren't interesting, testing each version of the code to make sure that the file descriptor leak is still happening. Frequently during this process, you'll chop out a chunk of code and the problem will go away. When this happens, take a look at what you chopped out to see what bearing it may have on the problem, alternately, you'll get a small enough program for people to look at that you can post and ask qustions about. Anyway, when I looked at your debug log, I notice a couple things: The log contains references DBI in an unusual-looking path: /usr/opt/temip/alarm_beautifier/perl/lib/site_perl/x86.../DBI.pm: Do you possibly have a hacked up version of DBI? You might want to compare it to the original distribution version to see if there is anything suspicious in there. It looks like there are multiple DB handles in your log (I don't have an active DB right now, so I can't confirm), perhaps you're leaking DB handles which are causing your problem? At the end of your log, I see some "DESTROY(..) ignored for outer handle (inner DBI::st=... has ref cnt 1)", so it looks like something is holding a handle to a statement, so your attempt to close the database may be failing because you still have statement handles lying around. Since perl tries to delete things when they're no longer accessible, I'd look for places where you store database handles, statement handles, etc. Not only can you store them in a hash or array, you can also have accidental references to them with closures, so be sure to look for those, too. ...roboticus When your only tool is a hammer, all problems look like your thumb.	[reply]
Re^2: FD leaks while interacting with DB by prabakar.bhatt (Novice) on May 04, 2020 at 10:46 UTC
Thanks for your help. We tried few things to give the exact reproducer. What we figured is , Issue is reproducible when application is multi threaded. In Multi threaded application , even after exiting the thread FDs are not freed. Please find the reproducer scripts and steps below. File1 : Sample.pm package sample; use strict; use DBI; my $count = 0; sub showtime () { print "Starting loop \n"; #while ( $count < 50 ) { $count++; print ("Connecting to DB \n"); # Modify sid, user, password values. my $dbh = DBI->connect("DBI:Oracle:host=localhost;port=1521;sid= +syno",'temipsyno','temipsyno',{PrintError => 1, RaiseError => 1, ora_ +envhp => 0}); #my $cmd = "grep VmRSS /proc/$$/status"; # Check no. of fd's after connection to db. #my $cmd = "ls -l /proc/$$/fd \| grep ocius"; #print `$cmd`; sleep(1); print ("Disconnecting from DB \n"); $dbh->disconnect or warn "Disconnection failed: $DBI::errstr\n"; #} print "Ending script \n"; } 1; [download] Source file2 : scr1 #!/usr/local/bin/perl use threads; use sample; $ENV{'ORACLE_HOME'} = '/usr/opt/oracle'; sub worker() { my $count = 0; # Make it do some work (open and close DB 10 times). while ( $count < 2 ) { sample::showtime(); $count = $count + 1 ; #my $cmd = "ls -l /proc/$$/fd \| grep ocius"; #print threads -> self() -> tid() . " : " . `$cmd` ; sleep 3 } } my $nthreads = 5; for ( 1..$nthreads ) { threads->create(\&worker); } foreach my $thr (threads->list() ) { $thr->join(); } print ("Check no. of fd's for ocius.msb using lsof -p $$. Sleeping 30s + \n"); print ("If no. of fd's > 0, then why there is still fd's not closed ev +en after" . " threads have exited \n"); sleep(30); [download] How to execute the script: `./scr1` [download] Sample o/p: Starting loop Connecting to DB Starting loop Connecting to DB Starting loop Connecting to DB Starting loop Connecting to DB Starting loop Connecting to DB Disconnecting from DB Ending script Disconnecting from DB Ending script Disconnecting from DB Ending script Disconnecting from DB Ending script Disconnecting from DB Ending script Starting loop Connecting to DB Starting loop Connecting to DB Starting loop Connecting to DB Starting loop Connecting to DB Starting loop Connecting to DB Disconnecting from DB Ending script Disconnecting from DB Ending script Disconnecting from DB Ending script Disconnecting from DB Ending script Disconnecting from DB Ending script Check no. of fd's for ocius.msb using lsof -p 9940. Sleeping 30s [download] If no. of fd's > 0, then why there is still fd's not closed even after threads have exited	[reply] [d/l] [select]
Re^3: FD leaks while interacting with DB by choroba (Cardinal) on May 05, 2020 at 12:50 UTC
I changed the DSN to Postgres and tested locally. I added another sleep before the loop and ran lsof there as well, then compared the outputs. There were many files open at the end of the program not present in the first list, but none of them seem to be a leaked database handle: 11116432.pl 17198 choroba mem REG 254,0 118512 6711636 /usr +/lib64/libsasl2.so.3.0.0 11116432.pl 17198 choroba mem REG 254,0 14648 6711746 /usr +/lib64/libkeyutils.so.1.6 11116432.pl 17198 choroba mem REG 254,0 14720 6719925 /usr +/lib64/libcom_err.so.2.1 11116432.pl 17198 choroba mem REG 254,0 159456 5909809 /lib +64/libselinux.so.1 11116432.pl 17198 choroba mem REG 254,0 199576 6714342 /usr +/lib64/libk5crypto.so.3.1 11116432.pl 17198 choroba mem REG 254,0 217032 264891 /var +/lib/nscd/passwd 11116432.pl 17198 choroba mem REG 254,0 2681240 6719579 /usr +/lib64/libcrypto.so.1.1 11116432.pl 17198 choroba mem REG 254,0 299128 6729817 /usr +/lib64/libpq.so.5.10 11116432.pl 17198 choroba mem REG 254,0 309784 6714338 /usr +/lib64/libgssapi_krb5.so.2.2 11116432.pl 17198 choroba mem REG 254,0 335416 6715270 /usr +/lib64/libldap_r-2.4.so.2.10.9 11116432.pl 17198 choroba mem REG 254,0 442648 6730433 /usr +/lib64/libssl.so.1.1 11116432.pl 17198 choroba mem REG 254,0 52440 6714354 /usr +/lib64/libkrb5support.so.0.1 11116432.pl 17198 choroba mem REG 254,0 575808 6711541 /usr +/lib64/libpcre.so.1.2.9 11116432.pl 17198 choroba mem REG 254,0 60472 6715268 /usr +/lib64/liblber-2.4.so.2.10.9 11116432.pl 17198 choroba mem REG 254,0 900864 6714352 /usr +/lib64/libkrb5.so.3.3 11116432.pl 17198 choroba mem REG 254,0 92216 5909835 /lib +64/libz.so.1.2.11 11116432.pl 17198 choroba mem REG 254,0 96624 5909861 /lib +64/libresolv-2.26.so 11116432.pl 17198 choroba mem REG 254,2 844776 14710922 /hom +e/choroba/perl5/lib/perl5/x86_64-linux-thread-multi/auto/DBD/Pg/Pg.so [download] It seems to be an Oracle issue, see File Handles Staying Open on ocius.msb (they're using C++, so it doesn't seem to be Perl related). `map{substr$_->[0],$_->[1]\|\|0,1}[\\|\|{},3],[[]],[ref qr-1,-,-1],[{}],[sub{}^ARGV,3]`	[reply] [d/l] [select]
Re^3: FD leaks while interacting with DB by choroba (Cardinal) on May 05, 2020 at 09:51 UTC
Does the problem persist when you remove `use DBI`, change it to `require DBI`, and move it inside the showtime sub? `map{substr$_->[0],$_->[1]\|\|0,1}[\\|\|{},3],[[]],[ref qr-1,-,-1],[{}],[sub{}^ARGV,3]`	[reply] [d/l] [select]
Re^4: FD leaks while interacting with DB by prabakar.bhatt (Novice) on May 05, 2020 at 11:20 UTC