解决删除操作过程执行慢的案例分析 db file scattered read

一、前言

    本文讲述了一个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在线帮助，这是一个宝库里面包含了许多我们想要的知识。

希望本文对各位技术人员以后在处理类似问题时，有一个清晰的处理思路，不必再不知所措。