诊断案例：Failed parse elapsed time引发db time过高的案例

转载

mob604756f61e6c 2021-06-17 22:25:54

文章标签 Java 文章分类 Java 后端开发

卢立广数据和云

作者|卢立广：云和恩墨交付工程师，有多年数据库运维工作经验，擅长数据库性能优化和数据迁移等，长期服务于政府、能源、通信等行业客户。

在 awr 的 Time Model Statistics 里有个 failed parse elapsed time 指标,它是指 Amount of time spent performing SQL parses which ultimately fail with some parse error。12.2以前的版本，我们可以通过 10035 事件来追踪引发该异常的根源，对于12.2版本,则可直接在 alert 中查看分析。

摘要

这几天遇见一份 awr，发现其 db time 比平时高出 200 倍左右，这个时间段（1个小时左右）的会话量比平时高出一倍，但与之对应的 awr 中 Load Profile 的部分指标如 executes、transactions、redo size 等比平时反而要减少，这引起了我的好奇，于是想探究一下。

诊断案例：Failed parse elapsed time引发db time过高的案例_Java

一、awr分析

下图是高负载时段的 awr

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_02

通过上面可以看到 DB Time 2458.93 分钟，平均每秒有 40.98 的 DB Time,也就是说节点1平均活动会话数为 40.98(不包含数据库后台进程会话)，对于 cpu 个数为8的服务器来说，DB 占 CPU 资源的 512.25%。

我们在看一段正常时段的 db time(我随便截图的一个，平时的 dbtime 在80到120左右)

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_03

对比 load profile 中的信息

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_04

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_05

通过对比大部分 load profile 指标可以发现正常时段的事务量、解析数、日志、执行频率等比高负载时反而低，这意味着在负载高的时段系统的运行效率在下降，或者说系统的各项运行并没有随着会话（业务量）的增加而增加。

通过 top 5，发现排第一的是 SQL*Net break/reset to client 等待。

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_06

当使用 db_link 时，如果应用程序运行发生错误，服务器端本地的服务进程会将该信息告之远程客户端，这个告知的过程中服务进程就处于 SQL*Net break/reset to client 等待中，直到客户端收到问题信息为止，这种一般是由于应用端对 exception 的捕获不充分造成的，可以通过 10046 事件进行捕获。

不过今天想研究的是下面的这个，在这个环境中，它和上面的等待事件是相互呼应的，因为该系统中大量的数据操作都是通过 dblink 实现的；

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_07

failed parse elapsed time 意味着当我们的 sql 在进行硬解析的时候，出现了错误。主要产生错误的原因可能包含：SQL 语法错误，对象不存在，没有足够的权限等。我们在查看下高负载时段的 Instance Activity Stats

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_08

硬解析次数143次，解析失败次数达到了131次，我们在来看一个正常时段的

诊断案例：Failed parse elapsed time引发db time过高的案例_Java_09

我们可以通过 10035 事件来观察解析 sql 失败的操作来发现问题语句，从而完善代码处理逻辑，减少解析失败的几率，从某种程度上讲也会减少 SQL*Net break/reset to client 等待事件。

二、测试环境模拟10035观察解析失败sql

创建测试表；

SQL> create table aa as select * from v$mystat where rownum <6;

Table created.

SQL> desc aa;

Name Null? Type

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

SID NUMBER

STATISTIC# NUMBER

VALUE NUMBER

开启 10035 事件,并做几笔错误 sql；

SQL> select sdi1 from aa;

select sdi1 from aa

*

ERROR at line 1:

ORA-00904: "SDI1": invalid identifier

SQL> update aa set sid=sysdate where value=0;

update aa set sid=sysdate where value=0

*

ERROR at line 1:

ORA-00932: inconsistent datatypes: expected NUMBER got DATE

SQL> select * from cc;

select * from cc

*

ERROR at line 1:

ORA-00942: table or view does not exist

查看 trace 日志

Fri May 06 05:05:04 2016

PARSE ERROR: ospid=23029, error=904 for statement:

select sdi1 from aa

Additional information: hd=0x861a7168 phd=0x861dfc90 flg=0x20 cisid=0 sid=0 ciuid=0 uid=0

Fri May 06 05:06:10 2016

PARSE ERROR: ospid=23029, error=932 for statement:

update aa set sid=sysdate where value=0

Additional information: hd=0x85132fe8 phd=0x853760b0 flg=0x20 cisid=0 sid=0 ciuid=0 uid=0

Fri May 06 05:06:43 2016

PARSE ERROR: ospid=23029, error=942 for statement:

select * from cc

Additional information: hd=0x852332a0 phd=0x8524d360 flg=0x28 cisid=0 sid=0 ciuid=0 uid=0