Dear Paul,
I've been unable to reproduce the problem, to my not very big surprise.
Attached is a heavily revised version of your script - using
DBI->data_sources() to obtain database names. Note that it cycles around
the list of databases ten times. It provides Perl-level timing
information using Time::HiRes and POSIX functions. On occasion, I invoked
usleep with a value 325000 (microseconds) at the point when work might be
done (see the code).
(See attached file: paulreilly.pl)
My major questions are now about how your IDS server is set up - which
makes it less appropriate for the DBI mailing list.
Before abandoning the list, some observations on my system - a single CPU
Solaris 8 machine running IDS 9.40.UC1 with 4 server names/aliases (two for
oltlitcp, one for olipcstr, one for olipcshm), with limited to no
significant other activity on the server. I've configured the TCP and STR
connections on NET VPs, and the SHM connection on the (sole) CPU VP. When
I ran the attached script with the shared memory connections, it took about
120 seconds to run; with the TCP connections, it took about 16 seconds;
with the stream connections, about 14 seconds. I have 6 databases and the
script connects to each in turn 10 times, for 60 connect and disconnect
operations. The problem with the shared memory connection seems to be a 1
second heartbeat in some shape or form - the operations were very stable at
taking about one second to connect, and one second to disconnect. This is
odd - something I'll find out more about from the relevant part of the R&D
team. However, if connection responsiveness is critical, it appears that
shared memory connections are a disaster - even though they have
performance benefits when a session is long running. With the
microsleeping, it added approximately 6 databases x 10 iterations x 0.325
seconds ~= 20 seconds to the run time of the TCP and STR connections.
Intriguingly, it did not make any difference (less than 1 second) to the
runtime of the SHM connections, because of the heatbeat. The delay was
less than the heartbeat interval of one second, so it used a bit of time,
but then got hung waiting for the heartbeat to tick again.
Summary:
* For long-running sessions, consider using shared memory connections.
* For short-running (eg web) sessions - avoid shared memory connections
like the plague; use TLI/TCP (or SOC/TCP) or STR connections.
Detailed questions - Paul, please only respond to me (both email addresses)
and not the list.
What does your ONCONFIG file look like? Where are your shared memory
connections configured? On a NET VP or on a CPU VP? When you're running
your tests, are there any (many?) other users on the system? Have you
considered using TLI connections? Or STR connections? How many CPU VPs do
you have?
--
Jonathan Leffler ([EMAIL PROTECTED])
STSM, Informix Database Engineering, IBM Data Management
4100 Bohannon Drive, Menlo Park, CA 94025
Tel: +1 650-926-6921 Tie-Line: 630-6921
"I don't suffer from insanity; I enjoy every minute of it!"
|---------+---------------------------->
| | "Paul Reilly" |
| | <[EMAIL PROTECTED]|
| | nex.com> |
| | |
| | 07/09/2003 04:56 |
| | AM |
| | |
|---------+---------------------------->
>---------------------------------------------------------------------------------------------------------------------------------------------|
|
|
| To: <[EMAIL PROTECTED]>, <[EMAIL PROTECTED]>
|
| cc: Jonathan Leffler/Menlo Park/[EMAIL PROTECTED]
|
| Subject: Re: DBD::Informix Slow Disconnect
|
|
|
>---------------------------------------------------------------------------------------------------------------------------------------------|
Please see below ...
-------Original Message-------
From: Jonathan Leffler
Date: Wednesday, July 09, 2003 08:02:51
To: Paul Reilly
Cc: Jonathan Leffler
Subject: Re: DBD::Informix Slow Disconnect
Paul Reilly wrote:
>> I want to connect and disconnect to several databases on 'Informix
>> Dynamic Server 2000 Version 9.21.UC5'
>>
>> However, it is running very slowly because I am calling
>>
>> $dbh->disconnect
>>
>> after each connection and it seems to take a very long time.
>>
>>
>> I am using DBI 1.37 and the latest version of DBD::Informix.
>>
>> Any ideas ??
>Succinctly - no.
>I've had such reports before, but not been able to get much in the way
>of evidence to back it up. I've also been unable to reproduce the
>problem myself.
In a way I'm glad. There's always a danger with these lists of asking a
very easy question and embarrasing yourself :-)
>Which version of ESQL/C? Which platform? Which version of Perl?
My system stats are as follows
This is perl, v5.8.0 built for sun4-solaris
Informix Dynamic Server 2000 Version 9.21.UC5
IBM Informix CSDK Version 2.81, IBM Informix-ESQL Version 9.53.UC1
DBI 1.37
IBM Informix Database Driver for Perl Version 2003.04 (2003-03-05)
>How long is a very long time - milliseconds, seconds, minutes, hours?
I should add that the problem is not there all the time, rather about half
the time.
Sometimes $dbh->disconnect() works immediatedly, and sometimes takes up to
about 50 seconds
>What sort of database connection are you using - olipcshm, oltlitcp,
olsoctcp, olipcstr?
onipcshm
>Can you run with SQLIDEBUG=2:dbdix and then run sqliprint on the
resulting dbdix_* file.
>This would show what is happening at the DBI/DBD::Informix level - with
time stamps, I seem to >recall. It might therefore show what is causing
the delay - in terms of which SQL statement is >taking its time.
I used the following script for testing purposes
//////////////////////////////////////////////
#!/usr/local/bin/perl
use DBI;
$dsn = "DBI:Informix:sysmaster";
print "DBG - 1 Connecting $dsn ... \n";
my $dbStart = DBI->connect($dsn, '', '')
or die "Can't connect to Database : $DBI::errstr \n";
print " Connected <br> \n";
push (@db_used, "stores");
push (@db_used, "dimonex");
$sDB = $dbStart->prepare("select name from sysdatabases");
$sDB->execute();
my @DBrows;
while ( $DBrow = $sDB->fetchrow_array() ) {
$indOfCheck = -1;
$DBrow =~ s/\W//gs;
$indOfCheck = &indexof($DBrow, @db_used);
if($indOfCheck > -1){
push (@DBrows, $DBrow);
}
}
$sDB->finish();
print " Disconnecting ... \n";
$dbStart->disconnect();
print "Disconnected <br> <br> <br> \n";
foreach $DBrow (@DBrows) {
$DBrow =~ s/\W//gs;
my $dsnDbh ="DBI:Informix:$DBrow";
print "DBG - 2 Connecting $dsnDbh ... \n";
$dbh = DBI->connect($dsnDbh, '', '')
or die "Can't connect to Database : $DBI::errstr
\n";
print "Connected <br> \n";
# $sth = $dbh->prepare("select systables.tabname,
syscolumns.colname, #syscolumns.tabid from syscolumns, systables where
syscolumns.tabid > 99 and systables.tabid = #syscolumns.tabid order by
tabname, colname ");
#
#
# $sth->execute();
# while ( ($tabName, $colName, $colId) =
$sth->fetchrow_array() ) {
# $tabName =~ s/\W//gs;
# $colName =~ s/\W//gs;
# $colId =~ s/\W//gs;
#
# print "$DBrow,$tabName,$colName,$colId \n";
# }
# $sth->finish();
#
print "DBG - 2 Disconnecting ... \n";
$dbh->disconnect();
print "Disconnected <br> <br> \n";
print " \n \n";
}
sub indexof {
local($i);
for($i=1; $i <= $#_; $i++) {
if ($_[$i] eq $_[0]) { return $i - 1; }
}
return -1;
}
/////////////////////////////////////////////
I ran this a few times until I got an example of an immediate disconnect
and of a delayed disconnect. The only difference between the outputs were
the timestamps.
On the output that failed , it looked sa if the whoe thing took less than
2.5 seconds whereas it actually took about 3 minutes.
This portion of output is between one disconnect and the following connect
and took about 50 seconds
///////////////////////////////
S->C (2) Time: 2003-07-09 12:18:50.87513
SQ_EXIT
C->S (30) Time: 2003-07-09 12:19:41.87095
SQ_DISCONNECT
"sysmaster" [9]
"x_000000000" [11]
S->C (4) Time: 2003-07-09 12:19:42.83955
SQ_INTERNALVER
Internal Version Number: 307
C->S (190) Time: 2003-07-09 12:19:42.84194
SQ_INFO
INFO_ENV
Name Length = 12
Value Length = 94
"DBTEMP"="/tmp"
"SHELL"="/bin/sh"
"TZ"="GB"
"SUBQCACHESZ"="10"
"PATH"="/usr/bin::/usr/local/mysql/bin:/usr/local/bin:/usr/local/sbin:/usr
/ccs/bin:/apps/informix/bin
"
"NODEFDAC"="no"
INFO_DONE
SQ_EOT
S->C (2) Time: 2003-07-09 12:19:42.84257
SQ_EOT
C->S (26) Time: 2003-07-09 12:19:42.84265
SQ_CONNECT
"dimonex" [6]
"x_000000001" [11]
//////////////////////////////
>PERL_DBI_DEBUG=9 would generate a different pile of information.
This is the output for the first disconnection using PERL_DBI_DEBUG=9 :
///////////////////////////////////////////////////////
Disconnecting ... ##### <-- from my script
-->> DBD::Informix::dbd_ix_db_disconnect()
dbd_ix_db_disconnect -- delete statements
-->> DBD::Informix::dbd_ix_link_delchain()
-->> DBD::Informix::::dbd_st_destroyer()
-->> del_statement() 0x0026B048
-->> del_statement() state NoMoreData
-->> del_statement() state Opened
del_statement() CLOSE cursor c_000000000
-->> del_statement() state Declared
del_statement() FREE cursor c_000000000
-->> del_statement() state Described
-->> del_statement() state Allocated
dbd_ix_st_deallocate() DEALLOCATE DESCRIPTOR d_000000000
-->> del_statement() state Prepared
del_statement() FREE statement p_000000000
-->> del_statement() state Unused
<<-- del_statement() 0x0026B048
<<-- DBD::Informix::::dbd_st_destroyer()
<<-- DBD::Informix::dbd_ix_link_delchain()
dbd_ix_db_disconnect -- statements deleted
DISCONNECT (x_000000000)
DISCONNECT -- STATUS 0
<<-- DBD::Informix::dbd_ix_db_disconnect()
<- disconnect= 1 at tmp line 33
-> DBI->connect(DBI:Informix:dimonex, , ****)
>> connect DISPATCH (DBI::dr=HASH(0x1186d0) rc2/4 @5 g0 ima1
pid#28768) at /usr/local/lib/perl5/site_perl/5.8.0/sun4-solaris/DBI.pm
line 582
-> connect for DBD::Informix::dr (DBI::dr=HASH(0x1186d0)~0x1b4034
'dimonex' '' **** HASH(0x261f54))
New DBI::db (for DBD::Informix::db, parent=DBI::dr=HASH(0x1b4034),
id=)
dbih_setup_handle(DBI::db=HASH(0x1214c0)=>DBI::db=HASH(0x261fcc),
DBD::Informix::db, 1214cc, Null!)
dbih_make_com(DBI::dr=HASH(0x1b4034), 23e2b8, DBD::Informix::db, 288,
0) thr#0
dbih_setup_attrib(DBI::db=HASH(0x261fcc), Err, DBI::dr=HASH(0x1b4034))
SCALAR(0x121430) (already defined)
dbih_setup_attrib(DBI::db=HASH(0x261fcc), State,
DBI::dr=HASH(0x1b4034)) SCALAR(0x1213a0) (already defined)
dbih_setup_attrib(DBI::db=HASH(0x261fcc), Errstr,
DBI::dr=HASH(0x1b4034)) SCALAR(0x12140c) (already defined)
dbih_setup_attrib(DBI::db=HASH(0x261fcc), TraceLevel,
DBI::dr=HASH(0x1b4034)) 0 (already defined)
dbih_setup_attrib(DBI::db=HASH(0x261fcc), FetchHashKeyName,
DBI::dr=HASH(0x1b4034)) 'NAME' (already defined)
dbih_setup_attrib(DBI::db=HASH(0x261fcc), HandleError,
DBI::dr=HASH(0x1b4034)) undef (not defined)
Disconnected <br> <br> <br> ##### <-- from my script
//////////////////////////////////////////////////////////////////////////
/////////////
Is it my imagination or is it setting up the next connection before
finishing the current one. How is this possible ??
>And running truss or its equivalent on perl would also potentially be
informative.
truss -f gives the following output
//////////////////////////////////////////////////////
>> disconnect DISPATCH (DBI::db=HASH(0x1b3ff8) rc1/1 @1 g0 imac01
pid#28768) at tmp line 33
-> disconnect for DBD::Informix::db (DBI::db=HASH(0x1b3ff8)~0x1213b8)
Disconnecting ...
-->> DBD::Informix::dbd_ix_db_disconnect()
dbd_ix_db_disconnect -- delete statements
-->> DBD::Informix::dbd_ix_link_delchain()
29365: write(5, "\0\0\0\f", 4) = 4
29365: write(5, " ACF86\0\v13 +A1", 8) = 8
29365: write(5, "\004\0\0\0\t10\0\0\0\0\f", 12) = 12
29365: semop(196609, 0xFFBEF128, 1) = 0
29365: getpid() = 29365 [29364]
29365: write(5, " S C", 2) = 2
29365: write(5, "\0\002 <", 4) = 4
29365: write(5, " ACF86\0\v139607", 8) = 8
29365: write(5, "\00E\0\0\0\0\080 s y s m".., 572) = 572
29365: getpid() = 29365 [29364]
29365: write(5, " C S", 2) = 2
29365: write(5, "\0\0\0\b", 4) = 4
29365: write(5, " ACF86\0\v1411A1", 8) = 8
29365: write(5, "\004\0\0\0\n\0\f", 8) = 8
29365: semop(196609, 0xFFBEF068, 1) = 0
29365: getpid() = 29365 [29364]
29365: write(5, " S C", 2) = 2
29365: write(5, "\0\0\002", 4) = 4
29365: write(5, " ACF86\0\v14 j <", 8) = 8
29365: write(5, "\0\f", 2) = 2
Disconnecting ...
29365: write(1, " D i s c o n n e c t i".., 20) = 20
29365: getpid() = 29365 [29364]
29365: write(5, " C S", 2) = 2
29365: write(5, "\0\0\0\b", 4) = 4
29365: write(5, " ACF86\0\v14C3FC", 8) = 8
29365: write(5, "\004\0\0\0\n\0\f", 8) = 8
29365: semop(196609, 0xFFBEF178, 1) = 0
29365: getpid() = 29365 [29364]
29365: write(5, " S C", 2) = 2
29365: write(5, "\0\0\002", 4) = 4
29365: write(5, " ACF86\0\v15147F", 8) = 8
29365: write(5, "\0\f", 2) = 2
29365: getpid() = 29365 [29364]
29365: write(5, " C S", 2) = 2
29365: write(5, "\0\0\0\b", 4) = 4
29365: write(5, " ACF86\0\v15 Z u", 8) = 8
29365: write(5, "\004\0\0\0\v\0\f", 8) = 8
29365: semop(196609, 0xFFBEF150, 1) = 0
29365: getpid() = 29365 [29364]
29365: write(5, " S C", 2) = 2
29365: write(5, "\0\0\002", 4) = 4
29365: write(5, " ACF86\0\v15B2EE", 8) = 8
29365: write(5, "\0\f", 2) = 2
29365: getpid() = 29365 [29364]
29365: write(5, " C S", 2) = 2
29365: write(5, "\0\0\004", 4) = 4
29365: write(5, " ACF86\0\v15F79D", 8) = 8
29365: write(5, "\0 T\0\f", 4) = 4
29365: semop(196609, 0xFFBEEE50, 1) = 0
29365: getpid() = 29365 [29364]
29365: write(5, " S C", 2) = 2
29365: write(5, "\0\0\006", 4) = 4
29365: write(5, " ACF86\0\v16 N H", 8) = 8
29365: write(5, "\0 T\0\0\0\f", 6) = 6
29365: getpid() = 29365 [29364]
29365: write(5, " C S", 2) = 2
29365: write(5, "\0\0\002", 4) = 4
29365: write(5, " ACF86\0\v1689FC", 8) = 8
29365: write(5, "\0 8", 2) = 2
29365: semop(196609, 0xFFBEEEB0, 1) = 0
29365: getpid() = 29365 [29364]
29365: write(5, " S C", 2) = 2
29365: write(5, "\0\0\002", 4) = 4
29365: write(5, " ACF86\0\v16EAFB", 8) = 8
29365: write(5, "\0 8", 2) = 2
29365: semop(196609, 0xFFBEEC80, 1) = 0
29365: semop(196609, 0xFF0A24E0, 1) = 0
29365: alarm(0) = 0
29365: sigaction(SIGALRM, 0xFFBEEB98, 0xFFBEEC48) = 0
29365: sigfillset(0xFF23C824) = 0
29365: sigprocmask(SIG_BLOCK, 0xFFBEEC38, 0xFFBEEC28) = 0
29365: alarm(1) = 0
29365: Received signal #14, SIGALRM, in sigsuspend() [caught]
29365: sigsuspend(0xFFBEEC18) Err#4 EINTR
29365: setcontext(0xFFBEE900)
29365: alarm(0) = 0
29365: sigprocmask(SIG_UNBLOCK, 0xFFBEEC38, 0x00000000) = 0
29365: sigaction(SIGALRM, 0xFFBEEB98, 0x00000000) = 0
29365: shmdt(0x00800000) = 0
29365: write(5, " C S", 2) = 2
29365: write(5, "\0\0\01E", 4) = 4
29365: write(5, " ACF86\0\v978499", 8) = 8
29365: write(5, "\0 r\0\0\0\t s y s m a s".., 30) = 30
Disconnected <br> <br> <br>
DBG - 2 Connecting DBI:Informix:dimonex ...
29365: write(1, " D i s c o n n e c t e d".., 7
////////////////////////////////////////////////////////////////////////
>Why are you stuck with IDS 9.21? Can you not upgrade to a more recent
version? I'm not in the >least bit sure it would alter the slow disconnect
behaviour, but it would at least avoid problems >with the potential
unavailability of support. There could be a large number of subsidiary
questions >arising - but I need some basic data first.
Unfortunately, this is the version we are running with at the moment ...
But I'll get the boss onto it :-)
I hope that this mail provides some useful information,
sincerely,
Paul.
>--
>Jonathan Leffler ([EMAIL PROTECTED], [EMAIL PROTECTED])
>#include <disclaimer.h>
>Guardian of DBD::Informix v2003.04 -- http://dbi.perl.org/
.
____________________________________________________
(Embedded image moved to file: pic27818.gif) IncrediMail - Email has
finally evolved - Click Here
paulreilly.pl
Description: Binary data
<<attachment: pic27818.gif>>
