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".

On Feb 20, 9:01*pm, Vsevolod Afanassiev <vafanass...@yahoo.com> wrote:
> 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".

Do you have a sqlnet.ora? What is in it? Do you have a
tnsnames.ora? What is in it? Do you have a version? Is your client
on the same box as the server? Have you tried sqlnet tracing? Do you
have login.sql or glogin.sql in use?

I speculate you are traversing a directory path and having to wait for
some dang thing or other, like a login.sql on NFS or something silly
like that.

jg
--
@home.com is bogus.