[原创]DebugTools系列(3):AQTime实践

导读

通过前两篇文章，大家应该对AQTime已经有了一定的理论认识了吧！[上一篇]文章最后埋了几颗地雷在Demo里面，希望感兴趣的同学自己挖挖看！因为对地雷的反馈不多，所以不知道有多少同学真正亲自动手实验了，如果你动手做了希望能告诉我，我会感到非常欣慰的！OK，不管怎么样，这次我们就是要演示挖地雷的过程了，有了AQTime这个超级探雷器，其实这是个非常简单愉快的过程，希望您能乐在其中！
记得留下宝贵意见哦！！！ 源代码下载： 

首先，我们打开AQTime，新建一个项目，然后先将Bin目录中的Justin.UILibrary.dll加载到Modules列表里，然后我们选择Profile Entire .NET Code，将项目类型选择为ASP.NET,然后在Run Parameters里设置Start Page是http://localhost/Justin/Default.aspx(根据自己环境IIS虚拟目录的配置而定)，然后我们就可以开始挖雷了！



如上图所示，这里有两个问题(基于[上一篇]文章介绍的配置分析范围和粒度)，第一个，为什么在开始没有设置成状态？第二个，为什么我们要使用Profile Entire .NET Code 这个默认的Area？第一个问题的答案是因为我们现在不知道地雷在那里，所以我们要跟踪分析程序的整个生命周期；第二个问题的答案是因为我们不明确加载的Module是否足够，和具体要加载那些Module，所以我们先使用默认的Area设置，分析程序加载的所有Module；其实也可以认为这两个问题的答案都是因为我们一开始没有明确的目标，所以我们只能靠“广撒网多捞鱼”的笨方法了。



如上图所示，当第一次Run的时候，会先后弹出上面三个窗口，你可以完全不去管它们，全部回车过去就行了，当然也可以分别选择"Don't..."复选框，让它们下次不会再弹出来。



OK!程序执行起来以后，我们依次分别执行了一遍“模拟提交”、“模拟浏览”、“模拟修改”，发现都比较慢，看来性能问题是比较严重。全部执行过后，我们通过来收集程序这段生命周期里的性能数据，可以说这是最完整的整个生命周期的所有操作的分析数据了。

【大图】

如上图所示，这次我们收获颇丰啊！这就是我们用AQTime收集到的Demo的完整生命周期(不包括关闭页面部分)的性能数据结果了，其中同时包含了所有底层框架(.NET)的方法，所有这些数据我已经打包在下载Demo的压缩包里了，这次收集的结果对应压缩包里的AQTimeTestJustinDemo_01.aqr文件，大家可以通过AQTime打开查看。下面就基于这个结果，开始挖雷了！我们先介绍一下挖雷的最最基本的技巧，那就是清楚地理解Report页签里的Grid中最基本的下面三列表示的意思：



上图表述的已经非常清楚了，这三列是我们日常使用AQTime分析程序性能问题时，最需要关注的三列(还有很多其他列，没有这三列实用，不过也不是一点用没有！)，首先，如果一个方法的执行时间过长，那么[Time]列的值就会很大，这也是最傻瓜的地雷了，因为已经清楚地告诉你，这个方法执行时间过长，它就是你要找的瓶颈，剩下的就是具体分析这个方法为什么时间过长，能不能优化一下，不能的话请高高手再来看看；其次，如果一个方法中调用了很多子方法，而且它的[Time with Children]列的值很大，那么要通过[Call Tree]或[Call Graph]页签来逐层查找瓶颈到底发生在那个子方法上，一般使用[Call Tree]可以很容易定位到耗时最多的子方法上，AQtime会自动将耗时最多的节点展开加粗显示，可以说是非常清晰明了的；最后，如果一个方法是[HitCount]列的值非常大，那么也要提高警惕了，有可能存在问题，如果是底层基类的方法HitCount次数比较高还比较容易接受，如果是一个自定义比较靠前端的方法，那么就要检查一下程序的逻辑，是不是跟预想的一样，有没有多执行了几次循环，这些都是完全有可能的事情。



基于前面介绍的基本排雷技巧，如上图，这是按[Time with Children]倒排后的结果，从上到下我们可以发现，_Default::Page_Load 以前的结果都是底层框架自身的，这部分不在我们排雷的范围内，因为我们开始收集性能数据时候使用了“广撒网多捞鱼”的笨方法，所以在分析结果的时候就需要靠自己来分离过滤掉底层框架的方法才行了。那么我们这里重点分析一下为什么_Default::Page_Load 这个方法耗时最长，我们通过[Call Tree]展开其子方法，看看瓶颈到底在哪里：



如上图所示，通过[Call Tree]，我们已经清楚的看到，耗时最多的是FormLoadUtils::LoadUI和_Default::InitData两个方法，而且这两个方法是[Time]本身就很大，所以它们都是傻瓜型地雷(我这次埋的都是傻瓜型的)，OK!既然已经准确定位到了地雷，下面就是该看看地雷里面有什么了，是否能动个小手术把这个地雷拆除了呢？



通过Editor页签，我们可以直接查看程序的源代码，而且Editor页签的内容还是跟Grid动态同步的，酷！简直太方便了！如上图所示，我们可以清楚地看到，在LoadUI方法里面，最后有一句：“System.Threading.Thread.Sleep(3000);”，是的，就是它，它是地雷2，我们找到它了！哈哈！



同理，如上图所示，我们很容易找到了地雷3，破坏力都是3秒，呵呵！
哦可！地雷2和地雷3我们都已经找到了，现在我可以透露一下，其实我就埋了3颗地雷，所以我们就差地雷1还没有找到了！按照上面的方法，仔细分析Grid列表，配合[Call Tree]，应该很快就能发现地雷1的，这个我们就不介绍了。我想说的是，其实聪明的同学早应该会想到，地雷1肯定也同样是傻瓜型的，而对于傻瓜型地雷，最好的方法是一开始就将Grid按[Time]列倒排，那样就可以直接暴露傻瓜型地雷的位置了！



如上图是按[Time]倒排后的结果，果然不出所料，UI::InitPage很明显地暴露了出来，没错，它就是地雷1，通过Editor可以看到，它同样是一个破坏力为3秒的傻瓜雷！呵呵！
那么到此为止，我们的地雷就都挖完了，恩，起码我有意埋下的都挖完了，无意埋下的就不知道还有没有了！那么肯定有人聪明地同学要问了，为什么我们不一开始就使用[Time]倒排呢？这是个好问题，在本文中，作者为了给大家演示Grid和[Call Tree]配合的神奇力量，所以一开始使用了[Time with Children]倒排的方式，其实在实际优化程序性能的过程中，用的比较多的也是这种方法，因为一般很少有那么多傻瓜型地雷可挖的。但是，我这里想强调的是，任何时候，建议大家都能按照“先[Time]再[Time with Children]最后[HitCount]”的方式来分析定位问题，这样是最合理，最高效的组合了，比如在这个Demo里用这个方法，只分析一遍[Time]倒排就搞定了！

最后，再补充一点，关于我们上面用到的“广撒网多捞鱼”的笨方法，这个方法在这个Demo里很好用，因为毕竟我们的Demo比较小，所以执行起来速度也比较快，收集到的结果数据也不会多得让人恐怖，但是一般在分析大型项目的时候，我们一般最好是有针对性地分析局部某段生命周期里的具体功能点，这个时候就需要我们明确加载那些Module,然后把扫雷的范围缩小，以帮助更快更准确地定位瓶颈的位置，具体可以进一步参考[上一篇]所述。那么以这个Demo来说，就像[第一篇]里描述的一样，如果想收集所有我们自定义程序的性能数据，除了需要加载Justin.UILibrary.dll以外，还要加载由ISAPI动态生成的aspx文件对应的类的DLL，具体请参考第一篇文章所述，那么这里我们最后重新配置一下AQTime的Modules，重新收集一遍数据。



如上图所示，这次我们加载了必要的Module，然后再Area里设置成“Full Check”选项，只跟踪分析Modules列表的Module。

【大图】

如上图所示，这次收集到的结果比上次清晰了很多(对应压缩包里的AQTimeTestJustinDemo_02.aqr文件)，而且没有包含任何底层框架的方法，所有收集的数据都是Modules列表里的Module的范围内的，这样我们分析定位问题的时间，就不需要像上面那样需要靠自己来分离过滤掉底层框架的方法了，是不是清爽了很多啊！配置分析范围的优点在这个Demo里并不明显，因为全生命周期分析下来，这个Demo也没有多少数据，但是在那种大型的项目里，挂上AQTime以后，点一下保存要等半小时的应用中，一开始就很好的控制分析的范围还是非常关键的，否则会收集到很多“垃圾”不说，最恐怖的是有可能等了半天什么也没收集到，Why？！：kao！死机了！

总结，这篇文章非常详细的介绍了使用AQTime在一般情况下的排雷过程，结合前两篇文章，相信大家现在应该可以使用AQTime熟练地解决一些性能分析的问题了！如果有什么问题，尽管在此留言，我会尽力解答。这个系列的文章关于AQTime的部分，我可能还会再写一篇，内容是一些AQTime的Tips，都是实际使用过程中的经验总结。

-欢迎加入博客园.Debug探索团队 Copyright © Justin