一、前言
本文讲述了一个ZLHIS删除操作案例，该操作的SQL语句执行计划中使用到索引，但是执行性能却不高，最终导致带来了严重的性能问题。通过跟踪日志分析，发现导致删除操作性能差的原因是在删除时候出现db file sequential read等待事件，进而分析阐述了产生该等待事件的原因和解决方法，最后把问题解决。本案例通过问题的排查，分析对于以后同事处理类似SQL语句性能问题有一定的参考价值。
二、渠道求助
5月10号早上正在专心的做着优化手段测试的实验，手机电话突然响起，一看来电是NM渠道的技术人员，肯定又是那个医院出了紧急问题，需要马上处理。接听电话，对方首先是一整寒暄，然后直奔主题，原来是渠道的一家医院，周末刚刚升级，升级后其他业务都正常，但是在门诊医生站病人取消接诊操作却异常的慢，一个病人取消接诊要3分钟，已经严重影响医院的正常业务。渠道的技术人员已经按照升级后的常规处理方式，对ZLHIS用户的统计信息进行了收集，但是问题依旧，渠道已经无计可施，因此申请技术支持。其实这个通过描述比较好定位，通过SQL跟踪工具就可以轻松定位问题SQL，这点技术人员也能够掌握，通过SQL跟踪工具，可以轻松定位到问题原来是Zl_病人接诊_Cancel执行性能比较差，光是这个过程执行就需要半分钟左右才能完成，渠道技术人员只能定位到这里，至于为什么这个过程执行慢，其就没有办法判断了，所以申请技术支持。
三、问题分析
其实要诊断过程为什么执行慢，我们可以通过过程调试，带入过程参数通过过程的单步调试功能，就可以跟踪出诊断出其具体执行情况，通过这种方式，我定位到了这个过程执行慢的原因，是如下的SQL语句：
Update 门诊费用记录
Set 执行人 = v_执行人, 执行状态 = 0, 执行时间 = Null, 发药窗口 = Decode(v_分诊方式, 0, Null, 发药窗口), 结论 = Null
Where NO = No_In And 记录性质 = 4 And 记录状态 In (1, 3);
单就该SQL的执行就占了Zl_病人接诊_Cancel过程的大部分时间，但是在其他正常环境中该SQL的执行只需要1秒左右，可以看到性能差距相当的明显，这时我单独把该语句提出出来，加上条件在PLSQL中执行确很快，不存在性能问题，看来该SQL语句必须在过程中性能问题才会突显，这就需要我们分析在过程执行中的该SQL语句的执行情况，我们平时查看单独的SQL语句的执行计划非常简单，但是如何查看存储过程中的SQL语句的执行计划，这里我们就必须要用到一个熟悉的方法----SQL TRACE，以前的文档中也对其进行了详细的介绍，我们这里就不做过多的说明，启用SQL TRACE的方法有很多种，为了得到更多的信息，我们这里采用dbms_session包来对Zl_病人接诊_Cancel存储过程的执行进行跟踪，新打开一个会话窗口，然后执行如下操作：
exec dbms_session.session_trace_enable(waits => True); --跟踪包括等待事件
exec Zl_病人接诊_Cancel('213685','M0064711'); ---传入参数根据实际情况调整
通过执行完上面的语句，对应的TRACE文件就在USER_DUMP_DEST下生成，但是这个原生trace文件格式比较复杂，可读性较差，我们需要通过tkprof命令行工具进行格式化才能够好的解读，格式化的语法如下：
Tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ]
参数说明：
o tracefile： 你要分析的trace文件
o outputfile： 格式化后的文件
o explain=user/password@connectstring
o table=schema.tablename
这两个参数是一起使用的，通过连接数据库对在trace文件中出现的每条sql语句查看执行计划，并将之输出到outputfile中。注意，该table必须是数据库中不存在的，如果存在会报错。为了保证信息准确,这两个参数一般不使用。
o print=n： 只列出最初N个sql执行语句
o insert=filename： 会产生一个sql文件，运行此文件可将收集到的数据insert到数据库表中
o sys=no： 过滤掉由sys执行的语句
o record=filename： 可将非嵌套执行的sql语句过滤到指定的文件中去
o waits=yes|no： 是否统计任何等待事件
o aggregate=yes|no： 是否将相同sql语句的执行信息合计起来，默认为yes
o sort=option： 设置排序选项,主要常用的有exeela（执行时间),execpu（cpu资源),execnt扫行次数等
由于我们需要查看SQL语句的执行计划，因此要使用到explain参数，这里的用户名和密码是你执行存储过程时候的用户名和密码，例如我们这里生成的原文件名为orcl1_ora_14128.trc，格式化操作如下：
tkprof D:\oracle\product\10.2.0\admin\orcl\udump\orcl1_ora_14128.trc D:\oracle\product\10.2.0\admin\orcl\udump\orcl1_ora_14128.txt explain=zlhis/his@orcl
通过上面的格式化操作，我们就得到了一个新的文件orcl1_ora_14128.txt，里面的内容就是已经格式化了的内容，接着我们就需要认真分析该文件。
首先看下整个存储过程的执行时间，如下，
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 18 0.00 0.00 0 0 16 0
Execute 20 4.02 21.42 26015 80437 32 7
Fetch 10 0.00 0.00 0 30 0 8
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 48 4.02 21.43 26015 80467 48 15
大概需要21.43秒，效率确实不高，我们再一步查看先前已经重点关注的SQL语句执行计划如下：
UPDATE 门诊费用记录 SET 执行人 = :B3 , 执行状态 = 0, 执行时间 = NULL,
发药窗口 = DECODE(:B2 , 0, NULL, 发药窗口), 结论 = NULL
WHERE
NO = :B1 AND 记录性质 = 4 AND 记录状态 IN (1, 3)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 3.98 21.39 26015 80366 28 4
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 3.98 21.39 26015 80366 28 4
需要21.39秒，占整个过程执行时间的99%，因此也可以判断这就是该过程执行慢的根本原因，另外我们还可以看出，物理读非常大，难道是没有或者走错了索引导致？我们再来看下这个SQL语句的执行计划，如下：
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 65 (ZLHIS) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
0 UPDATE OF '门诊费用记录'
0 INDEX MODE: ANALYZED (RANGE SCAN) OF '门诊费用记录_UQ_NO'
(INDEX (UNIQUE))
从执行计划看，没有什么问题，用到了门诊费用记录_UQ_NO索引，而且走的是索引范围扫描，同单独提取该SQL在PLSQL执行的执行计划是一样的，这就奇怪了，但是我们再观察其他信息，发现该语句执行过程中，出现了如下的等待事件：
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 7168 0.09 4.66
db file scattered read 5252 0.10 3.92
这就很奇怪了，特别是db file scattered read等待事件，在使用索引范围扫面的情况下，是不应该出现的，为什么这里会出现呢？带着这个疑问，在metalink中进行了查询，还真让我找到了一篇文章《Delete or Update running slow -- db file scattered read waits on index range scan [ID 296727.1]》，这篇文章给出了详细的解释，在使用了索引范围扫面出现db file scattered read和db file sequential reads等待事件原因：
1.由于每次进行索引范围扫描操作时，都需要对索引叶块进行预取（prefetching）操作，而在删除和修改操作时候，oracle要对预取指数进行维护，因此出现了db file sequential read和db file scattered read等待事件。
2.oracle有个隐含参数“_db_file_noncontig_mblock_read_count”定义了索引每次预期的数据块数，默认是11。
一般情况下，预取指数很少会影响查询的性能，在考虑到用户那里也没做任何修改的情况下，决定不动隐含参数，毕竟隐含参数的修改存在一定的风险，文档中提供了两种处理方式：1.重建索引；2.在WHERE条件中加入更多的索引字段，这里我们采用重建索引的方式，如下：
alter index 门诊费用记录_UQ_NO rebuild online;
四、问题解决
通过重建完索引后，我们再次操作取消接诊，只需要1秒多钟，就完成操作，看来问题已经得到解决，我们再次对Zl_病人接诊_Cancel过程进行一个SQL TRACE操作，生成个TRACE文件，格式化后，结果如下：
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 16 0.00 0.00 0 0 0 0
Execute 18 1.26 1.23 0 45072 34 7
Fetch 8 0.00 0.00 0 28 0 8
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 42 1.27 1.24 0 45100 34 15
可以看到，整个过程的执行时间已经骤减到1.24秒，然后我们再看看刚才那个SQL语句的执行计划，如下：
UPDATE 门诊费用记录 SET 执行人 = :B3 , 执行状态 = 0, 执行时间 = NULL,
发药窗口 = DECODE(:B2 , 0, NULL, 发药窗口), 结论 = NULL
WHERE
NO = :B1 AND 记录性质 = 4 AND 记录状态 IN (1, 3)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 1.24 1.21 0 45001 30 4
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 1.24 1.21 0 45001 30 4
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 65 (ZLHIS) (recursive depth: 1)
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
0 UPDATE OF '门诊费用记录'
0 INLIST ITERATOR
0 INDEX MODE: ANALYZED (RANGE SCAN) OF '门诊费用记录_UQ_NO'
(INDEX (UNIQUE))
*******************************************************************************
物理读已经没有了，执行时间同样骤减到1.21秒，而且先前的db file sequential read和db file scattered read等待事件也不在了，这个问题已经得到了处理，随后的几天观察也未再次出现性能问题，至此问题得到圆满解决。
五、小结
通过本案例，我们简单的分析下为什么会出现该性能问题，我想ORACLE内部维护有一套复杂的机制，再一些特定的环境下，这些机制可能出现问题，从而导致出现性能问题，如本例中就是索引的叶块的预期值在进行维护的时候，出现了性能问题，通过重建该索引，相当于重新构建了维护机制，从而解决了问题，另外我们从该问题的解决过程可以得到一些启示：
1.处理性能问题，SQL TRACE是一个非常有用的手段，我们每个技术人员都应该掌握。
2.对于隐含参数，再没有特殊必要的情况下，尽量少用。
3.多利用ORACLE在线帮助，这是一个宝库里面包含了许多我们想要的知识。
希望本文对各位技术人员以后在处理类似问题时，有一个清晰的处理思路，不必再不知所措。