[Debug實踐]windbg解決網站伺服器高CPU問題

高CPU是網站伺服器常見的一種故障，很多windbg教程中都拿高CPU做例子。3月份我在公司伺服器上也碰到一次，整個debug過程十分順利且常規，但最終找到的原因卻很有意思，與一個掛馬行為有關。

現像：網站伺服器的w3wp進程經常出現突發性的高CPU，如week15-16處所示。修正後的效果還是很明顯的。

分析過程：
（1）之前在伺服器上安裝了windbg，在cpu高點時運行adplus.vbs -hang -pn w3wp.exe -o d:\ops\以產生dump檔案，
如果沒有條件的朋友，可以使用系統內建的ntsd來產生，如 
ntsd  -pv -pn w3wp.exe -logo d:\out.txt -lines -c ".dump /ma d:\testlocal.dmp;q"
關於64位機上ntsd的使用注意點詳見調試運行於64位機上的32位w3wp進程

因為需要解決的是高CPU的問題，思路是分析某個線程在進程啟動後佔用的cpu時間。所以需要取多個dump，看"高CPU時間段"內"佔用cpu時間增長最多"的是哪個線程，最終得到的兩個檔案如下：

（2）  windbg開啟1227.dmp，運行!runaway命令可以看到各線程的CPU佔用總時間

0:000> !runaway

 User Mode Time

  Thread       Time

  18:fdc       0 days 1:20:28.390

  19:1370      0 days 1:16:36.359

  21:538       0 days 1:08:28.765

  22:698       0 days 1:07:55.968

  20:1180      0 days 0:58:22.046

 138:1284      0 days 0:56:53.890

 136:f9c       0 days 0:49:38.609

   9:1094      0 days 0:44:26.312

 147:db8       0 days 0:25:16.234

 149:6f4       0 days 0:22:00.687

 148:c8c       0 days 0:20:29.156

  13:1108      0 days 0:01:31.562

  12:d24       0 days 0:01:27.593

  14:5e8       0 days 0:01:26.203

  11:ce0       0 days 0:01:06.703

（3）  看一下另外一個dmp檔案，windbg開啟1236.dmp

0:000> !runaway

 User Mode Time

  Thread       Time

  18:fdc       0 days 1:21:09.125

  19:1370      0 days 1:20:20.468

  21:538       0 days 1:08:43.140

  22:698       0 days 1:08:28.812

  20:1180      0 days 1:03:01.078

 138:1284      0 days 0:57:49.281

 136:f9c       0 days 0:55:01.250

   9:1094      0 days 0:44:50.781

 146:db8       0 days 0:27:10.062

 147:c8c       0 days 0:25:17.828

 148:6f4       0 days 0:25:03.656

  13:1108      0 days 0:01:32.328

（4）將(2),(3)中的結果減一下，可以得出136線程在這段時間內增長得最快，也就是說cpu這段時間內都在完成136線程的事情，那它肯定就是高cpu的原因了
為了查看136線程對應的託管堆棧，需要載入sos擴充，輸入.load sos.dll，然後運行~136 s 切換到136線程，再運行!clrstack查看堆棧

OS Thread Id: 0xf9c (136)

ESP       EIP    

0c23e810 7a4c7af0 System.Text.RegularExpressions.RegexInterpreter.SetOperator(Int32)

0c23e814 7a4c7c8f System.Text.RegularExpressions.RegexInterpreter.Backtrack()

0c23e820 7a4c7adb System.Text.RegularExpressions.RegexInterpreter.Go()

0c23e91c 7a4b1615 System.Text.RegularExpressions.RegexRunner.Scan(System.Text.RegularExpressions.Regex, System.String, Int32, Int32, Int32, Int32, Boolean)

0c23e948 7a4b14f3 System.Text.RegularExpressions.Regex.Run(Boolean, Int32, System.String, Int32, Int32, Int32)

0c23e978 7a4d17d7 System.Text.RegularExpressions.Regex.IsMatch(System.String)

0c23e984 0363a858 com.****.***.****.***(System.String, System.String, System.String, System.String)
****這裡省略一些內容，因為出現公司名了：）*****

是一個Regex處理，為什麼要這麼長的時間呢？直覺就是處理的字串過長了，為了驗證，來看看Regex在處理的串

（5）運行  0:136> !clrstack -p
比第四步中多看到的就是參數的記憶體位址，為了省略篇輻不再列出，看到的參數地址是0x1c75df0c，用!do可以查看託管對象的內容
 

0:136> !do 0x1c75df0c

Name: System.String

MethodTable: 790fd8c4

EEClass: 790fd824

Size: 12900(0x3264) bytes

 (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

String: /pages.aspx?***id=***&***_id=4210281%3B%44%65%43%4C%61%52%45%20%40%53%20%4E%76%41%72%43%48%61%52%28%34%30%30%30%29%3B%53%65%54%20%40%53%3D%43%61%53%74%28%30%78%34%34%30%30%36%35%30%30%36%33%30%30%36%43%30%30%36%31%30%30%37%32%30%30%36%35%30%30%32%30%30%30%34%30%30%30%35%34%30%30%32%30%30%30%35%36%30%30%36%31%30%30%37%32%30%30%36%33%30%30%36%38%30%30%36%31%30%30%37%32%30%30%32%38%30%30%33%32%30%30%33%35%30%30%33%35%30%30%32%39%30%30%32%43%30%30%34%30%30%30%34%33%30%30%32%30%30%30%35%36%30%30%36%31%30%30%37%32%30%30%36%33%30%30%36%38%30%30%36%31%30%30%37%32%30%30%32%38%30%30%33%32%30%30%。。。。。。後面省略一堆

（6）確認原因是在處理一個超長的字串，與相關的開發人員確認，是為了分析使用者行為對URL進行處理，但沒有考慮到URL超長的情況。
而再回頭來看這個超長的參數，是一個BASE64的編碼，利用google的參數編碼也是base64的，讓google義務翻譯一下，google上搜尋ff,出來的url是
http://www.google.cn/search?hl=zh-CN&newwindow=1&q=ff&meta=&aq=f&oq=
將ff改成上面的字串，google搜尋結果頁如下：

經過翻譯內容為DeCLaRE @S NvArCHaR(4000);SeT @S=CaSt(0x4400650063006C0061007200650020004000540。。。。

很經典的一個掛馬行為，同時從google的搜尋結果看到，很多網站都被掛了馬：）我們的網站雖然沒有被掛上，但在處理這些參數時引發了伺服器高CPU的問題，也算是被攻擊了，看來以後還是得多考慮一些邊界情況呀