1. 程式人生 > 其它 >緩慢的update語句效能分析(r6筆記第61天)

緩慢的update語句效能分析(r6筆記第61天)

最近處理一個問題的時候,先是收到DB time升高的報警,然後檢視DB time的情況發現,已經有近1000%的負載了。

帶著好奇心想看看到底是什麼樣的一個語句導致如此的情況。 先抓取了一個awr報告,因為問題發生的時間段比較集中而且時間持續有幾個小時,所以抓取了一個小時的快照。 得到的awr部分內容如下:

Cache Sizes

Begin

End

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 Second

Per 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上還是存在較大的影響。我們先放過這個問題,繼續往下看。

Event

Waits

Time(s)

Avg Wait(ms)

% Total Call Time

Wait 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 Name

Time (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)

Executions

Elap per Exec (s)

% Total DB Time

SQL Id

SQL Module

SQL Text

8,659

69

622

13.92

54.34

94p345yuqh3zd

update user_test t set t.login_status='' where t.CN_TEST=:1

第一感覺就是這個語句走了全表掃描,因為一個簡單的Update竟然需要花費近13秒的時間,已經算很長的了。 當然猜測也需要驗證,我們來看看awrsqrpt的結果。 發現這個報告還是蠻有意思。至於執行計劃是走了唯一性索引掃描,所以執行計劃的情況來看還是沒有問題的。

Id

Operation

Name

Rows

Bytes

Cost (%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 Name

Statement Total

Per 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) [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.

RECOMMENDATION 1: Host Configuration, 39% benefit (6136 seconds) ACTION: Consider increasing the throughput of the I/O subsystem. Oracle's recommended solution is to stripe all data file using the SAME methodology. You might also need to increase the number of disks for better performance. Alternatively, consider using Oracle's Automatic Storage Management solution. RATIONALE: During the analysis period, the average data files' I/O throughput was 3.9 M per second for reads and 2.7 M per second for writes. The average response time for single block reads was 16 milliseconds. 這個部分還是能夠說明問題的,在IO上還是遇到了較大的瓶頸。這些延遲等待是造成DB time急劇升高的主因。 當然了我們也不能按照addm的說法,直接替換成asm,這個不是馬上能夠實現的方法。 但是在awr報告中還是發現了一絲蛛絲馬跡,有一些輔助的調優方法。 第一個就是shared pool的大小,這個庫大概有1000個session,但是因為使用了sga的自動管理,結果shared pool被30G的空間中只剩下了1.4G左右的快取,很明顯對於支援1000多個session的庫來說,shard pool被壓榨的太多了,可以指定一個稍大一些的值,保證shared pool不被全部榨乾。 另外一個問題就是update執行如此緩慢,出了user I/O的原因之外,可以一個執行極為頻繁的sql語句掃描的是同一張表,會造成一些熱塊的爭用。同時會為了支援一致性讀,勢必在undo上會有較大的消耗,查看了這個庫的undo還是一個相對較小的值,可以調大一些。