排错案例分享

前几天另一个组的同事遇到了一个问题,他们的服务器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%



还有:对这个页面的请求一直不超时,无论我回收甚至停止应用程序池,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诊断工具,可以看到当前请求内容,在这里我提供了一个 下载连接,所以上面我的程序就没有什么用处了,不过可以作为参考,改改的话可以监视很多性能指标的变动时间:)

很快,运维人员就找到了有问题的请求,是一个插入高亮代码的页面,里面代码特简单,实在看不出有死循环,实际这个页面前一天大家曾经怀疑过,但是就是因为里面代码一幕了然,就放过了,我们来看看这个页面的代码

 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会被占用,内存一切正常下图是我用自己的工具执行匹配时的截图



具体为什么,到底是什么文字模式会导致问题,我还不知道,但是可以肯定的是,问题就在这里了,具体怎么解决,就交给那组的同事了


总结:

身为程序员,通过自己的努力能解决一个问题,心里都是很愉快的,不过高兴之余也应该有所总结,为了自己不被同样的问题再困扰,也为了下次能够更快的找到问题

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