[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)
****这里省略一些内容，因为出现公司名了：）*****

是一个正则表达式处理，为什么要这么长的时间呢？直觉就是处理的字串过长了，为了验证，来看看正则表达式在处理的串

（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的问题，也算是被攻击了，看来以后还是得多考虑一些边界情况呀