oracle dbview用户,关于SQLRecoverableException问题的排查和分析

上周在升级的时候,客户反馈某个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的操作是否可以做耕细粒度的设置,或者提供临时解决方案来解决。

从目前的问题情况来说,客户还是倾向于保持现有的设置.

所以说一个看似很普通的错误日志,后面还是和数据库的各个方面紧密相关,需要耐心地查看日志,不断的排除和分析,最终找到发现问题,解决问题的钥匙。

  • 0
    点赞
  • 0
    收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
©️2022 CSDN 皮肤主题:数字20 设计师:CSDN官方博客 返回首页
评论
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、C币套餐、付费专栏及课程。

余额充值