查詢條件為ROWNUM=1仍產生長時間等待

yangtingkun發表於2011-10-26

正常情況下,指定了ROWNUM=1會迅速的返回結果,但是也有異常的情況產生。

 

 

其實ROWNUM1之所以可以快速的返回結果,是由於執行計劃中採用了STOPKEY的方式,當查詢到第一條符合要求的記錄後,執行就中止了。

但是ROWNUM=1並非對所有情況都適用,比如如果記憶體查詢包含GROUP BY操作,那麼ROWNUM=1就無法推到GROUP BY查詢內部,因此這時的ROWNUM=1的條件對於查詢速度的提高就非常有限了。還有一種情況,在指定了一個限制條件後,加上ROWNUM=1後,發現查詢效率仍然不高。這時因為表中滿足指定限制條件的記錄非常少或者根本沒有,以致於Oracle要掃描全部表資料後才能返回結果。

但是客戶碰到了的現象和上面描述的幾種情況都不相符,查詢只是一個單表查詢,唯一的限制條件就是ROWNUM=1,沒有GROUP BYORDER BY語句,語句就是簡單到不能再簡單的:select * from RTDRULETRACEHISTORY where rownum = 1

檢查了這個語句的執行計劃,並未發現異常之處:

Id  Operation             Name                Rows  Bytes  Cost (%CPU) Time 
0   SELECT STATEMENT                                       2 (100)  
1     COUNT STOPKEY           
2       TABLE ACCESS FULL RTDRULETRACEHISTORY  1    827    2 (0)       00:00:01 

嘗試指定索引列的條件,透過索引掃描的方式來訪問這個表,查詢瞬間就可以返回結果。這說明表本身沒有問題。觀察查詢時刻的等待事件,發現絕大部分是正常的db file scattered readgc cr multi block request等待,這說明並不是latch之類的將資源鎖住。

*** 2011-10-18 10:16:35.765
*** ACTION NAME:() 2011-10-18 10:16:35.722
*** MODULE NAME:(SQL*Plus) 2011-10-18 10:16:35.722
*** SERVICE NAME:(SYS$USERS) 2011-10-18 10:16:35.722
*** SESSION ID:(1500.50317) 2011-10-18 10:16:35.722
WAIT #8: nam='SQL*Net message to client' ela= 9 driver id=1650815232 #bytes=1 p3=0 obj#=12803 tim=31019702733135
*** 2011-10-18 10:16:46.489
WAIT #8: nam='SQL*Net message from client' ela= 10471689 driver id=1650815232 #bytes=1 p3=0 obj#=12803 tim=31019713247383
=====================
PARSING IN CURSOR #4 len=50 dep=0 uid=33 ct=3 lid=33 tim=31019713253946 hv=3186239259 ad='964fa8b0'
select * from RTDRULETRACEHISTORY where rownum = 1
END OF STMT
PARSE #4:c=10000,e=5864,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=31019713253748
BINDS #4:
EXEC #4:c=0,e=215,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=31019713254416
WAIT #4: nam='SQL*Net message to client' ela= 13 driver id=1650815232 #bytes=1 p3=0 obj#=12803 tim=31019713254581
WAIT #4: nam='gc cr multi block request' ela= 2041 file#=22 block#=352168 class#=1 obj#=12803 tim=31019713257631
WAIT #4: nam='db file scattered read' ela= 1195 file#=22 block#=352164 blocks=5 obj#=12803 tim=31019713259143
WAIT #4: nam='gc cr multi block request' ela= 1888 file#=22 block#=352176 class#=1 obj#=12803 tim=31019713261925
WAIT #4: nam='db file scattered read' ela= 1732 file#=22 block#=352169 blocks=8 obj#=12803 tim=31019713264136
WAIT #4: nam='gc cr multi block request' ela= 1699 file#=22 block#=352184 class#=1 obj#=12803 tim=31019713266769
WAIT #4: nam='db file scattered read' ela= 764 file#=22 block#=352178 blocks=7 obj#=12803 tim=31019713267883
WAIT #4: nam='gc cr multi block request' ela= 1357 file#=22 block#=352192 class#=1 obj#=12803 tim=31019713270308
WAIT #4: nam='gc cr multi block request' ela= 215 file#=22 block#=352192 class#=1 obj#=12803 tim=31019713270605
WAIT #4: nam='db file scattered read' ela= 1489 file#=22 block#=352185 blocks=8 obj#=12803 tim=31019713272209
WAIT #4: nam='gc cr multi block request' ela= 46 file#=22 block#=352200 class#=1 obj#=12803 tim=31019713273728
WAIT #4: nam='gc cr multi block request' ela= 1897 file#=22 block#=352200 class#=1 obj#=12803 tim=31019713275710
WAIT #4: nam='db file scattered read' ela= 836 file#=22 block#=352194 blocks=7 obj#=12803 tim=31019713276890
WAIT #4: nam='gc cr multi block request' ela= 1555 file#=22 block#=352208 class#=1 obj#=12803 tim=31019713279226
WAIT #4: nam='db file scattered read' ela= 1397 file#=22 block#=352201 blocks=8 obj#=12803 tim=31019713280861
WAIT #4: nam='gc cr multi block request' ela= 2194 file#=22 block#=352216 class#=1 obj#=12803 tim=31019713284098
WAIT #4: nam='db file scattered read' ela= 971 file#=22 block#=352210 blocks=7 obj#=12803 tim=31019713285421
WAIT #4: nam='gc cr multi block request' ela= 1394 file#=22 block#=352224 class#=1 obj#=12803 tim=31019713287803
WAIT #4: nam='gc cr multi block request' ela= 153 file#=22 block#=352222 class#=1 obj#=12803 tim=31019713288044
WAIT #4: nam='db file scattered read' ela= 1206 file#=22 block#=352217 blocks=8 obj#=12803 tim=31019713289370
WAIT #4: nam='gc cr multi block request' ela= 1577 file#=22 block#=352232 class#=1 obj#=12803 tim=31019713291581
WAIT #4: nam='db file scattered read' ela= 1157 file#=22 block#=352226 blocks=7 obj#=12803 tim=31019713293069
WAIT #4: nam='gc cr multi block request' ela= 2132 file#=22 block#=352240 class#=1 obj#=12803 tim=31019713296012
WAIT #4: nam='db file scattered read' ela= 1285 file#=22 block#=352233 blocks=8 obj#=12803 tim=31019713297485
WAIT #4: nam='gc cr multi block request' ela= 1575 file#=22 block#=352248 class#=1 obj#=12803 tim=31019713300039
WAIT #4: nam='db file scattered read' ela= 2419 file#=22 block#=352242 blocks=7 obj#=12803 tim=31019713302788
WAIT #4: nam='gc cr multi block request' ela= 31 file#=22 block#=352255 class#=1 obj#=12803 tim=31019713303561
WAIT #4: nam='gc cr multi block request' ela= 1354 file#=22 block#=352255 class#=1 obj#=12803 tim=31019713305054
WAIT #4: nam='db file scattered read' ela= 1346 file#=22 block#=352249 blocks=8 obj#=12803 tim=31019713306635
WAIT #4: nam='db file scattered read' ela= 740 file#=22 block#=352258 blocks=4 obj#=12803 tim=31019713308265
WAIT #4: nam='db file scattered read' ela= 971 file#=22 block#=352263 blocks=2 obj#=12803 tim=31019713309864
WAIT #4: nam='db file scattered read' ela= 1146 file#=23 block#=353033 blocks=7 obj#=12803 tim=31019713311595
WAIT #4: nam='db file scattered read' ela= 1169 file#=23 block#=353042 blocks=7 obj#=12803 tim=31019713313700
WAIT #4: nam='db file scattered read' ela= 2273 file#=23 block#=353049 blocks=8 obj#=12803 tim=31019713316548
WAIT #4: nam='db file scattered read' ela= 1663 file#=24 block#=357643 blocks=16 obj#=12803 tim=31019713319295
WAIT #4: nam='db file scattered read' ela= 3674 file#=24 block#=357659 blocks=16 obj#=12803 tim=31019713324249
WAIT #4: nam='db file scattered read' ela= 2430 file#=24 block#=357675 blocks=16 obj#=12803 tim=31019713328180
WAIT #4: nam='db file scattered read' ela= 2894 file#=24 block#=357691 blocks=16 obj#=12803 tim=31019713332267
WAIT #4: nam='db file scattered read' ela= 7359 file#=24 block#=357707 blocks=16 obj#=12803 tim=31019713341148
WAIT #4: nam='db file scattered read' ela= 1682 file#=24 block#=357723 blocks=8 obj#=12803 tim=31019713343705
WAIT #4: nam='db file scattered read' ela= 1493 file#=24 block#=357732 blocks=16 obj#=12803 tim=31019713346356
WAIT #4: nam='gc cr multi block request' ela= 47 file#=24 block#=357763 class#=1 obj#=12803 tim=31019713347548
WAIT #4: nam='gc cr multi block request' ela= 1538 file#=24 block#=357763 class#=1 obj#=12803 tim=31019713349157
WAIT #4: nam='gc cr multi block request' ela= 79 file#=24 block#=357763 class#=1 obj#=12803 tim=31019713349320
WAIT #4: nam='gc cr multi block request' ela= 61 file#=24 block#=357763 class#=1 obj#=12803 tim=31019713349576
WAIT #4: nam='gc cr multi block request' ela= 62 file#=24 block#=357763 class#=1 obj#=12803 tim=31019713349688
WAIT #4: nam='db file scattered read' ela= 2292 file#=24 block#=357748 blocks=16 obj#=12803 tim=31019713352166
WAIT #4: nam='gc cr multi block request' ela= 1713 file#=24 block#=357768 class#=1 obj#=12803 tim=31019713354600
WAIT #4: nam='db file scattered read' ela= 942 file#=24 block#=357764 blocks=5 obj#=12803 tim=31019713355837
WAIT #4: nam='db file scattered read' ela= 1830 file#=22 block#=352267 blocks=16 obj#=12803 tim=31019713358515
WAIT #4: nam='db file scattered read' ela= 2326 file#=22 block#=352283 blocks=16 obj#=12803 tim=31019713362098
WAIT #4: nam='db file scattered read' ela= 1546 file#=22 block#=352299 blocks=16 obj#=12803 tim=31019713364587
WAIT #4: nam='db file scattered read' ela= 2004 file#=22 block#=352315 blocks=16 obj#=12803 tim=31019713367496
WAIT #4: nam='db file scattered read' ela= 1926 file#=22 block#=352331 blocks=16 obj#=12803 tim=31019713370250
WAIT #4: nam='db file scattered read' ela= 1750 file#=22 block#=352347 blocks=16 obj#=12803 tim=31019713373524
WAIT #4: nam='db file scattered read' ela= 1375 file#=22 block#=352363 blocks=16 obj#=12803 tim=31019713375927
WAIT #4: nam='gc cr multi block request' ela= 2280 file#=22 block#=352392 class#=1 obj#=12803 tim=31019713380187
WAIT #4: nam='db file scattered read' ela= 6749 file#=22 block#=352379 blocks=14 obj#=12803 tim=31019713387286
WAIT #4: nam='gc cr multi block request' ela= 2624 file#=23 block#=353178 class#=1 obj#=12803 tim=31019713391083
WAIT #4: nam='db file scattered read' ela= 1645 file#=23 block#=353163 blocks=16 obj#=12803 tim=31019713392893
WAIT #4: nam='gc cr multi block request' ela= 1470 file#=23 block#=353194 class#=1 obj#=12803 tim=31019713395432
WAIT #4: nam='gc cr multi block request' ela= 498 file#=23 block#=353194 class#=1 obj#=12803 tim=31019713396168
WAIT #4: nam='db file scattered read' ela= 2708 file#=23 block#=353179 blocks=16 obj#=12803 tim=31019713399190
WAIT #4: nam='gc cr multi block request' ela= 70 file#=23 block#=353210 class#=1 obj#=12803 tim=31019713401176
WAIT #4: nam='gc cr multi block request' ela= 2393 file#=23 block#=353210 class#=1 obj#=12803 tim=31019713403660
WAIT #4: nam='db file scattered read' ela= 2962 file#=23 block#=353195 blocks=16 obj#=12803 tim=31019713406784
WAIT #4: nam='gc cr multi block request' ela= 2055 file#=23 block#=353220 class#=1 obj#=12803 tim=31019713409738
WAIT #4: nam='db file scattered read' ela= 1882 file#=23 block#=353211 blocks=10 obj#=12803 tim=31019713411882
WAIT #4: nam='gc cr multi block request' ela= 43 file#=23 block#=353237 class#=1 obj#=12803 tim=31019713414032
WAIT #4: nam='gc cr multi block request' ela= 2417 file#=23 block#=353237 class#=1 obj#=12803 tim=31019713416569
WAIT #4: nam='db file scattered read' ela= 1825 file#=23 block#=353222 blocks=16 obj#=12803 tim=31019713418775
WAIT #4: nam='gc cr multi block request' ela= 1917 file#=23 block#=353245 class#=1 obj#=12803 tim=31019713421691
WAIT #4: nam='gc cr multi block request' ela= 90 file#=23 block#=353245 class#=1 obj#=12803 tim=31019713421908
WAIT #4: nam='gc cr multi block request' ela= 62 file#=23 block#=353245 class#=1 obj#=12803 tim=31019713422020
WAIT #4: nam='gc cr multi block request' ela= 84 file#=23 block#=353245 class#=1 obj#=12803 tim=31019713422253
WAIT #4: nam='db file scattered read' ela= 1067 file#=23 block#=353238 blocks=8 obj#=12803 tim=31019713423663
WAIT #4: nam='gc cr multi block request' ela= 41 file#=23 block#=353251 class#=1 obj#=12803 tim=31019713424512
WAIT #4: nam='gc cr multi block request' ela= 1167 file#=23 block#=353251 class#=1 obj#=12803 tim=31019713425733
WAIT #4: nam='gc cr multi block request' ela= 265 file#=23 block#=353251 class#=1 obj#=12803 tim=31019713426060
WAIT #4: nam='db file scattered read' ela= 1041 file#=23 block#=353247 blocks=5 obj#=12803 tim=31019713427205
WAIT #4: nam='gc cr multi block request' ela= 2468 file#=23 block#=353268 class#=1 obj#=12803 tim=31019713430616
WAIT #4: nam='db file scattered read' ela= 1562 file#=23 block#=353253 blocks=16 obj#=12803 tim=31019713432505
.
.
.
WAIT #4: nam='db file scattered read' ela= 12261 file#=23 block#=582746 blocks=16 obj#=12803 tim=31019894112271
WAIT #4: nam='db file scattered read' ela= 4545 file#=23 block#=582762 blocks=16 obj#=12803 tim=31019894118627
WAIT #4: nam='gc cr multi block request' ela= 55 file#=23 block#=582792 class#=1 obj#=12803 tim=31019894119991
WAIT #4: nam='gc cr multi block request' ela= 2321 file#=23 block#=582792 class#=1 obj#=12803 tim=31019894122435
WAIT #4: nam='db file scattered read' ela= 35721 file#=23 block#=582778 blocks=15 obj#=12803 tim=31019894158558
WAIT #4: nam='db file scattered read' ela= 2538 file#=24 block#=588562 blocks=16 obj#=12803 tim=31019894163029
FETCH #4:c=73150000,e=180908720,p=532660,cr=537132,cu=0,mis=0,r=1,dep=0,og=1,tim=31019894163425
WAIT #4: nam='SQL*Net message from client' ela= 2818 driver id=1650815232 #bytes=1 p3=0 obj#=12803 tim=31019894166521
FETCH #4:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=31019894166683
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=12803 tim=31019894166836
*** 2011-10-18 10:20:15.486
WAIT #4: nam='SQL*Net message from client' ela= 23178892 driver id=1650815232 #bytes=1 p3=0 obj#=12803 tim=31019917345799
STAT #4 id=1 cnt=1 pid=0 pos=1 bj=0 p='COUNT STOPKEY (cr=537132 pr=532660 pw=0 time=180908666 us)'
STAT #4 id=2 cnt=1 pid=1 pos=1 bj=12803 p='TABLE ACCESS FULL RTDRULETRACEHISTORY (cr=537132 pr=532660 pw=0 time=180908601 us)'
=====================
PARSING IN CURSOR #10 len=55 dep=0 uid=33 ct=42 lid=33 tim=31019917347295 hv=2217940283 ad='0'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #10:c=0,e=633,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=31019917347273
EXEC #10:c=0,e=283,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=31019917347733

詢問了一下這張表的業務處理邏輯,找到了最終問題所在。這是表存放的資料只會保留一段時間,因此每天都會執行刪除操作來刪除。大量刪除的操作使得表的前部產生大量的空塊,因此Oracle即使要獲取一條資料,也要掃描這些空塊知道找到第一條未刪除的記錄。這和即使表中沒有資料,但是高水位線很高,COUNT(*)操作也要執行很長時間的道理是一樣的。

根據表的統計資訊計算,表中接近一半的大小的空的,而這些空行幾種分佈在表的前端,造成了這個問題的產生,解決問題的方法很簡單,對於可以短時間中斷業務的環境,只需要MOVE然後REBUILD索引既可,而對於業務不能停頓的系統,可以使用SHRINK來線上回收表中的空閒空間,當然如果表上的操作比較頻繁,還可以使用線上重定義來接近問題。

雖然問題解決了,但是要規避這個問題的再次出現,還必須建立適合的資料生命週期管理方案,透過合理高效的方式來處理資料,避免透過大量的DELETE刪除過期資料。

 

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/4227/viewspace-709763/,如需轉載,請註明出處,否則將追究法律責任。

相關文章