tns连接非常慢

BTxigua · 发表于 2010-8-9 19:15

在做并发登陆的时候，做了个truss：
truss -aefo /tmp/truss.log sqlplus test/test@mssdb2_255
，结果在下面sleeping这个环节上hang了几分钟。
1401114: 2486645: setsockopt(7, 6, 1, 0x0FFFFFFFFFFF5D64, 4) = 0
1401114: 2486645: kfcntl(7, F_SETFD, 0x0000000000000001)       = 0
1401114: 2486645: access("/oracle/app/oracle/product/9.2.0/lib/libnk59.so", 0) Err#2  ENOENT
1401114: 2486645: access("/oracle/app/oracle/product/9.2.0/lib/libngss9.so", 0) Err#2  ENOENT
1401114: 2486645: access("/oracle/app/oracle/product/9.2.0/lib/libnnts9.so", 0) Err#2  ENOENT
1401114: 2486645: access("/oracle/app/oracle/product/9.2.0/lib/libnrad9.so", 0) Err#2  ENOENT
1401114: 2486645: sigprocmask(2, 0x09001000A02A07C8, 0x0FFFFFFFFFFF6090) = 0
1401114: 2486645: _sigaction(13, 0x0FFFFFFFFFFF61C0, 0x0FFFFFFFFFFF61F0) = 0
1401114: 2486645: thread_setmystate(0x0FFFFFFFFFFF5C80, 0x0000000000000000) = 0
1401114: 2486645: _getpid()                            = 1401114
1401114: 2486645: kwrite(7, "\0DB\0\001\0\0\001 801 ,".., 219) = 219
1401114: 2486645: kread(7, "\0\0\0\0\0\0\0\0\0\0\0\0".., 2064) (sleeping...)

BTxigua · 发表于 2010-8-9 19:16

详细的truss log

BTxigua · 发表于 2010-8-9 19:22

truss的日志不太看得懂，不知哪位高手帮忙解答一下。

顺便留一个并发登陆测试时的系统资源使用情况：
Mon Aug  9 19:21:14 2010 Interval:  2       Cswitch 2272  Readch 1884.7K4
                                             Syscall 9674  Writech 39178
Kernel 12.5 |####                      |  Reads    1218  Rawin       0
User    1.1 |#                         |  Writes    1173  Ttyout    429
Wait    0.3 |#                         |  Forks       2  Igets       0
Idle    86.2 |######################### |  Execs       1  Namei    477
                                             Runqueue 1.5  Dirblk    133
Network  KBPS I-Pack  O-Pack KB-In  KB-Out  Waitqueue 0.5
lo0    23.9    66.4 66.4 11.9 11.9
en0    6.4    6.5 38.9    0.4    6.0  PAGING          MEMORY
en1    4.9    45.9    3.5    4.2    0.7  Faults    1967  Real,MB 23647
                                             Steals       0  % Comp    71.9
Disk Busy%    KBPS    TPS KB-Read KB-Writ  PgspIn       0  % Noncomp  11.2
hdisk1 2.9    35.9    4.5    2.0 33.9  PgspOut    0  % Client 2.6
skpower8  2.9    7.0    2.5    0.0    7.0  PageIn       6
hdisk40 2.9    2.5    1.0    0.0    2.5  PageOut    8  PAGING SPACE
hdisk0 2.4    55.9    9.5 22.0 33.9  Sios       10  Size,MB 8192
hdisk20 2.4    2.0    0.5    0.0    2.0                % Used    1.3
skpower9  2.4    6.0    1.5    0.0    6.0  NFS (calls/sec)  % Free    98.6
hdisk42 0.4    4.0    1.0    0.0    4.0  ServerV2    0
hdisk18 0.4    4.5    1.5    0.0    4.5  ClientV2    0 Press:
hdisk78 0.0    0.0    0.0    0.0    0.0  ServerV3    0 "h" for help
hdisk79 0.0    0.0    0.0    0.0    0.0  ClientV3    0 "q" to quit
hdisk60 0.0    0.0    0.0    0.0    0.0
hdisk27 0.0    0.0    0.0    0.0    0.0
hdisk80 0.0    0.0    0.0    0.0    0.0

Name          PID  CPU%  PgSp Owner
tnslsnr    287064 2.0 1092.1 oracle
topas       844064 0.3 6.7 oracle
java       1356176 0.3 1324.6 root
sqlplus    1581094 0.1 2.2 oracle
sqlplus    1380570 0.1 2.2 oracle
java       696356 0.1 522.8 root
oracle    897208 0.1 4.6 oracle  t
gil          45374 0.1 0.9 root
sched       4394 0.0 0.4 root t
clstrmgr    139730 0.0 3.2 root
oracle    1114360 0.0 4.7 oracle  t
hatsd       323928 0.0 7.8 root t
java       1265884 0.0 833.6 root t
java       1511558 0.0 687.5 root t

Yong Huang · 发表于 2010-8-9 23:34

I don't see any big jump in timestamp in the listener trace. So there's no hang in the listener's processing. (If may help if you could tell us from what time to what time your tnsping command hung so we can cross-reference in the listener trace.)

vmstat indicates you have 10 to 20% sys CPU usage. It's not too high but not low either. Your truss against the client has a long wait on read on descriptor 7, which is the network connection to the server. That's no surprise because the listener on the server is too busy to respond. You may truss the server-side tnslsnr instead.

topas was not run during the busy period. You had too much idle (86.2).

I would open an SR with Oracle if there's nothing obvious. For now, you can set up a few more listeners to handle the connection load.

Yong Huang

BTxigua · 发表于 2010-8-10 12:10

下午我再模拟一下情况，上传一个listener的truss日志。

BTxigua · 发表于 2010-8-10 12:37

$ ps -ef | grep tns
  oracle  283084 1470604 0 12Ê±26·Ö25Ãë  pts/4  0:00 grep tns
  oracle  287064    1 0       9ÔÂ23    - 54071:46 /oracle/app/oracle/product/9.2.0/bin/tnslsnr LISTENER -inherit
$ truss -fdD -o /tmp/lis.truss.out -p 287064 &
[1]    1286240
$
$ tnsping mssdb2_255

TNS Ping Utility for IBM/AIX RISC System/6000: Version 9.2.0.8.0 - Production on 10-AUG-2010 12:30:58

Copyright (c) 1997, 2006, Oracle Corporation.  All rights reserved.

Used parameter files:
/oracle/app/oracle/product/9.2.0/network/admin/sqlnet.ora

Used TNSNAMES adapter to resolve the alias
Attempting to contact (DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = TCP)(HOST = 10.201.255.10)(PORT = 1521))) (CONNECT_DATA = (SERVICE_NAME =mssdb2)))
^C$
这里延时应该在17万秒左右，等不了那么长时间，我就直接ctrl+c了
$ fg
truss -fdD -o /tmp/lis.truss.out -p 287064
^C$

magic007 · 发表于 2010-8-10 18:37

看看listener是什么时候启的？占用了多少内存？重启listener会不会有所缓减？
再看看listener.log，看看高峰期连接频率是否很高。
看看truss log fork一个子进程是否过慢，或者是整个连接处理过徎需要多长的时间。比如上百毫秒就是比较慢的了。

实在不行，增加几个监听就OK了。

BTxigua · 发表于 2010-8-10 18:39

看看truss log fork一个子进程是否过慢

这个不知道怎么看？

magic007 · 发表于 2010-8-10 18:42

你的truss有个问题，首先你这个没有时间戳。另外，你truss的似乎不是listener进徎啊。

BTxigua · 发表于 2010-8-10 18:43

jsmssc:[/]#svmon -P 287064

-------------------------------------------------------------------------------
   Pid Command       Inuse    Pin    Pgsp  Virtual 64-bit Mthrd  16MB
  287064 tnslsnr       670603 65584       0 414717    Y    N    N

   PageSize    Inuse       Pin    Pgsp Virtual
   s 4 KB    604987       0       0    349101
   m  64 KB       5       3       0       5