Re: Slow new connections
William,
Don't ge too hung up on semaphores with IPCSHM interfaces. They are normal.
That said -- the time that it takes to connect is pretty much dependent on
how long it takes to authenticate the user. And the bulk of that is OS
functionality.
M.P.
"William" <weiran_will@yahoo.com> wrote in message
news:9cb24aa0.0409011139.1078d292@posting.google.com...
> Folks,
>
> We've experienced slow connections periodically on IDS
> 7.31.UD6/Solaris 2.8 environment for the last a few weeks. The problem
> is that connecting to the database can take 2-5 minutes when we hit
> the curb.
>
> As we looked into it, we noticed that the problem happens about a
> dozen time in a normal day. Each time it lasts about 1-5 minutes.
> During that time new connections are hanging while existing sessions
> work just fine. In other words, the problem seems to impact new
> connections only.
>
> By tracing system calls on a little ESQL/C program we built, which
> does nothing but connect and disconnect from the database, we noticed
> that it actually waited a much longer time for semaphore-related
> operations when the problem happens. I wonder if anyone of you guys
> can explain to me what those calls mean and/or what it's waiting for.
>
> The output of command "truss" is attached to the end of the message.
> The part you might interest in starts from "23416: semop(262148,
> 0x0013EB0C, 1) (sleeping...)".
>
> We are confident that this is not a "general perforamce tunning
> issue". Therefore, unless you know what exactly the problem is and ask
> for the information for verification, please skip the part asking for
> onstat -p, onstat -c and etc - Let's get to the point directly: what> are those calls waiting for and what do they do?
>
> Thanks in advance.
> William
>
> --------------------------------------------------------------------------
> Base time stamp: 1094006740.5241 [ Tue Aug 31 22:45:40 EDT 2004 ]
> 23416: 0.0000 0.0000 execve("/home/informix_731UD6/bin/dbaccess",
> 0xFFBEFAD4, 0xFFBEFAE0) argc = 2
> 23416: 0.0029 0.0029 resolvepath("/usr/lib/ld.so.1",
> "/usr/lib/ld.so.1", 1023) = 16
> 23416: 0.0032 0.0003 open("/var/ld/ld.config", O_RDONLY) Err#2
> ENOENT
> 23416: 0.0035 0.0003 stat("/usr/lib/libnsl.so.1", 0xFFBEF1F4) = 0
> 23416: 0.0037 0.0002 open("/usr/lib/libnsl.so.1", O_RDONLY) = 3
> 23416: 0.0038 0.0001 fstat(3, 0xFFBEF1F4) = 0
> 23416: 0.0039 0.0001 mmap(0x00000000, 8192, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF3A0000
> 23416: 0.0040 0.0001 mmap(0x00000000, 712704, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF280000
> 23416: 0.0042 0.0002 mmap(0xFF31E000, 33072,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 581632) =
> 0xFF31E000
> 23416: 0.0045 0.0003 mmap(0xFF328000, 23088,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANON, -1, 0)
> = 0xFF328000
> 23416: 0.0046 0.0001 munmap(0xFF30E000, 65536) = 0
> 23416: 0.0050 0.0004 memcntl(0xFF280000, 83280, MC_ADVISE,
> MADV_WILLNEED, 0, 0) = 0
> 23416: 0.0051 0.0001 close(3) = 0
> 23416: 0.0052 0.0001 stat("/usr/lib/libsocket.so.1", 0xFFBEF1F4) = 0
> 23416: 0.0054 0.0002 open("/usr/lib/libsocket.so.1", O_RDONLY) = 3
> 23416: 0.0055 0.0001 fstat(3, 0xFFBEF1F4) = 0
> 23416: 0.0056 0.0001 mmap(0xFF3A0000, 8192, PROT_READ|PROT_EXEC,
> MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF3A0000
> 23416: 0.0057 0.0001 mmap(0x00000000, 114688, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF380000
> 23416: 0.0059 0.0002 mmap(0xFF39A000, 4365,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 40960) =
> 0xFF39A000
> 23416: 0.0060 0.0001 munmap(0xFF38A000, 65536) = 0
> 23416: 0.0062 0.0002 memcntl(0xFF380000, 14496, MC_ADVISE,
> MADV_WILLNEED, 0, 0) = 0
> 23416: 0.0063 0.0001 close(3) = 0
> 23416: 0.0065 0.0002 stat("/usr/lib/libaio.so.1", 0xFFBEF1F4) = 0
> 23416: 0.0067 0.0002 open("/usr/lib/libaio.so.1", O_RDONLY) = 3
> 23416: 0.0068 0.0001 fstat(3, 0xFFBEF1F4) = 0
> 23416: 0.0069 0.0001 mmap(0xFF3A0000, 8192, PROT_READ|PROT_EXEC,
> MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF3A0000
> 23416: 0.0071 0.0002 mmap(0x00000000, 106496, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF360000
> 23416: 0.0072 0.0001 mmap(0xFF378000, 1584,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 32768) =
> 0xFF378000
> 23416: 0.0074 0.0002 munmap(0xFF368000, 65536) = 0
> 23416: 0.0075 0.0001 memcntl(0xFF360000, 7184, MC_ADVISE,
> MADV_WILLNEED, 0, 0) = 0
> 23416: 0.0076 0.0001 close(3) = 0
> 23416: 0.0077 0.0001 stat("/usr/lib/libdl.so.1", 0xFFBEF1F4) = 0
> 23416: 0.0079 0.0002 open("/usr/lib/libdl.so.1", O_RDONLY) = 3
> 23416: 0.0080 0.0001 fstat(3, 0xFFBEF1F4) = 0
> 23416: 0.0081 0.0001 mmap(0xFF3A0000, 8192, PROT_READ|PROT_EXEC,
> MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF3A0000
> 23416: 0.0082 0.0001 mmap(0x00000000, 8192,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANON, -1, 0) =
> 0xFF350000
> 23416: 0.0084 0.0002 close(3) = 0
> 23416: 0.0085 0.0001 stat("/usr/lib/libelf.so.1", 0xFFBEF1F4) = 0
> 23416: 0.0087 0.0002 open("/usr/lib/libelf.so.1", O_RDONLY) = 3
> 23416: 0.0088 0.0001 fstat(3, 0xFFBEF1F4) = 0
> 23416: 0.0089 0.0001 mmap(0x00000000, 8192, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF340000
> 23416: 0.0090 0.0001 mmap(0x00000000, 196608, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF240000
> 23416: 0.0092 0.0002 mmap(0xFF26E000, 3640,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 122880) =
> 0xFF26E000
> 23416: 0.0094 0.0002 munmap(0xFF25E000, 65536) = 0
> 23416: 0.0095 0.0001 memcntl(0xFF240000, 12304, MC_ADVISE,
> MADV_WILLNEED, 0, 0) = 0
> 23416: 0.0096 0.0001 close(3) = 0
> 23416: 0.0097 0.0001 stat("/usr/lib/libc.so.1", 0xFFBEF1F4) = 0
> 23416: 0.0098 0.0001 open("/usr/lib/libc.so.1", O_RDONLY) = 3
> 23416: 0.0100 0.0002 fstat(3, 0xFFBEF1F4) = 0
> 23416: 0.0101 0.0001 mmap(0xFF340000, 8192, PROT_READ|PROT_EXEC,
> MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF340000
> 23416: 0.0102 0.0001 mmap(0x00000000, 802816, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF100000
> 23416: 0.0104 0.0002 mmap(0xFF1BC000, 24764,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 704512) =
> 0xFF1BC000
> 23416: 0.0106 0.0002 munmap(0xFF1AC000, 65536) = 0
> 23416: 0.0109 0.0003 memcntl(0xFF100000, 113504, MC_ADVISE,
> MADV_WILLNEED, 0, 0) = 0
> 23416: 0.0110 0.0001 close(3) = 0
> 23416: 0.0112 0.0002 stat("/usr/lib/libmp.so.2", 0xFFBEF1F4) = 0
> 23416: 0.0113 0.0001 open("/usr/lib/libmp.so.2", O_RDONLY) = 3
> 23416: 0.0115 0.0002 fstat(3, 0xFFBEF1F4) = 0
> 23416: 0.0116 0.0001 mmap(0xFF340000, 8192, PROT_READ|PROT_EXEC,
> MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF340000
> 23416: 0.0117 0.0001 mmap(0x00000000, 90112, PROT_READ|PROT_EXEC,
> MAP_PRIVATE, 3, 0) = 0xFF220000
> 23416: 0.0118 0.0001 mmap(0xFF234000, 865,
> PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 16384) =
> 0xFF234000
> 23416: 0.0119 0.0001 munmap(0xFF224000, 65536) = 0
> 23416: 0.0122 0.0003 memcntl(0xFF220000, 3124, MC_ADVISE,
> MADV_WILLNEED, 0, 0) = 0
> 23416: 0.012
Hi Madison, You're probably right. However, the problem happens to user informix as well. In our environment, informix account is local and is never on NIS. That really shakes my long-authentication assumption. The problem persists on all our connection types, including shared memory, ipcstr and tcp/ip. It seems that ipcstr connections sleep on an open() call while tcp/ip is waiting for a getmsg(). Does that make more sense to you? +++++++++++++++++++++++++++++ IPCSTR: 513: 0.1438 0.0001 getpid() = 1513 [1511] 1513: 0.1439 0.0001 time() = 1094214960 1513: 0.1442 0.0003 uname(0xFFBEE068) = 1 1513: open("/INFORMIXTMP/sqlexec.str", O_RDWR) (sleeping...) 1513: 136.6710 136.5268 open("/INFORMIXTMP/sqlexec.str", O_RDWR) = 5 1513: 136.6717 0.0007 ioctl(5, I_CANPUT, 0x00000000) = 1 1513: 136.6718 0.0001 brk(0x00180458) = 0 1513: 136.6720 0.0002 brk(0x00182458) = 0 1513: 136.6722 0.0002 time() = 1094215097 1513: 136.6723 0.0001 poll(0xFFBEE7DC, 1, 80000) = 1 1513: 136.6725 0.0002 putmsg(5, 0x00000000, 0xFFBEE84C, 0) = 0 1513: 136.6833 0.0108 getmsg(5, 0xFFBEE84C, 0xFFBEE840, 0xFFBEE85C) = 0 1513: 136.6840 0.0007 putmsg(5, 0x00000000, 0xFFBEEE34, 0) = 0 1513: 136.6860 0.0020 getmsg(5, 0xFFBEED54, 0xFFBEED48, 0xFFBEED64) = 0 1513: 136.6871 0.0011 putmsg(5, 0x00000000, 0xFFBEEDD4, 0) = 0 1513: 136.6880 0.0009 getmsg(5, 0xFFBEED54, 0xFFBEED48, 0xFFBEED64) = 0 1513: 136.6883 0.0003 putmsg(5, 0x00000000, 0xFFBEEECC, 0) = 0 1513: 136.6898 0.0015 getmsg(5, 0xFFBEEE4C, 0xFFBEEE40, 0xFFBEEE5C) = 0 1513: 136.6901 0.0003 putmsg(5, 0x00000000, 0xFFBEEF54, 0) = 0 1513: 136.7115 0.0214 getmsg(5, 0xFFBEEED4, 0xFFBEEEC8, 0xFFBEEEE4) = 0 1513: 136.7119 0.0004 access("lt.dbs", 0) Err#2 ENOENT 1513: 136.7121 0.0002 access("./lt.dbs", 0) Err#2 ENOENT ++++++++++++++++++++++++++++++++++ TCP/IP: 1512: 0.1626 0.0026 time() = 1094214960 1512: 0.1627 0.0001 poll(0xFFBEE7CC, 1, 80000) = 1 1512: 0.1628 0.0001 fstat(5, 0xFFBEE620) = 0 1512: 0.1630 0.0002 write(5, " s q A Y U B P Q A A s q".., 393) = 393 1512: 0.1637 0.0007 fstat(5, 0xFFBEE618) = 0 1512: getmsg(5, 0xFFBEE7C4, 0xFFBEE7B4, 0xFFBEE7F4) (sleeping...) 1512: 136.3429 136.1792 getmsg(5, 0xFFBEE7C4, 0xFFBEE7B4, 0xFFBEE7F4) = 0 1512: 136.3434 0.0005 fstat(5, 0xFFBEEC08) = 0 1512: 136.3441 0.0007 write(5, "\\0 5\\0\\f", 4) = 4 1512: 136.3444 0.0003 fstat(5, 0xFFBEEB20) = 0 1512: 136.3642 0.0198 getmsg(5, 0xFFBEECCC, 0xFFBEECBC, 0xFFBEECFC) = 0 1512: 136.3650 0.0008 fstat(5, 0xFFBEEBA8) = 0 1512: 136.3652 0.0002 write(5, "\\0 Q\\006\\094\\0\\f\\01E\\006".., 158) = 158 1512: 136.3654 0.0002 fstat(5, 0xFFBEEB20) = 0 1512: 136.3865 0.0211 getmsg(5, 0xFFBEECCC, 0xFFBEECBC, 0xFFBEECFC) = 0 1512: 136.3871 0.0006 fstat(5, 0xFFBEECA0) = 0 1512: 136.3874 0.0003 write(5, "\\002\\0\\0\\0\\r D a t a b a".., 26) = 26 1512: 136.3877 0.0003 fstat(5, 0xFFBEEC18) = 0 1512: 136.3878 0.0001 getmsg(5, 0xFFBEEDC4, 0xFFBEEDB4, 0xFFBEEDF4) = 0 1512: 136.3881 0.0003 fstat(5, 0xFFBEED28) = 0 1512: 136.3887 0.0006 write(5, "\\004\\0\\0\\007\\0\\f", 8) = 8 1512: 136.3894 0.0007 fstat(5, 0xFFBEECA0) = 0 1512: 136.3909 0.0015 getmsg(5, 0xFFBEEE4C, 0xFFBEEE3C, 0xFFBEEE7C) = 0 1512: 136.3911 0.0002 access("lt.dbs", 0) Err#2 ENOENT 1512: 136.3913 0.0002 access("./lt.dbs", 0) Err#2 ENOENT "Madison Pruet" <mpruet@comcast.net> wrote in message news:<v4RZc.280163$eM2.135795@attbi_s51>... > William, > > Don't ge too hung up on semaphores with IPCSHM interfaces. They are normal. > > That said -- the time that it takes to connect is pretty much dependent on > how long it takes to authenticate the user. And the bulk of that is OS > functionality. > > M.P. > >