緩慢的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.

聲明：本網頁內容旨在傳播知識，若有侵權等問題請及時與本網聯系，我們將在第一時間刪除處理。TEL:177 7030 7066 E-MAIL:11247931@qq.com