缓慢的update语句性能分析

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

最近处理一个问题的时候，先是收到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

但是查看sql语句的执行统计信息，就有些奇怪了。

Stat NameStatement TotalPer Execution% Snap Total

Elapsed Time (ms) 8,659,180 13,921.51 54.34

CPU Time (ms) 69,346 111.49 11.63

Executions 622    

Buffer Gets 3,146,068 5,057.99 35.91

Disk Reads 645,229 1,037.35 70.31

Parse Calls 622 1.00 0.04

Rows 621,827 999.72  

User I/O Wait Time (ms) 8,608,075  

sql语句的执行总共持续8659s左右，然后8608s的时间在user I/O的等待上，这样下来，622次的执行其实花费的时间并不多。
 对于这个问题，自己也比较疑惑，开始怀疑是否是磁盘的IO上出现了问题。
 但是使用MegaCli查看的时候，发现不存在任何的坏块。
# MegaCli -CfgDsply -a0|grep Error
 Media Error Count: 0
 Other Error Count: 0
 Media Error Count: 0
 Other Error Count: 0
 Media Error Count: 0
 Other Error Count: 0
 Media Error Count: 0
 Other Error Count: 0
 Media Error Count: 0
 Other Error Count: 0
 Media Error Count: 0
 Other Error Count: 0
 Media Error Count: 0
这个时候的一个猜测就是可能由绑定变量的数据类型不同导致的sql性能问题。但是排查一番，发现还是没有得到自己期望的结果。
 查看输入的参数类型，都是期望中的varchar2，所以sql语句的过程中还是不会出现自己猜想的全表扫描的可能性。
  select name,datatype_string,value_string,datatype from DBA_HIST_SQLBIND where sql_id='94p345yuqh3zd' and snap_id between 58711 and 58712
 NAME                          DATATYPE_STRING VALUE_STRING                    DATATYPE
 ------------------------------ --------------- ------------------------------ ----------
 :1                            VARCHAR2(128)  xxxxxx9@test.com                        1
 :1                            VARCHAR2(128)  23234324324234                              1
对于IO的瓶颈问题，自己还是从addm中得到了自己需要的东西。
 对于磁盘吞吐量的说法，addm的报告中是这么描述的。

FINDING 6: 39% impact (6136 seconds)
 ------------------------------------
 The throughput of the I/O subsystem was significantly lower than expected.