缓慢的update语句性能分析

最近处理一个问题的时候，先是收到DB time升高的报警，然后查看DB time的情况发现，已经有近1000%的负载了。

带着好奇心想看看到底是什么样的一个语句导致如此的情况。

先抓取了一个awr报告，因为问题发生的时间段比较集中而且时间持续有几个小时，所以抓取了一个小时的快照。

得到的awr部分内容如下：

Cache Sizes

 BeginEnd  
Buffer Cache:   39,472M   39,472M   Std Block Size:   8K  
Shared Pool Size:   1,440M   1,440M   Log Buffer:   14,256K  

从下面的部分可以看出数据库其实内部的活动并不多，redo生成量不高，tps也不高。
Load Profile

 Per SecondPer Transaction
Redo size:   154,276.41   24,024.13  
Logical reads:   4,864.90   757.57  
Block changes:   779.75   121.42  
Physical reads:   509.53   79.35  
Physical writes:   359.90   56.04  
User calls:   2,658.46   413.98  
Parses:   837.89   130.48  
Hard parses:   0.09   0.01  
Sorts:   171.22   26.66  
Logons:   0.47   0.07  
Executes:   949.10   147.80  
Transactions:   6.42      

而查看等待时间，发现第一个等待事件是db file sequential read,平均等待时间有近17ms,

延迟一般需要在10ms以下,或者至少100 reads/sec，在基于SAN存储缓存数据的情况下，sequential read的指标有时候会保持在2ms左右，这个只能说明SAN已经把数据转化为缓存了，倒不能说明硬盘驱动确实很快。这个地方已经超过了10ms说明IO上还是存在较大的影响。我们先放过这个问题，继续往下看。

EventWaitsTime(s)Avg Wait(ms)% Total Call TimeWait Class
db file sequential read   917,810   15,310   17   96.1   User I/O  
CPU time       596       3.7      
log file sync   16,085   186   12   1.2   Commit  
log file parallel write   15,466   140   9   .9   System I/O  
ARCH wait on SENDREQ   374   10   27   .1   Network  

而根据时间模型来看，绝大部分的DB time都在sql语句方面，所以关注sql语句就是一个很重要的部分。

Statistic NameTime (s)% of DB Time
sql execute elapsed time   15,533.43   97.47  
DB CPU   596.11   3.74  
connection management call elapsed time   82.89   0.52  
parse time elapsed   20.22   0.13  

而对于top1的sql语句让自己和吃惊，竟然是一个很简单的update.

Elapsed Time (s)CPU Time (s)ExecutionsElap per Exec (s)% Total DB TimeSQL IdSQL ModuleSQL Text
8,659   69   622   13.92   54.34         update user_test t set t.login_status='' where t.CN_TEST=:1  

第一感觉就是这个语句走了全表扫描，因为一个简单的Update竟然需要花费近13秒的时间，已经算很长的了。
当然猜测也需要验证，我们来看看awrsqrpt的结果。
发现这个报告还是蛮有意思。至于执行计划是走了唯一性索引扫描，所以执行计划的情况来看还是没有问题的。

IdOperationNameRowsBytesCost (%CPU)Time
0   UPDATE STATEMENT               1 (100)      
1     UPDATE   USER_BILLING                  
2       INDEX UNIQUE SCAN   IDX_USER_TEST_CNMASTER   1   30   1 (0)   00:00:01