Slow new connections

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: whatare 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.0122 0.0000 close(3) = 0 23416: 0.0129 0.0007 stat("/usr/platform/SUNW,Sun-Fire/lib/libc_psr.so.1", 0xFFBEF004) = 0 23416: 0.0132 0.0003 open("/usr/platform/SUNW,Sun-Fire/lib/libc_psr.so.1", O_RDONLY) = 3 23416: 0.0133 0.0001 fstat(3, 0xFFBEF004) = 0 23416: 0.0135 0.0002 mmap(0xFF340000, 8192, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 3, 0) = 0xFF340000 23416: 0.0137 0.0002 close(3) = 0 23416: 0.0170 0.0033 brk(0

William wrote: > Folks, > > > 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. > Possibly asking the blindingly obvious but have you checked that DNS resolution, forward and reverse for both the client and server, on both the client and server is working during the slow times? -- Clive

Clive Eisen <clive@serendipita.com> wrote in message news:<41362d47$0$22759$db0fefd9@news.zen.co.uk>... > William wrote: > > Folks, > > > > > > 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. > > > Possibly asking the blindingly obvious but have you checked that DNS > resolution, forward and reverse for both the client and server, on both > the client and server is working during the slow times? We're actually looking for clues at that direction as well. It seems that DNS may be fine for hostname solutions were fine. However, we also have NIS in place, which could not be excluded here. We've noticed that the delay has never lasted longer than 5 minutes, which makes me wonder if there is a timeout setting somewhere contributing to the delay... Thanks for your response anyway. Regards, William

Clive Eisen <clive@serendipita.com> wrote in message news:<41362d47$0$22759$db0fefd9@news.zen.co.uk>... > William wrote: > > Folks, > > > > > > 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. > > > Possibly asking the blindingly obvious but have you checked that DNS > resolution, forward and reverse for both the client and server, on both > the client and server is working during the slow times? The problem affects ALL new connections - including shared memory connections - i.e. telnet to the informix server ; specify ipcshm connection ; dbaccess <database> will also be affected. NSSWITCH on the server validates against local passwords and groups. Host name resolution is against /etc/hosts and then DNS and the host name is specified in /etc/hosts. Leighton