排错案例分享 朱燚:

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