一個os thread startup、log file sync等待的故障回顧

darren__chan發表於2018-10-31
thread

     這是一個原來遇到過，困擾過了我們很多人很久的故障，問題遲遲無法解決的原因是因為概念的模糊。os thread startup 是oracle 等待事件中Concurrency的一個等待，與之相關的解釋實際非常少。從種種故障現象及字面意義來理解，在進行並行分配是向os 申請程式啟動，而在正常的系統中，該動作是非常快的，在我們高壓力的資料庫環境下，os存在響應問題，激發了該等待事件的等待。最近因整理以前知識，由此記錄一下。

以下摘錄於網路的解釋： 

Know more about “os thread startup”
 
‘os thread startup’ takes significant amount of time in ‘create index parallel’.
All slaves are allocated one by one in serial.
SQL tracing on foreground, there is one ‘os thread startup’ wait per slave, each wait takes 100ms. –> May
need investigation
When there are 512 slaves, ‘os thread startup’ wait take 50 seconds before the slaves start to do any job.
Resolution is to set *.parallel_min_servers=512 to pre-allocated 512 slaves per instance duirng instance
startup, or to run PCIX twice and ignore the first run

【故障現象】

1.資料庫出現os thread startup等待，並伴隨著大量DFS lock handle,log file sync，latch free等等待堆積。

2.首先出現異常等待節點資料庫阻塞達到一定程度，系統資源大量消耗，主機hang住。

3.另外一節點資料庫受前一節點資料庫影響出現大量gc 等待事件，但異常等待積累到一定程度便出現DFS lock handle等等待，系統資源大量消耗，主機hang住。


【分析處理思路】

1. 資料庫等待情況：

從 dba_hist_active_sess_history 分析，資料庫出現os thread startup，之後開始引起大量的log file sync，latch free等待和DFS lock handle等阻塞。並且阻塞的源頭是 os thread startup.

節選：

節點1 根據 時間點 ， 按等待事件進行彙總：

28-JUL-16 04.22.16.187 PM      PX Deq: Slave Session Stats                  1

28-JUL-16 04.22.16.187 PM      control file sequential read                 1

28-JUL-16 04.22.16.187 PM                                  1 <<<---

28-JUL-16 04.22.16.187 PM      gc current grant 2-way                       2

28-JUL-16 04.22.16.187 PM      ASM file metadata operation                  2

......

28-JUL-16 04.22.16.187 PM      gc buffer busy release                      11

28-JUL-16 04.22.16.187 PM      db file sequential read                     54

28-JUL-16 04.22.16.187 PM                                                 107

28-JUL-16 04.22.16.187 PM      log file sync                              114  <<<----

28-JUL-16 04.22.16.187 PM      latch free                                 138  <<<----

 

28-JUL-16 04.22.27.538 PM      gc cr grant 2-way                            1

 

 

2.LGWR trace 寫入出現告警，實際寫入的資料量非常小，卻消耗了大量的時間。

### LGWR trace日誌 ###

LGWR寫入量及其耗用的時間，直觀表明I / O出現寫入緩慢的情況                                                     

*** 2016-06-21 17:11:22.234                         

Warning: log write elapsed time 516ms, size 16727KB

                                                    

*** 2016-06-21 17:11:44.492                         

Warning: log write elapsed time 21902ms, size 16KB  

                                                    

*** 2016-06-21 17:12:08.449                         

Warning: log write elapsed time 23529ms, size 381KB

 

 

3.CPU使用情況

（ 1）故障前主機 CPU 資源耗盡並存在多 個 CPU分割槽負荷100%的 情況 ，另 外存在 多 個 CPU分割槽 高 負荷 並且是系統 SYS佔用

（ 2）ORACLE SR 分析 並結合其接觸過的案例， AIX下 可能存在 CPU摺疊 的情況， 單個 CPU滿負荷使用會造成無法排程，而造成OS hang或非常緩慢的情況 後 IBM已解釋並說明目前系統的CPU不會出現CPU摺疊的情況，相關係統引數已設定正確，

vmstat：

zzz ***Thu Jul 28 09:37:45 BEIST 2016<<---CPU資源IDLE 30%左右

 

System configuration: lcpu=256 mem=745216MB

 

kthr    memory              page              faults        cpu    

----- ----------- ------------------------ ------------ -----------

 r  b   avm   fre  re  pi  po  fr   sr  cy  in   sy  cs us sy id wa

100  0 134703580 35782109   0   0   0   0    0   0 25724 255043 108481 61 12 22  5

86  0 134705919 35779762   0   0   0   0    0   0 21259 215539 88214 57  9 28  6

77  0 134701214 35784474   0   0   0   0    0   0 18884 194253 76418 54  9 30  7

zzz ***Thu Jul 28 09:38:41 BEIST 2016  <<<---CPU資源耗盡

System configuration: lcpu=256 mem=745216MB

 

kthr    memory              page              faults        cpu    

----- ----------- ------------------------ ------------ -----------

 r  b   avm   fre  re  pi  po  fr   sr  cy  in   sy  cs us sy id wa

272  1 134995188 35752075   0   0   0   0    0   0 4881 231230 79391 81 13  3  3

253  0 134995238 35752029   0   0   0   0    0   0 3699 179424 63599 79 13  4  3

203  1 134997247 35750015   0   0   0   0    0   0 4928 258230 62545 75 14  7  5

 

mp stat：

zzz ***Thu Jul 28 09:36:59 BEIST 2016

 

System configuration: lcpu=256 mode=Capped

 

cpu  min  maj  mpc  int   cs  ics   rq  mig lpa sysc us sy wa id   pc

....

 84  581    0    0  499 1298  239    1  386 100 4098 74 15  2  9 0.30

  85    0    0    0  236   21   21    1    0 100    0 99  1  0  0 0.55 <<<---cpu 100%

 

4.磁碟IO情況

   故障期間 redo file所 在磁碟組 DGSYSDG 對應 的所有磁碟 都 存在一個共同的現象， 磁碟 的 MAXSERV的值 開始出現 異 常 上漲， maxserv 從 20 以 下上漲至 100~400 左右， maxserv 異常增長與 log file sync   異常增長的時間點非常吻合，並且峰值的時間點一致。

 

5.   磁碟 maxserv 與資料庫 log file sync對比資料

   發現故障前log file sync高且redo所在磁碟的maxserv高的異常表現，後與IBM同事透過部署指令碼實時對新劃的一塊磁碟進行資料持續寫入並抓取出磁碟的maxserv資料，後對比新劃磁碟的maxserv峰值與redo所有磁碟的maxserv峰值出現時間，得出兩者峰值出現時間點一致

 

6. 其他

（ 1） 透過部署 truss、pdump指令碼對故障前夕出現異常等待事件os thread startup程式的捕獲跟蹤，並同時觸發執行trace指令碼

（ 2） 透過 pau資料去了解磁碟讀寫響應時間，可以瞭解磁碟方面讀寫是否存在效能問題


【原因&解決辦法】 確認 maxserv是導致故障的直接原因

   1.因為受 maxserv 高的影響，每次故障都導致大量的 log file sync 的等待，從而導致應用大量的積壓。

   2.僅僅是 maxserv高不一定會引起故障，每次故障前還伴隨著資料庫二階段應用量增大；

   因此， 引發故障需要具備兩個條件：1.磁碟maxserv高  2.二階段應用量出現高峰 ， 故障基本出現在業務高峰期間。

最後的解決方法是透過更換了效能更好的e880主機後再無出現此故障。




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

相關文章