缓慢的update语句性能分析

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

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

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

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

得到的awr部分内容如下：

Cache Sizes

BeginEnd

Buffer Cache:39,472M39,472MStd Block Size:8K

Shared Pool Size:1,440M1,440MLog Buffer:14,256K

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

Per SecondPer Transaction

Redo size:154,276.4124,024.13

Logical reads:4,864.90757.57

Block changes:779.75121.42

Physical reads:509.53

本文来源gao!%daima.com搞$代*!码网1

79.35

Physical writes:359.9056.04

User calls:2,658.46413.98

Parses:837.89130.48

Hard parses:0.090.01

Sorts:171.2226.66

Logons:0.470.07

Executes:949.10147.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 read917,81015,3101796.1User I/O

CPU time 596 3.7

log file sync16,085186121.2Commit

log file parallel write15,4661409.9System I/O

ARCH wait on SENDREQ3741027.1Network

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

Statistic NameTime (s)% of DB Time

sql execute elapsed time15,533.4397.47

DB CPU596.113.74

connection management call elapsed time82.890.52

parse time elapsed20.220.13

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

Elapsed Time (s)CPU Time (s)ExecutionsElap per Exec (s)% Total DB TimeSQL IdSQL ModuleSQL Text

8,6596962213.9254.34 update user_test t set t.login_status=” where t.CN_TEST=:1

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

IdOperationNameRowsBytesCost (%CPU)Time

0UPDATE STATEMENT 1 (100)

1 UPDATEUSER_BILLING

2 INDEX UNIQUE SCANIDX_USER_TEST_CNMASTER1301 (0)00:00:01

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

Stat NameStatement TotalPer Execution% Snap Total

Elapsed Time (ms)8,659,18013,921.5154.34

CPU Time (ms)69,346111.4911.63

Executions622

Buffer Gets3,146,0685,057.9935.91

Disk Reads645,2291,037.3570.31

Parse Calls6221.000.04

Rows621,827999.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) [email protected] 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.

喜欢 (0)赏

[搞代码]

分享 (0)