Oracle运维实用经验系列第十一期-JDBC驱动缺陷导致数据库硬解析问题分析

前言：

在生产环境中，客户端使用Oracle提供的JDBC驱动包ojdbc.jar来连接到数据库，但实际生产中经常出现因JDBC的某种缺陷而造成的SQL语句翻译错误，进而给数据库端造成负担。关于JDBC驱动的问题，在Oracle运维实用经验系列第五期时，介绍过一个案例，本次讨论关于JDBC驱动的另外一个案例。

案例描述：

在应用程序日志中报错执行SQL语句超时，导致业务受到影响：

通过收集AWR报告发现数据库产生大量library cache lock和library cache:mutex x，library cache lock等待平均耗时达到了300ms左右，正常情况下应该在1～3ms；并且存在大量的SQL硬解析失败现象：

案例分析：

打开Oracle 10035trace，观察alert.log中解析失败的语句，通过对比发现：实际业务SQL的where条件中的4个字段变成了该错误SQL的选择列，实际业务SQL中本该作为别名的noholdlock 变成了错误SQL中的一张表。正因为noholdlock这张表不存在，才出现了ORA-942的报错。通过查找资料及案例库，我们初步定位了JDBC驱动调用OracleParameterMetaData.getParameterType方法时造成了错误的翻译。因大量翻译错误的SQL被送往数据库，产生了大量硬解析，library cache lock采用串行机制，故而阻塞了正常业务SQL执行。

在生产常备测试环境中，我们通过如下代码重现了生产问题：

编译的执行结果如下：

10046trace可以看到解析失败SQL与生产异常情况完全符合，同时JDBC getParameterType方法也抛出异常。进一步分析dba_hist_active_sess_history发现，其实在生产环境中一直存在解析错误的SQL。但在11月26日前，该解析错误并未影响到实际的生产。那么此时的问题是，oracle反馈给jdbc的942异常之后，jdbc反馈给应用程序，应用程序为什么没有做出一般的异常处理等等操作？进一步观察应用程序日志发现：

应用程序可能并不一定仅使用的是当前oracle的jdbc进行SQL编译重组的。可能还使用了Apache提供的通用的jar包commons-dbutils-1.5.jar。我们采用如下代码来模拟dbutil的工作：

编译后执行结果如下：

可以看到返回了S（代表模拟业务执行SQL场景是成功了），但是还是伴随抛出了942的异常。这种现象说明了，实际情况是应用调用dbutils时，把jdbc返回的错误忽略掉了，并没有中断程序去做异常处理。也就是说，本身这条取metadata的SQL语句自始至终并没有解析成功过。进一步了解，发现应用是对异常的记录是交易超时（timeout），那么结合目前的模拟测试来看，生产环境一直也是抛解析异常的，应用程序对这里的jdbc反馈的ora-942的异常并没有做异常处理。getParameterType select语句成功与否，其实对具体的交易成功与否无关。

总结：

数据库访问请求进行对比，交易量较其他同时间段增长了15%，较前一天同时间段增长了将近40%，当交易量逐步增大时，数据库因为反复对错误SQL进行硬解析从而造成Library Cache Lock等待。同时，应用程序未对JDBC抛出的异常进行处理，仅仅依靠timeout来判断交易是否正常。后续在测试环境中进行了测试，测试结果并结合实际交易量，可以得出基本结论：交易并发数达到某个临界值时（测试环境中为10-20个并发1分钟20笔/秒），该时间点累积大量解析错误导致library cache lock等待，导致了交易堵塞超时。

开放系统支持部 吴昊@ABCDC