link:

http://www.eygle.com/case/sql_trace_1.htm

問題描述:

這是幫助一個公司的診斷案例.
應用是一個后臺新聞發布系統.

癥狀是,通過連接訪問新聞頁是極其緩慢
通常需要十數秒才能返回.

這種性能是用戶不能忍受的.

操作系統:sunos 5.8
數據庫版本:8.1.7


1.檢查并跟蹤數據庫進程
診斷時是晚上,無用戶訪問
在前臺點擊相關頁面,同時進行進程跟蹤

查詢v$session視圖,獲取進程信息


 

sql> select sid,serial#,username from v$session; sid serial# username---------- ---------- ------------------------------ 1 1 2 1 3 1 4 1 5 1 6 1 7 284 iflow 11 214 iflow 12 164 sys 16 1042 iflow10 rows selected.

啟用相關進程sql_trace


 

sql> exec dbms_system.set_sql_trace_in_session(7,284,true)pl/sql procedure successfully completed.sql> exec dbms_system.set_sql_trace_in_session(11,214,true)pl/sql procedure successfully completed.sql> exec dbms_system.set_sql_trace_in_session(16,1042,true)pl/sql procedure successfully completed.sql> select sid,serial#,username from v$session; sid serial# username---------- ---------- ------------------------------ 1 1 2 1 3 1 4 1 5 1 6 1 7 284 iflow 11 214 iflow 12 164 sys 16 1042 iflow10 rows selected.

等候一段時間,關閉sql_trace


 

sql> exec dbms_system.set_sql_trace_in_session(7,284,false)pl/sql procedure successfully completed.sql> exec dbms_system.set_sql_trace_in_session(11,214,false)pl/sql procedure successfully completed.sql> exec dbms_system.set_sql_trace_in_session(16,1042,false)pl/sql procedure successfully completed.

2.檢查trace文件

檢查發現以下語句是可疑的


 

********************************************************************************select auditstatus,categoryid,auditlevel from categoryarticleassign a,category b where b.id=a.categoryid and articleid= 20030700400141 and auditstatus>0call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------parse 1 0.00 0.00 0 0 0 0execute 1 0.00 0.00 0 0 0 0fetch 1 0.81 0.81 0 3892 0 1------- ------ -------- ---------- ---------- ---------- ---------- ----------total 3 0.81 0.81 0 3892 0 1********************************************************************************

這里顯然是根據articleid進行新聞讀取的.
很可疑的是query讀取有3892

這個內容引起了我的注意.
如果遇到過類似的問題，大家在這里就應該知道是怎么回事情了.
如果沒有遇到過的朋友，可以在這里思考一下再往下看.

misses in library cache during parse: 1optimizer goal: chooseparsing user id: 41 rows row source operation------- --------------------------------------------------- 1 nested loops 2 index range scan (object id 25062) 1 table access by index rowid category 2 index unique scan (object id 25057)********************************************************************************select auditstatus,categoryid from categoryarticleassign where articleid=20030700400138 and categoryid in ('63', '138','139','140','141','142','143','144','168','213','292','341','346', '347','348','349','350','351','352','353','354','355','356','357','358', '359','360','361','362','363','364','365','366','367','368','369','370', '371','372','383','460','461','462','463','621','622','626','629','631', '634','636','643','802','837','838','849','850','851','852','853','854', '858','859','860','861','862','863','-1')call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------parse 1 0.00 0.00 0 0 0 0execute 1 0.00 0.00 0 0 0 0fetch 1 4.91 4.91 0 2835 7 1------- ------ -------- ---------- ---------- ---------- ---------- ----------total 3 4.91 4.91 0 2835 7 1misses in library cache during parse: 1optimizer goal: chooseparsing user id: 41 rows row source operation------- --------------------------------------------------- 1 'table access full categoryarticleassign'我們注意到，這里有一個全表掃描存在********************************************************************************




 


3.登陸數據庫,檢查相應表結構




 


sql> select index_name,table_name,column_name from user_ind_columns 2 where table_name=upper('categoryarticleassign');index_name table_name column_name ------------------------------ ------------------------------ -------------------- idx_articleid categoryarticleassign articleidind_articleid_categ categoryarticleassign articleid ind_articleid_categ categoryarticleassign categoryid idx_sortid categoryarticleassign sortid pk_categoryarticleassign categoryarticleassign articleid pk_categoryarticleassign categoryarticleassign categoryid pk_categoryarticleassign categoryarticleassign assigntype idx_cat_article categoryarticleassign auditstatus idx_cat_article categoryarticleassign articleid idx_cat_article categoryarticleassign categoryid idx_cat_article categoryarticleassign assigntype 11 rows selected.


我們注意到,idx_articleid索引在以上查詢中都沒有被用到.

檢查表結構:


 

sql> desc categoryarticleassign name null? type ----------------------------------------- -------- ---------------------------- categoryid not null number articleid not null varchar2(14) assigntype not null varchar2(1) auditstatus not null number sortid not null number unpass varchar2(255)



問題發現:
因為articleid是個字符型數據,查詢中給入的articleid= 20030700400141 是一個數字值
oracle發生潛在的數據類型轉換,從而導致了索引失效



 

sql> select auditstatus,categoryid 2 from 3 categoryarticleassign where articleid=20030700400132;auditstatus categoryid ----------- ---------- 9 94 0 383 0 695 elapsed: 00:00:02.62execution plan---------------------------------------------------------- 0 select statement optimizer=choose (cost=110 card=2 bytes=38) 1 0 table access (full) of 'categoryarticleassign' (cost=110 card=2 bytes=38)





4.解決方法

簡單的在參數兩側各增加一個',既可解決這個問題.

對于類似的查詢,我們發現query模式讀取降低為2
幾乎不需要花費cpu時間了


 ********************************************************************************select unpass from categoryarticleassign where articleid='20030320000682' and categoryid='113' call count cpu elapsed disk query current rows------- ------ -------- ---------- ---------- ---------- ---------- ----------parse 1 0.00 0.00 0 0 0 0execute 1 0.00 0.00 0 0 0 0fetch 1 0.00 0.00 0 2 0 0------- ------ -------- ---------- ---------- ---------- ---------- ----------total 3 0.00 0.00 0 2 0 0misses in library cache during parse: 1optimizer goal: chooseparsing user id: 20 rows row source operation------- --------------------------------------------------- 0 table access by index rowid categoryarticleassign 1 index range scan (object id 3080)********************************************************************************

 

 

至此,這個問題得到了完滿的解決.