11gR2 RAC警告日志大量报监听连接超时TNS-12535

renjie_41

操作系统版本：AIX 6100-08-03-1339
数据库版本：11.2.0.3.7
警告日志报错：
Fatal NI connect error 12170.
  VERSION INFORMATION:
        TNS for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
        TCP/IP NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
        Oracle Bequeath NT Protocol Adapter for IBM/AIX RISC System/6000: Version 11.2.0.3.0 - Production
  Time: 10-SEP-2013 17:04:27
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12535
   
TNS-12535: TNS:operation timed out
    ns secondary err code: 12606
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
  Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=52128))
WARNING: inbound connection timed out (ORA-3136)

listener日志部分信息：
10-SEP-2013 16:52:07 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=xjocsdb1)(USER=grid))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647296)) * status * 0
10-SEP-2013 16:52:12 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53047)) * establish * billdb * 0
10-SEP-2013 16:52:12 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53051)) * establish * billdb * 0
10-SEP-2013 16:52:13 * service_update * billdb1 * 0
Tue Sep 10 16:52:22 2013
10-SEP-2013 16:52:22 * service_update * billdb1 * 0
Tue Sep 10 16:52:33 2013
10-SEP-2013 16:52:33 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53061)) * establish * billdb * 0
10-SEP-2013 16:52:34 * service_update * billdb1 * 0
10-SEP-2013 16:52:41 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53068)) * establish * billdb * 0
Tue Sep 10 16:52:43 2013
10-SEP-2013 16:52:43 * service_update * billdb1 * 0
10-SEP-2013 16:52:52 * service_update * billdb1 * 0
Tue Sep 10 16:53:07 2013
10-SEP-2013 16:53:07 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=xjocsdb1)(USER=grid))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647296)) * status * 0
10-SEP-2013 16:53:10 * service_update * billdb1 * 0
10-SEP-2013 16:53:12 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53084)) * establish * billdb * 0
10-SEP-2013 16:53:13 * service_update * billdb1 * 0
Tue Sep 10 16:53:22 2013
10-SEP-2013 16:53:22 * service_update * billdb1 * 0
Tue Sep 10 16:53:33 2013
10-SEP-2013 16:53:33 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53094)) * establish * billdb * 0
10-SEP-2013 16:53:34 * service_update * billdb1 * 0
10-SEP-2013 16:53:42 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53101)) * establish * billdb * 0
Tue Sep 10 16:53:43 2013
10-SEP-2013 16:53:43 * service_update * billdb1 * 0
10-SEP-2013 16:53:45 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=serv_taf_billdb)(CID=(PROGRAM=AM_Server_A11)(HOST=xjocsapp1)(USER=ocsext))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.37)(PORT=57554)) * establish * serv_taf_billdb * 0
10-SEP-2013 16:53:45 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=serv_taf_billdb)(CID=(PROGRAM=AM_Server_A11)(HOST=xjocsapp1)(USER=ocsext))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.37)(PORT=57562)) * establish * serv_taf_billdb * 0

sqlnet已经设置了超时时间，但不管用
SQLNET.INBOUND_CONNECT_TIMEOUT=180
监听日志也设置了INBOUND_CONNECT_TIMEOUT_LISTENER=120
但警告日志依然报错。
]$ netstat -an|grep 1521|wc -l
      82
]$ ps -ef|grep LOCAL=NO|wc -l
     394
连接数还在继续增长，估计是超时导致大量重连接所致。
求助一下各位

Maclean Liu(刘相兵

10-SEP-2013 16:53:34 * service_update * billdb1 * 0
10-SEP-2013 16:53:42 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))(SERVICE_NAME=billdb)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.26)(PORT=53101)) * establish * billdb * 0
Tue Sep 10 16:53:43 2013
10-SEP-2013 16:53:43 * service_update * billdb1 * 0
10-SEP-2013 16:53:45 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=serv_taf_billdb)(CID=(PROGRAM=AM_Server_A11)(HOST=xjocsapp1)(USER=ocsext))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.37)(PORT=57554)) * establish * serv_taf_billdb * 0
10-SEP-2013 16:53:45 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=serv_taf_billdb)(CID=(PROGRAM=AM_Server_A11)(HOST=xjocsapp1)(USER=ocsext))) * (ADDRESS=(PROTOCOL=tcp)(HOST=136.24.2.37)(PORT=57562)) * establish * serv_taf_billdb * 0




似乎有多种 连入源头 有jdbc 还有AM_Server_A11 ，服务有的用 serv_taf_billdb  而有的用billdb


搞清楚 发起连接的应用是否有问题先吧？

renjie_41

awr里等待时间，library cache等待严重
Top 5 Timed Foreground Events

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

library cache lock 892 3,695,592 4143041 99.94 Concurrency
DB CPU   537   0.01   
db file scattered read 14,852 272 18 0.01 User I/O
SQL*Net more data from dblink 76,942 114 1 0.00 Network
log file sync 22,903 16 1 0.00 Commit

renjie_41

节点1的AWR，library cache lock等待严重
数据库没什么负载，连接的用户只有几十个，在MOS没找到相关bug，补丁已经打到11.2.0.3.7

renjie_41

上传节点2问题时间段的AWR

renjie_41

希望得到刘老师的帮助

Maclean Liu(刘相兵

library cache lock等待严重
==>自相矛盾的说法
数据库没什么负载

Maclean Liu(刘相兵

Cache        Get Requests        Pct Miss        Scan Reqs        Pct Miss        Mod Reqs        Final Usage
dc_awr_control        358        0.00        0                 8        1
dc_constraints        128        68.75        0                 128        64
dc_files        72        0.00        0                 0        24
dc_global_oids        3,109        0.03        0                 0        48
dc_histogram_data        11,685        3.83        0                 0        2,959
dc_histogram_defs        31,622        2.29        0                 9        5,061
dc_object_grants        81        17.28        0                 0        42
dc_objects        45,437        1.10        0                 102        2,281
dc_profiles        3,099        0.03        0                 0        2
dc_rollback_segments        13,316        0.00        0                 0        73
dc_segments        30,426        0.61        0                 1,597        1,179
dc_sequences        687        64.77        0                 687        10
dc_tablespaces        19,365        0.01        0                 0        15
dc_users        261,161        0.01        0                 0        127
global database name        20,280        0.00        0                 0        1
outstanding_alerts        322        85.40        0                 19        5
sch_lj_oids        22        9.09        0                 0        6



==》怀疑有应用使用了错误密码尝试登陆

renjie_41

刘老师，这个是不是bug引起的呢？

Maclean Liu(刘相兵

==》怀疑有应用使用了错误密码尝试登陆

harryzhang

新特性，登陆密码错，然后延迟死你么？

harryzhang

Statistic Name                                            Time (s)        % of DB Time
connection management call elapsed time        3,696,953.53        99.98
sql execute elapsed time                                       733.42        0.02
DB CPU                                                               537.38        0.01



event="28401 trace name context forever, level 1" # disable logon delay.
This "event" will disable the logon sleep delay system-wide,
ie. it will affect all user accounts, system-wide, and so should be used
with extreme caution.

renjie_41

在sqlnet.ora里加入了DIAG_ADR_ENABLED = OFF，
在listener里加入了参数DIAG_ADR_ENABLED_LISTENER= OFF后，
异常进程数减少了，library cache lock消失，警告日志不再出现报错，好在已经解决了，谢谢大家，应该是系统表空间的表被锁住了