linq性能调优小结-- 如何定位到出问题的代码段

（作者原创，转载请注明出处）

 

通常遇到性能问题，只要能定位到出问题的代码，或者sql。基本上问题就解决掉80%了，毕竟各种性能问题的解决方案都很成熟了，网上搜索下，遍地都是。

而对于新手来说，通常最重要的是，如何定位到出问题的代码段。

请看下面的伪代码例子（用C#语法）：

PerformanceIssueFunction()

{

　　List<int> idList = GetList();

　　foreach (var id in idList)

　　{

　　　　var box = GetBoxById(id);

　　　　DoSecondThing(box);

　　}

}

我们假设确定上面的函数PerformanceIssueFunction存在性能问题，那我们现在的目标就是确定哪一句，或者哪几句有性能问题。

办法通常有两种，

第一种，靠猜！（表用鸡蛋砸我。。。= =）  

---  这种办法只适用于对于程序内部逻辑非常之熟悉的人，或者问题函数相对简单，可以一眼看出问题来。复杂的情况下并不推荐这种办法。

好了，言归正传，我们来说比较传统的办法。

第二种，打印操作日志：

整体思路如下：

1. 在可疑的代码段前后，把开始执行该语句时间点和结束的时间点打印到日志中。（你也可以在程序中计算出该语句花费的时间，但是作者不推荐这种办法，原因在后面会详细说）

2. 分析日志，得出可疑代码花费的时间。

 

下面是详细说明这两部分的思路。

 

打印日志部分：

作者使用的打印日志的办法是用log4net，代码如下：

Log.Debug("<{1}Start>{0}</{1}Start>", DateTime.Now.Ticks, "codepart1");

Log.Debug("<{1}End>{0}</{1}End>", DateTime.Now.Ticks, "codepart1");

这里使用的是C#代码，DateTime.Now.Ticks表示当前时间节点，codepart1是你自定义的可疑代码段的名字，用于分析日志时方便识别。而start和end用于标识代码段的开始和结束。

注意：每一个可疑代码段的名字一定保持不一样，否则就会分析有误了。

 

那么上面的函数在加了日志部分代码后，将会变成这个样子：

PerformanceIssueFunction()

{

     Log.Debug("<{1}Start>{0}</{1}Start>", DateTime.Now.Ticks, "GetList");

　　List<int> idList = GetList();

     Log.Debug("<{1}End>{0}</{1}End>", DateTime.Now.Ticks, "GetList");

　　foreach (var id in idList)

　　{

           Log.Debug("<{1}Start>{0}</{1}Start>", DateTime.Now.Ticks, "GetBoxById");

　　　　var box = GetBoxById(id);

　　　　Log.Debug("<{1}End>{0}</{1}End>", DateTime.Now.Ticks, "GetBoxById");

　　　　Log.Debug("<{1}Start>{0}</{1}Start>", DateTime.Now.Ticks, "DoSecondThing");

　　　　DoSecondThing(box);

　　　　Log.Debug("<{1}End>{0}</{1}End>", DateTime.Now.Ticks, "DoSecondThing");

　　}

}

在程序中直接计算出该语句花费的时间也能定位到问题，但比起作者推荐的这种办法，直接计算时间有两个缺点：

1. 每一个可疑的地方，你都要新写代码，新命名变量自己做计算。而打印日志的办法则完全不需要思考，全部copy即可，我们不求最懒，只求更懒。。。

2. 计算时间的代码通常不合适放在正式产品中的，毕竟它什么业务都不干，解决完性能问题后，你还得删掉它。而打印日志的办法，代码完全可以保留在正式产品中。你可以利用log4net的配置功能，解决问题的时候，把debug日志设置为允许输出，而解决完问题后，把debug关闭输出即可，下次还可以再用。看，很绿色环保吧。

 

分析日志部分：

打印出的日志将会是这个样子：

日期部分blabla。。。。<codepart1Start>139948109284<codepart1Start>

日期部分blabla。。。。<codepart1End>139912341234<codepart1End>

日期部分blabla。。。。<codepart2Start>13994823109284<codepart2Start>

日期部分blabla。。。。<codepart2End>13991232341234<codepart2End>

。。。。

 

那么作者的办法就是正则提取出其中的时间点再分别用End tag中的时间点减去start tag的时间点即可得出该部分所消耗的时间。然后再把相同名字的tag消耗时间加起来，就可以得到循环里面函数的消耗时间。

下面的脚本用的python实现。

这里不得不强烈推荐.net程序员学习下python，这个语言写这种小脚本效率之高（据说ruby效率更高，作者还没实验过），至少远远超过.net。用python写脚本之后，我有这样的感慨，用C#写小工具简直就是浪费生命。。。

好了，闲话不说，贴上代码：

你所需要做的修改就是

1. 找到tag_array的定义，把这个数组中的值替换为你要分析日志里的tag即可，也就是上面Log.debug中用的最后一个参数。

2. 这段脚本对当前目录下的'debug.txt'进行分析。你也可以改成别的路径。

然后不需要输入参数，把下面的脚本保存为analyze.py文件，然后在cmd窗口直接用python调用即可。（当然，你要先安装python）

（如何安装python，请见：http://readthedocs.org/docs/learn-python-the-hard-way-zh_cn-translation/en/latest/ex0.html）

代码部分：

import re

import string

 

def get_tag_value(tag, file_name, tag_postfix):

    reg_expression = '(<%s%s>)(\d+)(</%s%s>)' %(tag, tag_postfix, tag, tag_postfix)

    #print reg_expression

    p = re.compile(reg_expression)

    txt = open(file_name).read()

    matchs = p.findall(txt)

    #print matchs

 

    sum = 0

    if matchs!=None:

        #print "%s%s> count is: %d" %(tag, tag_postfix, len(matchs))

        for img in matchs:

            #print img

            sum += string.atof(img[1])

 

    return sum

 

    return getsum(matchs)

 

 

tag_array = ['GetList', 'GetBoxById', 'DoSecondThing']  ＃＃ 这里只需要把tag_array替换为你要分析日志里的tag即可，也就是上面applicationlog.debug中用的最后一个参数。

input_file = 'debug.txt' ＃＃找到当前目录下的debug.txt，对其中的内容做分析

total_sec = 0

for tag in tag_array:

    start_value = get_tag_value(tag, input_file, 'Start')

    end_value = get_tag_value(tag, input_file, 'End')

 

    cost_time_tick =  (end_value - start_value)

    #print "%s cost time tick is %f" %(tag, cost_time_tick)

    cost_time_sec = cost_time_tick / 10000000

    print "%s cost time is %f" %(tag, cost_time_sec)

    total_sec += cost_time_sec

 

print total_sec