关于SQLRecoverableException问题的排查和分析-阿里云开发者社区

开发者社区> 数据库> 正文

关于SQLRecoverableException问题的排查和分析

简介: 上周在升级的时候,客户反馈某个job报了下面的错误,想让我们查看一下是不是数据库这边有什么问题。 报错的内容如下。Caused by: java.sql.SQLRecoverableException: No more data to read from socket         at oracle.
上周在升级的时候,客户反馈某个job报了下面的错误,想让我们查看一下是不是数据库这边有什么问题。
报错的内容如下。
Caused by: java.sql.SQLRecoverableException: No more data to read from socket
        at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1142)
        at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1099)
        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:288)
        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:191)
        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:523)
        at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207)
        at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:863)
        at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1153)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1275)
        at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3576)
        at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3620)
        at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1491)
        at amdocs.jf.dbutils.connection.impl.BatchPreparedStatementWrapper.executeQuery(BatchPreparedStatementWrapper.java:43)
        at amdocs.ac.db.views.AcGetNextFilesDBView.select(AcGetNextFilesDBView.java:970)
        at amdocs.ac.impl.file.AcFileOperationImpl.retrieveFileBuffer(AcFileOperationImpl.java:274)
        ... 9 more
一般这种类型的问题,错误从应用层抛出来是很难复现的。所以这种问题的排查也是比较棘手的。
首先查看了metalink,看是否有一些特殊的设置引起。但是从目前查到的结果来看,大多是由于bug引起,和目前的这个问题还是不太一致。
因为问题已经发生了好久,需要查看的地方就是tns的日志。日志还是最有说服力的。
但是查了半天,奇怪的是日志竟然都找不到。
10g的版本中tns的日志是在$ORACLE_HOME/network/log下面
这个库是SQL*Plus: Release 11.2.0.2.0 Production,没有找到日志还能理解。
因为11g中启用了adr特性,日志应该是在$ORACLE_BASE/diag下面
但是查找了半天,里面的日志只有去年11月份以前的,没有最近的日志。
> ls -lrt
-rw-r----- 1 xxxx    dba  433364 Oct  8 20:04 log_1106.xml.gz
-rw-r----- 1 xxxxx  dba 3321677 Oct  8 23:17 log.xml
没有日志这可是很郁闷的事情,更郁闷的是还找不到日志。
静下心来查看,首先可以排除是人为操作,肯定是做了某些变更导致的。能够想到的就是sqlnet.ora,一查还确实是这个原因。
network/admin> cat sqlnet.ora
DIAG_SIGHANDLER_ENABLED=FALSE
DIAG_ADR_ENABLED=OFF
DIAG_DDE_ENABLED=OFF
bequeath_detach=yes
SQLNET.INBOUND_CONNECT_TIMEOUT=240
看到这个变更就豁然开朗了,这个变更是在去年升级数据库10g到11g之后做的变更。
既然ADR中的tns日志禁用了,那么日志应该在哪呢。
其实万变不离其宗,这个根本就是listener。我们可以通过lsnrctl查看listener的状态。
network/admin> lsnrctl status listener_cust01
LSNRCTL for Linux: Version 11.2.0.2.0 - Production on 12-JAN-2015 17:08:49
Copyright (c) 1991, 2010, Oracle.  All rights reserved.
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=xxxx)(PORT=1548)))
STATUS of the LISTENER
------------------------
Alias                     LISTENER_CUST01
Version                   TNSLSNR for Linux: Version 11.2.0.2.0 - Production
Start Date                15-DEC-2014 01:58:58
Uptime                    28 days 15 hr. 9 min. 50 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Listener Parameter File   /opt/app/oracle/xxxxx/product/11.2.0/network/admin/listener.ora
Listener Log File         /opt/app/oracle/xxxxx/product/11.2.0/log/diag/tnslsnr/xxxxx/listener_cust01/alert/log.xml

好了,日志的问题解决了。我们来查看一些明细的信息。    
结果在问题的时间点发现了一处错误日志。

type='UNKNOWN' level='16' host_id='ccbdbpr3'

host_addr='127.0.0.1'>

TNS-12547: TNS:lost contact

TNS-12560: TNS:protocol adapter error

  TNS-00517: Lost contact

   Linux Error: 104: Connection reset by peer

有了这个日志,能够判断出了问题,但是还不能判断出来问题倒底是由什么原因导致的。
其实tns的日志也是一个辅助,我们还可以参考更多的日志。这个时候需要推荐的就是11g的ADR特性。
假设数据库实例是CUST01,那么路径就是

$ORACLE_BASE/diag/rdbms/cust01/CUST01/alert
底下也是log.xml的日志文件,这个和alert_CUST01.log的日志内容还是有些差别的。
log.xml中发现的内容如下:

--

host_id='ccbdbpr3' host_addr='127.0.0.1' module='sqlplus@ccbdbpr3 (TNS V1-V3)'

pid='22321'>

Immediate Kill Session: sess: 0xa52fe0740  OS pid: 8314

--

host_id='ccbdbpr3' host_addr='127.0.0.1' module='sqlplus@ccbdbpr3 (TNS V1-V3)'

pid='22321'>

Immediate Kill Session#: 239, Serial#: 63057

--

host_id='ccbdbpr3' host_addr='127.0.0.1' module='sqlplus@ccbdbpr3 (TNS V1-V3)'

pid='22321'>

Immediate Kill Session: sess: 0xa512cff40  OS pid: 19222


可以看到在指定的时间点在做kill session的操作,这个操作从应用的角度来说是没有权限做的。
然后和开发做了确认,让他们帮忙提供其它时间点的错误信息。
结果通过tns日志和alert日志查看,时间点都是完全吻合的。都在指定的时间点做了kill session的操作。
这个时候问题就有些奇怪的了,倒底是什么原因导致的这种问题呢?一种可能是schedule job,这个 是数据库层面的,一种可能是crontab,这个是操作系统级别的设置。
简单排查了下,发现在crontab中的一处设置引起了我的注意。
#------------------------------------------------
# Kill inactive session that come from JDBC Thin Client:xxxxx@xxxx and logon time more than 24 Hours
# 30-DEC-2014

最后和客户反馈这个情况,发现是由这个crontab做的kill session操作,所以最后这个问题就可以进一步分解。
从开发的角度来说,这个job的session为什么能够超过24个小时,是否是由于连接没有正确释放导致的。
从dba的角度来说,这个kill session的操作是否可以做耕细粒度的设置,或者提供临时解决方案来解决。
从目前的问题情况来说,客户还是倾向于保持现有的设置.
所以说一个看似很普通的错误日志,后面还是和数据库的各个方面紧密相关,需要耐心地查看日志,不断的排除和分析,最终找到发现问题,解决问题的钥匙。


版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

分享:
数据库
使用钉钉扫一扫加入圈子
+ 订阅

分享数据库前沿,解构实战干货,推动数据库技术变革

其他文章