这几天遇见一份 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)