Slow connection to Oracle on AIX: using truss

From: Vsevolod Afanassiev <vafanassiev_at_yahoo.com>
Date: Wed, 20 Feb 2008 21:01:23 -0800 (PST)
Message-ID: <1f0c0fef-6fbd-450e-ae88-3c2bcf691c1f@o77g2000hsf.googlegroups.com>


Hi All,

We are investigating slow connection to Oracle on AIX 5.2 using truss utility:

> truss -d -o truss.out sqlplus user/pass @connect.sql

where connect.sql contains only one line: exit

The output file consistently shows something like that: (first column is time in seconds):


0.2123:        close(7)                         = 0
0.2125:        close(10)                        = 0
kread(9, " N T P 0   9 8 3 2 0 8\n".., 64)      = 12
1.0132:        _getpid()                        = 905314
1.0140:        kfcntl(9, F_SETFD, 0x0000000000000001) = 0
-----------------------------
So it spent 0.8 second executing "kread" with file_id = 9.
But what is it? There is no "open" that returns "9". I think "0" is standard input, "1" is standard output, and "2" is standard error. But what is "9"?

In the example above the delay is 0.8 second buy we have seen much longer delays.

"sar" does not show heavy load on the server. "sar -d" does not show any busy disks.

It is interesting that we are able to reproduce this problem on another server (AIX 5.3) by copying a large file within the filesystem where Oracle is installed. Output of truss shows:


0.2261:        close(7)                         = 0
kwrite(8, "01 Z\0\006\0\0\0\0\003 s".., 346)    = 346
2.2286:        kread(9, "\016\0\006\0\0\0\0\00280".., 2064)
(sleeping...)
kread(9, "04 6\0\006\0\0\0\0\0\b\0".., 2064) = 1078 29.8208: open("/ora/oracle/product/9207/rdbms/mesg/oraus.msb", O_RDONLY) = 7

So it spent 2 seconds doing "kwrite(8" and then 27 seconds doing "kread(9". Received on Wed Feb 20 2008 - 23:01:23 CST

Original text of this message