TNS-12535: TNS:operation timed out案例解析

一数据库突然连接不上，在自己电脑上使用SQL Developer也连接不上。立即使用SecureCRT连接上了这台服务器，从下面几个方面检查。

 

1：检查了数据库的状态是否正常

$ sqlplus / as sysdba

SQL*Plus: Release 10.2.0.5.0 - Production on Mon May 16 11:07:55 2016

Copyright (c) 1982, 2010, Oracle.  All Rights Reserved.


Connected to:
Oracle Database 10g Release 10.2.0.5.0 - 64bit Production

SQL> select status from v$instance;

STATUS
------------
OPEN

SQL>

 

2：检查监听日志是否出现错误和异常

$ more listener.log | grep TNS
TNS-12502: TNS:listener received no CONNECT_DATA from client
TNS-12502: TNS:listener received no CONNECT_DATA from client
TNS-12502: TNS:listener received no CONNECT_DATA from client
TNS-12502: TNS:listener received no CONNECT_DATA from client
TNS-12502: TNS:listener received no CONNECT_DATA from client
TNS-12502: TNS:listener received no CONNECT_DATA from client

 

如上所示，监听日志没有很特别的错误出现，使用tail -60f listener.log 也能看到监听进程一直处理用户请求，但是新的连接无法登录到数据库。事后检查（这种情况持续的实际较短，我还在检查时，数据库已经正常了，数据库又能正常连接），发现在12:59出现了TNS-12535错误，跟这个没有关系。

TNS-12525: TNS:listener has not received client's request in time allowed

TNS-12535: TNS:operation timed out

TNS-12606: TNS: Application timeout occurred

TNS-12502: TNS:listener received no CONNECT_DATA from client

TNS-12502: TNS:listener received no CONNECT_DATA from client

 

3：检查告警日志和跟踪日志

检查告警日志，没有发现任何错误信息，但是在这个时间点出现了几个trc文件

*** 2016-05-13 12:39:57.979
  NS Primary Error: TNS-12535: TNS:operation timed out
  NS Secondary Error: TNS-12606: TNS: Application timeout occurred
kmduicxd: 0x7f88cafc4620, kmduiflg: 1, circuit: 0x8507edda0
  (circuit) dispatcher process id = (0x85c694738, 1)
            parent process id = (18, 1)
            serial # = 2
            connection context = 0x7f88cafc4620
            user session = ((nil)), flag = (100c0), queue = (9)
            current buffer = (0), status = (4, 0)
Client Address = (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.xxx.xxx)(PORT=60049))
*** 2016-05-13 12:40:25.202
  NS Primary Error: TNS-12535: TNS:operation timed out
  NS Secondary Error: TNS-12606: TNS: Application timeout occurred
kmduicxd: 0x7f88cafc4dd0, kmduiflg: 1, circuit: 0x8507e8210
  (circuit) dispatcher process id = (0x85c694738, 1)
            parent process id = (18, 1)
            serial # = 2
            connection context = 0x7f88cafc4dd0
            user session = ((nil)), flag = (100c0), queue = (9)
            current buffer = (0), status = (4, 0)
Client Address = (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.xxx.xxx)(PORT=58630))
*** 2016-05-13 12:40:45.147
  NS Primary Error: TNS-12535: TNS:operation timed out
  NS Secondary Error: TNS-12606: TNS: Application timeout occurred
kmduicxd: 0x7f88cafc52f0, kmduiflg: 1, circuit: 0x8507e5448
  (circuit) dispatcher process id = (0x85c694738, 1)
            parent process id = (18, 1)
            serial # = 2
            connection context = 0x7f88cafc52f0
            user session = ((nil)), flag = (100c0), queue = (9)
            current buffer = (0), status = (4, 0)

查了一下metalink文档上关于TNS-12535的错误，如下所示

APPLIES TO:

Oracle Net Services - Version 10.1.0.3 to 11.2.0.4 [Release 10.1 to 11.2]
Information in this document applies to any platform.

This problem can occur on any platform.

SYMPTOMS

Error TNS-12535 when connecting to Oracle database via dispatchers (shared servers).

The dispatcher trace shows following error message -

NS Primary Error: TNS-12535: TNS:operation timed out 
NS Secondary Error: TNS-12606: TNS: Application timeout occurred 
kmduicxd: 0EEE01DC, kmduiflg: 1, circuit: 4D08C930 
(circuit) dispatcher process id = (85917028, 1) 
parent process id = (64, 1) 
serial # = 44 
connection context = 0EEE01DC 
user session = (00000000), flag = (100c0), queue = (9) 
current buffer = (0), status = (4, 0) 
Client Address = (ADDRESS=(PROTOCOL=tcp)(HOST=<IP address>)(PORT=<port>))

CAUSE

The SHARED_SERVER parameter is set to an inadequate value and should be raised.   A connection via shared server will fail if there are no free shared servers available to honor the request.

The 12535 error in the dispatcher trace indicates that the connection was timed out in the dispatchers queue.

SOLUTION

Increase value for following database parameters -

max_shared_servers
shared_servers

These parameters are modifiable using ALTER SYSTEM. For example -

SQL> alter system set shared_server=30;   
SQL> alter system set max_shared_server=300;

 

其中有这么一段描述，在共享服务器连接模式当中，如果SHARED_SERVER参数设置过小或不足，如果没有空闲的shared server进程可用，那么通过共享服务器模式连接到数据库的连接请求就会失败， TNS-12535错误就会出现dispatcher trace文件中，表明dispatcher队列中的请求超时。

The SHARED_SERVER parameter is set to an inadequate value and should be raised. A connection via shared server will fail if there are no free shared servers available to honor the request.

The 12535 error in the dispatcher trace indicates that the connection was timed out in the dispatchers queue.

 

我们的shared_server和max_shared_server参数一直以来都较合理，突然出现这种情况是为什么额？ 后面再DPA的监控里面看到，当时有个用户使用Toad更新了某个表，但是他后面意识到自己忘记在UPDATE语句里面添加WHERE条件了，就回滚了该SQL语句，这个时间段导致该表被锁，很多会话被阻塞。这就能解释为什么出现这种情况了。

接下来，我们通过下面例子来重现这个案例情况吧，我们先准备测试环境，如下所示，我们设置shared_servers、max_shared_servers、两个参数的值。由于是测试环境，我们尽量将这些设置小一点，方便我们测试。

SQL> alter system set shared_servers=4  scope=both;

System altered.

SQL> show parameter shared_server

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_shared_servers                   integer     30
shared_server_sessions               integer
shared_servers                       integer     4

SQL> alter system set max_shared_servers=4 scope=both;

System altered.

SQL> show parameter shared_server

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_shared_servers                   integer     4
shared_server_sessions               integer
shared_servers                       integer     4
SQL>

创建test用户，然后以test用户登录数据库，执行下面操作后，退出会话。

SQL> create table test(id number(10), name varchar(12));

Table created.

SQL> insert into test
  2  select 1, 'kerry' from dual union all
  3  select 2, 'jimmy' from dual union all
  4  select 3, 'jerry' from dual;

3 rows created.

SQL> commit;

Commit complete.
SQL> exit;

然后开启四个cmd命令窗口分别执行这个sql语句，当我们开启第五个cmd命令窗口时，依然能连接执行SQL（因为第一个会话变成INACTIVE状态，SERVER变成NONE状态了）

C:Users>sqlplus test/test@mytest

SQL*Plus: Release 11.2.0.1.0 Production on 星期一 5月 16 23:46:13 2016

Copyright (c) 1982, 2010, Oracle. All rights reserved.

连接到:

Oracle Database 10g Release 10.2.0.5.0 - 64bit Production

SQL> update test set name='kkk' where id=1;

已更新 1 行。

SQL>

会话窗口1

会话窗口2、3、4、5都如下所示

开启第六个窗口执行SQL命令时，报下面错误

使用sqlplus / as sysdba 登录数据库，执行下面命令，你会看到第一个会话的STATUS已经变成INACTIVE状态了， SERVER为NONE状态，所以开启第五个会话窗口时才会依然能连接数据库，当你开启第6个会话窗口才报上面错误。可以看到第一个会话961，阻塞了其它四个会话。

检查dispatcher的跟踪文件，你就能看到下面这样的错误信息。跟我们上面案例的几乎是一样的

当然，有时候你可能被ORA-00104这样的错误给干扰测试。

此时你需要设置参数的inbound_connect_timeout，不要给的过大。否则测试结果很容易被上面错误干扰。

 

其实V$SESSION中，状态为NONE的当前共享服务器进程没有任务处理，若果进程正在执行某些任务则会为SHARED状态。参考我这篇文章v$session中server为none与shared值解析

In MTS/Shared Server configuration when you see value 'NONE' (as shown below), it means there is no task being processed by shared server for that session. The server column will infact show status of 'SHARED' if there is some task being processed at that particular time by the shared server process for that session.

 

在共享服务器模式中，当并发工作的ACTIVE SESSION数大于max_shared_servers参数时，就不能在增加新的shared server processes，新的session请求就会得不到空闲的shared server processes的响应，dispatcher进程无法为会话分配一个服务器端进程（shared server perocesss）也就会出现数据库连接不上的现象,最后出现超时现象。如果这个有点难以理解，那么你想象一下，在一个餐厅里面，假设有40位客人在就餐，但是只有4个服务器员，如果同时四个服务员正在服务4个客户，那么第五个客户，就不能得到服务员的服务了。除非他等待其中一个客户已经服务完了，如果时间太长，他就会放弃这个服务了。

 

小结：

 

保证事务是短小的--这是用于MTS（共享服务器模式）的第一条规则。它们可以是频繁的，但它们应该是短小的(如OLTP 系统所表现的特点)。如果它们不是短小的，那么由于共享资源被一些进程独占，将导致系统速度整体下降。在极端的情况下，如果全部的共享服务都是忙的情况下，系统将被挂起。

所以对于事务具有时间短、频率高特点的OLTP 系统，MTS 是最合适的。在OLTP 系统中，事务是在几毫秒内执行完的。另一方面，MTS 非常不合适于数据仓库。

--------------------------------------------------------------------------------------------------------------------------------

             上面这段小结来自于《ORACLE专家高级编程》，用在此处非常恰当、合适！！！

 

参考资料：

https://support.oracle.com/epmos/faces/DocumentDisplay?_afrLoop=170439072788756&id=823274.1&_afrWindowMode=0&_adf.ctrl-state=222ndlb4e_34