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

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

在 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 等比平时反而要减少，这引起了我的好奇，于是想探究一下。

一、awr分析

下图是高负载时段的 awr

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

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

对比 load profile 中的信息

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

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

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

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

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

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

我们可以通过 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

通过 10035 事件，可以帮我们发现程序中那些不太完善需改进的 sql 语句；做为临时性解决办法，也可以采用调整 _cursor_features_enabled 隐藏参数的方式，具体调整方式可以查看 mos 文档：

How to Identify Hard Parse Failures (文档 ID 1353015.1)

Resolving Issues Where High ‘failed parse elapsed time’ Seen Due to SQL Receiving Errors on Parse/Execute (文档 ID 1476070.1)

资源下载

关注公众号：数据和云（OraNews）回复关键字获取

2018DTCC , 数据库大会PPT

2017DTC，2017 DTC 大会 PPT

DBALIFE ，“DBA 的一天”海报

DBA04 ，DBA 手记4 电子书

122ARCH ，Oracle 12.2体系结构图

2017OOW ，Oracle OpenWorld 资料

PRELECTION ，大讲堂讲师课程资料

近期文章

仅仅使用AWR做报告? 性能优化还未入门

实战课堂：一则CPU 100%的故障分析

杨廷琨:如何编写高效SQL(含PPT)

一份高达555页的技术PPT会是什么样子？

大象起舞：用PostgreSQL解海盗分金问题