排错案例分享

冷不防 2022-08-25 10:53 200阅读 0赞

前几天另一个组的同事遇到了一个问题,他们的服务器cpu总是很高,用性能监视器看来,情况更是奇怪,开始时cpu一直很低,接着忽然涨到25%,然后再也下不来了,隔一段时间cpu又涨25%,然后就一直保持50%以上,就这样一涨25%,最多涨四次就100%,占用CPU的是w3wp进程,到了100%的时候,就不得不把w3wp强行终止  
  
除了cpu外其他属性均正常  
  
在性能监视器里添加Asp.net 的Current Request(当前请求数),发现有一些请求始终没有结束,对比cpu的使用率,可以看到当有一个这样的请求,cpu为25%两个则为50%,三个75%....  
  
  
看到这个问题,我的第一个反应是请求为什么不过期,而是一直占用cpu,第二个,奇怪的地方,是cpu增长的方式和幅度很有趣,固定每次增长25%,并且增长的时间不定.  
  
开始我没有什么太好的想法,但是光cpu高,其他指标正常,让我觉得起一定有某项工作在努力进行,而且不涉及大量内存和io操作,最简单的模拟方法莫过于写一个什么都不做的死循环,于是我新建了一个web项目,在本机的的iis上建立一个站点指向他,为了真实一些,我还给这个站点单独设置了一个应用程序池,然后,我在一个空页面的onload里加上while(true)\{\}看看效果,下面是访问这个空页面的时候的cpu情况,我们可以看到,占用率超过了50%  
  
![cpu.GIF][]  
  
还有:对这个页面的请求一直不超时,无论我回收甚至停止应用程序池,w3wp都执着的占用我50%的cpu,而我是一个双核处理器,而有问题的那台是四核的.每次涨25%,呵呵,有点意思哈,是不是实际问题很像了呢?  
  
那么为什么请求不超时呢?本地的代码web.config中设置为debug="true",这时默认是不会超时的,但是发布后一般会改为debug="false",这时才有请求超时,推测另一组的开发人员出于某种原因,发布后没有进行修改.所以造成了一直存在的请求.赶忙叫请人看了看,果然webconfig中debug="true"  
  
但现在的问题是到底是什么请求导致了这些超长时间请求呢?难道真是一个死循环吗?  
  
要解决这个问题,我们首先要找到有问题的请求,开始的时候我们不知道怎么查看iis当前的具体请求,而iis只提供了当前请求数,但是起码我们有iis的日志吧,所以我想使用一个程序来监视cpu的值,一旦发生了25%的长期提升,我就记录下发生的时间,然后到log里面看看对应时间到底有些什么请求,下面就是我的程序,使用的是程序操控performace counter,大概逻辑我会在下面讲述

public  class  TestPerformanceTool  
\{  
 static  PerformanceCounter pc;  
 public  static  void  Test()  
\{  
TimeSpan span = new  TimeSpan( 0 , 2 , 0 ); // cpu升高持续多长时间需要记录:现为2分钟   
  int  interval = 1000 ; // 两次查看cpu使用率的间隔:现为1秒   
  float  limit = 20f; // cpu升高百分比限制:现为20%   
   
  
List < TimeValueRecord >  list  =  new  List < TimeValueRecord > ();  
pc  =  new  PerformanceCounter();  
 //  获取或设置此性能计数器的性能计数器类别的名称。   
  pc.CategoryName  =  " Processor " ;  
 //  获取或设置与此 PerformanceCounter 实例关联的性能计数器的名称。   
  pc.CounterName  =  " % Processor Time " ;  
pc.InstanceName  =  " \_Total " ;  
pc.ReadOnly  =  true ;  
 float  pre  =  0f;  
 float  cur  =  0f;  
 bool  firstTime  =  true ; // 排除第一次运行时的跃升干扰   
  DateTime currDate  =  DateTime.Now;  
DateTime preDate  =  DateTime.Now;  
 float  diff  =  0f;  
 while  ( true )  
\{  
cur  =  pc.NextValue();  
 if  ( ! firstTime)  
\{  
currDate  =  DateTime.Now;  
diff  =  cur  \-  pre;  
 if  (diff  >  limit)  
list.Add( new  TimeValueRecord(preDate,pre));  
 foreach  (TimeValueRecord entry  in  list)  
\{  
 if  (cur  \-  entry.Value  <  limit)  
entry.Value  =  int .MaxValue; // foreach中不能remove,这样就等于使得cur-entry.value为一个负数,肯定小于limit,   
  else  if  (currDate  \-  entry.Key  >  span)  
\{  
Console.WriteLine( " Jump Occurred at \{0\} " , entry.Key);  
entry.Value  =  int .MaxValue; // 以免多次输出   
  \}  
\}  
\}  
pre  =  cur;  
preDate  =  currDate;  
firstTime  =  false ;  
Thread.Sleep(interval);  
\}  
\}  
\}  
  
 internal  class  TimeValueRecord  
\{  
 public  TimeValueRecord(DateTime key, float  value)  
\{  
Key  =  key;  
Value  =  value;  
\}  
 public  DateTime Key;  
 public  float  Value;  
\}

大概逻辑是每隔interval秒查看一次cpu的使用率,如果当前值和上次值之间的差距<25%(程序里用的是20%,为的是灵敏度高一些),就放在一个数组里,注意由于有的时候服务器cpu会出现在一瞬间很高的情况,然后很快降下来的情况,因此,我们还需要知道这次提升是否持续了一段时间,程序里是2分钟,一旦持续超过两分钟,就把这次提升的时间输出,这里简单的输出在了控制台里  
  
写好之后在自己的机器上运行的不错,完全可以监视自己故意制造的cpu使用率持久提升,但是麻烦的是,放在服务器上就没效果了,大概是因为在服务器上,cpu并不是如我想象的瞬间提升,而是有一个过程,我的两次cpu监视的间隔设的是一秒,在这一秒内服务器的cpu没有提高到20%,所以程序就没有捕获,所以只好把间隔调大一些,不过自然输出时间的误差就要大了一些.  
  
不过这时我们的运维人员找到一个很好的工具,微软的 iis诊断工具,可以看到当前请求内容,在这里我提供了一个 [下载连接][Link 1],所以上面我的程序就没有什么用处了,不过可以作为参考,改改的话可以监视很多性能指标的变动时间:)  
  
很快,运维人员就找到了有问题的请求,是一个插入高亮代码的页面,里面代码特简单,实在看不出有死循环,实际这个页面前一天大家曾经怀疑过,但是就是因为里面代码一幕了然,就放过了,我们来看看这个页面的代码

1 using  System;  
  2 using  System.Data;  
  3 using  System.Configuration;  
  4 using  System.Collections;  
  5 using  System.Web;  
  6 using  System.Web.Security;  
  7 using  System.Web.UI;  
  8 using  System.Web.UI.WebControls;  
  9 using  System.Web.UI.WebControls.WebParts;  
 10 using  System.Web.UI.HtmlControls;  
 11   
 12 public  partial  class  InsertCode : System.Web.UI.Page  
 13 \{  
 14  protected  void  Page\_Load( object  sender, EventArgs e)  
 15  \{  
 16  if  (Request\[ " Language " \]  !=  null )  
 17  \{  
 18  HighLightService s  =  new  HighlightService();  
 19  bool  outlining  =  true ;  
 20  string  outText;  
 21  if  ( string .IsNullOrEmpty(Request\[ " outlining " \]))  
 22  outlining  =  false ;  
 23  if  (Request\[ " Code " \]  ==  null  ||  Request\[ " Language " \]  ==  null )  
 24 **outText**  **= s.Transform("public int c", "C\#"** **, outlining);**  
 25  else   
 26  **outText**  **= s.Transform(Request\["Code"\], Request\["Language"** **\], outlining);**  
 27  outText  =  outText.Replace( " / "" ,  " /// "" );  
 28  outText  =  outText.Replace( " /n " ,  " <br> " );  
 29  outText  =  outText.Replace( " /r " ,  " <br> " );  
 30  outText  =  outText.Replace( " <pre> " ,  "" );  
 31  outText  =  outText.Replace( " </pre> " ,  "" );  
 32 **outText**  **=**  **Globals.ReplaceSpace(outText);**  
 33  outText  =  @" <div style='BORDER-RIGHT: windowtext 0.5pt solid;PADDING-RIGHT: 5.4pt; BORDER-TOP: windowtext 0.5pt solid; PADDING-LEFT: 5.4pt; BACKGROUND: \#e6e6e6; PADDING-BOTTOM: 4px;PADDING-TOP: 4px; BORDER-LEFT: windowtext 0.5pt solid;WIDTH: 95%; BORDER-BOTTOM: windowtext 0.5pt solid;word-break:break-all'> "  \+  outText  \+  " </DIV> " ;  
 34  clientScript.Text  =  " var outText=/ ""  \+ outText +  " / " ; FCK.InsertHtml(outText);window.close(); " ;  
 35  \}  
 36  \}  
 37 \}

加上using才37行,本身逻辑不超过14行,不用管具体是干什么用的,只用分析一下这十几行代码,看似没有什么可能造成死循环的地方啊?  
再仔细看看,代码里有三个方法调用(见加粗的地方那个),前两个经检查是webservice,webservice的站点也不在那台服务器上,所以和cpu高没有关系,其他语句都很简单,不太可能有问题,而后面的一个方法调用很可能就是问题所在的地方了  
  
打开这个方法看看,里面是一个正则替换,也很简单,看来所有的问题就在这个正则上了,读不明白没关系,我也没读明白:P

public  static  string  ReplaceSpace( string  content)  
\{  
 string  findstr = " (?<fore>(?:(?:\[^< \])\*(?:<(?:!--(?:(?:\[^-\])\*(?:(?=-->)|-))\*--|(?:\[^>\])+)>)?)\*)\[ \](?<back>(?:(?:\[^< \])\*(?:<(?:!--(?:(?:\[^-\])\*(?:(?=-->)|-))\*--|(?:\[^>\])+)>)?)\*) " ;  
 string  replacestr = " $\{fore\}&nbsp;$\{back\} " ;  
 string  targetstr = System.Text.RegularExpressions.Regex.Replace(content,findstr,replacestr,System.Text.RegularExpressions.RegexOptions.IgnoreCase);  
 return  targetstr;  
\}

显然这个正则并不是所有的情况都有问题,不然后台监视到的cpu占用会厉害的多,所以我找了几段文本去测试,经过反复测试,发现匹配诸如<span>&dll;&dfasfd;&dsd;BB()</span>  
这样的代码,会造成死循环(当然也可能是执行时间巨长无比)而在此期间cpu会被占用,内存一切正常下图是我用自己的工具执行匹配时的截图  
  
![match.GIF][]  
  
具体为什么,到底是什么文字模式会导致问题,我还不知道,但是可以肯定的是,问题就在这里了,具体怎么解决,就交给那组的同事了  
  
  
**总结:**  
  
身为程序员,通过自己的努力能解决一个问题,心里都是很愉快的,不过高兴之余也应该有所总结,为了自己不被同样的问题再困扰,也为了下次能够更快的找到问题  
  
webconfig中的debug属性,发布时要注意修改,当然保持debug=true,也能让你查看到许多自己程序的问题,所以最好是最初发布时能够把他打开  
  
适应了调试环境,我们在又不能调试,又没法记录日志的时候,需要能静下心来看代码.许多问题通过仔细的阅读和分析代码都能找到.  
  
正则表达式,特别是相对复杂的表达式,一定不要忘记测试其有效性和性能,所以自己最好是手边常备一个习惯的正则工具,我用的是自己写的,下面这个blog上的正则工具比较全面,大家也可以用用看  
http://www.cnblogs.com/Heroman/archive/2005/01/13/91265.html  
  
多核服务器处理多线程时,我们可以看到线程和cpu数目之间的直接关系,但不等于说一个线程是由一个cpu全权处理的,具体调度问题我还不太清楚  
  
上面那个正则哪里有问题,我还不知道,大家如果能看出来一定要告诉我  
  
关于排错这篇文章讲的还不错  
http://news.csdn.net/n/20071228/112244.html

[cpu.GIF]: /images/20220824/749308b3669743478d8333ad3f13a1b4.png
[Link 1]: http://download.csdn.net/source/331257
[match.GIF]: /images/20220824/f97d49bc68994c488d11fd05060174c0.png