sqlplus 登入時快時慢問題診斷

531968912發表於2017-07-10
SQL

客戶反映前端系統反映很慢，自己透過sqlplus登入發現時而正常時而卡頓，登入之後有沒有明顯症狀，需要診斷原因。

因為客戶反映登入之後並沒有異常，所以先不懷疑是db端出現了效能問題，必須先從客戶端程式下手，對於診斷登入問
題，需要調查登入階段時間都花費在了那些呼叫上， 於是需要可以提供strace 輸出:
strace -f -ttt -o sqlplus.trc sqlplus / as sysdba 

收集資訊如下:
+ sqlplus.trc

11114 1468996741.620272 execve("/u01/app/oracle/product/11.2.0/bin/sqlplus", ["sqlplus", "system/spring"], [/* 29 vars */]) = 0
<skipping>...............
11114 1468996741.849734 read(11,  <unfinished ...>
11115 1468996741.849800 getrusage(RUSAGE_SELF, {ru_utime={0, 8998}, ru_stime={0, 28995}, ...}) = 0
<skipping>.....too much getrusage here 
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11111_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11112_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11113_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11114_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11115_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11116_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11117_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11118_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
<skipping>.....too much open here
11115 1468996743.559319 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11115_122.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = 8    <<<1.7s
<skipping>....
11114 1468996743.579234 read(0, "exit\n", 1024) = 5   
11114 1468996747.659642 write(10, "\0\r\0\0\6\0\0\0\0\0\3\t\10", 13 <unfinished ...>  <<<4s elapsed
11115 1468996747.659687 <... read resumed> "\0\r\0\0\6\0\0\0\0\0\3\t\10", 8208) = 13
11114 1468996747.659702 <... write resumed> ) = 13


首先分析第一個trace檔案，根據時間戳查詢花費時間最多的地方，的確能發現一處時間明顯變化地方，就是 read函式
居然花費了4s，非常可疑，經過自己測試發現原來read函式時間就是sqlplus顯示登入之後的提示符到最後客戶輸入exit
命令的時間差，若是是正常情況，剩下並沒有發現其他時間戳有明顯跳變情況，因為整個trace檔案非常大，所以只能一
點點從頭閱讀，忽然發現trace檔案中間有大量的/u01/app/oracle/admin/orcl/adump/orcl_ora_nnn_1.aud出現，一共有
上百個檔案，所有檔案讀完花費了1.7s，問題原因就發生在了這裡，這些檔案是審計檔案可以隨時備份刪除。於是讓客
戶理這些檔案之後再次登入，明顯好轉。至此問題解決，至於客戶反映時快時慢是因為客戶是RAC系統，而另外一個實
例目錄下並沒有這些檔案，所以有時候登入tns形式到第二個例項就沒有這個問題。

sqlplus 登入時快時慢問題診斷

By: Bin Mao

客戶反映前端系統反映很慢，自己透過sqlplus登入發現時而正常時而卡頓，登入之後有沒有明顯症狀，需要診斷原因。
因為客戶反映登入之後並沒有異常，所以先不懷疑是db端出現了效能問題，必須先從客戶端程式下手，對於診斷登入問
題，需要調查登入階段時間都花費在了那些呼叫上， 於是需要可以提供strace 輸出:
strace -f -ttt -o sqlplus.trc sqlplus / as sysdba 

收集資訊如下:
+ sqlplus.trc

11114 1468996741.620272 execve("/u01/app/oracle/product/11.2.0/bin/sqlplus", ["sqlplus", "system/spring"], [/* 29 vars */]) = 0
<skipping>...............
11114 1468996741.849734 read(11,  <unfinished ...>
11115 1468996741.849800 getrusage(RUSAGE_SELF, {ru_utime={0, 8998}, ru_stime={0, 28995}, ...}) = 0
<skipping>.....too much getrusage here 
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11111_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11112_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11113_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11114_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11115_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11116_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11117_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
11115 1468996741.871284 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11118_1.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = -1 EEXIST (File exists)
<skipping>.....too much open here
11115 1468996743.559319 open("/u01/app/oracle/admin/orcl/adump/orcl_ora_11115_122.aud", O_RDWR|O_CREAT|O_EXCL, 0660) = 8    <<<1.7s
<skipping>....
11114 1468996743.579234 read(0, "exit\n", 1024) = 5   
11114 1468996747.659642 write(10, "\0\r\0\0\6\0\0\0\0\0\3\t\10", 13 <unfinished ...>  <<<4s elapsed
11115 1468996747.659687 <... read resumed> "\0\r\0\0\6\0\0\0\0\0\3\t\10", 8208) = 13
11114 1468996747.659702 <... write resumed> ) = 13


首先分析第一個trace檔案，根據時間戳查詢花費時間最多的地方，的確能發現一處時間明顯變化地方，就是 read函式
居然花費了4s，非常可疑，經過自己測試發現原來read函式時間就是sqlplus顯示登入之後的提示符到最後客戶輸入exit
命令的時間差，若是是正常情況，剩下並沒有發現其他時間戳有明顯跳變情況，因為整個trace檔案非常大，所以只能一
點點從頭閱讀，忽然發現trace檔案中間有大量的/u01/app/oracle/admin/orcl/adump/orcl_ora_nnn_1.aud出現，一共有
上百個檔案，所有檔案讀完花費了1.7s，問題原因就發生在了這裡，這些檔案是審計檔案可以隨時備份刪除。於是讓客
戶理這些檔案之後再次登入，明顯好轉。至此問題解決，至於客戶反映時快時慢是因為客戶是RAC系統，而另外一個實
例目錄下並沒有這些檔案，所以有時候登入tns形式到第二個例項就沒有這個問題。

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

相關文章