现在的位置: 首页 > 综合 > 正文

使用Windbg和SoS扩展调试分析.NET程序

2013年12月08日 ⁄ 综合 ⁄ 共 13120字 ⁄ 字号 评论关闭

此文及后面的系列,都是从tess老大那里翻译过来的。一直和GTEC的老牛们作CASE(此句有误,一直提CASE,等老牛们提供答案),算是粘到了一点仙气。偶一直比较懒,所以以前精心抄袭的文章,今天再次精心作序于此,希望对各位挣扎于现实与理想的各位,共享,共勉。tess老大的文章国内似乎有人翻译过,但偶个人观点,不看好,因为好东西都没了哦。 

不是我不舍得,意思是,我的post里面基本上没有link,但是从google上都能搞到,如tess老大的系列debug文章。写程序的人,用好google应该是第一要素啊,哇哈哈哈!(百度除外,偶鄙视的公司)

每个post的题目都挺吓人,但是最终发现问题以及解决掉的方法,都异常简单。简单,产生丑陋。

问题描述:

程序慢的要死,CPU占用始终持续在70%-80%之间

解决步骤:

性能监视器。对于高CPU占用,一般的是这三个原因:

· 高的离谱的循环

· 太多的加载(比如,许多小的对象被频繁的处理)

· GC作了太多的事情

第一种情况,当你在恰当的时机抓到一个dump,就非常容易解决,一般而言,都是因为业务处理逻辑造成的。第二种情况,一般需要从硬件上考虑,scale up或者scale out,都行。

是否是GC的问题,我们需要看性能监视器里面的.NET CLR Memory计数器。这里面,最重要的是.net CLR Memory / % Time in GC. 这个值的阀值,可能是5%或者30%或者20%。实际上,没有一个准确的阀值存在的。当然,这个数字理论上应该接近于0%才对。

在GC里面,导致高CPU占用的原因,通常是因为过高的分配速率(对应到性能监视器里面的.net CLR Memory / allocated bytes/sec计数器。但实际上,如果所有的GC操作都在第0代上,则不会导致这个问题。真正的元凶,是大量的2代操作。如N多的对象在被移动到2代或者从2代中被释放。另一个原因就是我们熟知的大对象操作(LOH)

再强调一次,没有什么准确的指标,就告诉我们,超过了它就是出问题了,这是不可能的。包括微软给我们的大多数Practics Training,只有“尽量”、“尽可能”、“如果”等,而不是“一定”、“必须”。

如同我在那篇“浅谈GC中”讲到的一样,如果你搞了GC.Collect(2)或者GC.GetTotalMemory(true),那么也会导致大量的2代回收。

对于这个问题,我从性能监视器中抓到了这些数据:

% Time in GC ~40 % average
allocated bytes / sec 400 MB average
# Induced GC 0
# Gen 0 Collections 28.379
# Gen 1 Collections 28.378
# Gen 2 Collections 28.378

看第二行,真是让人晕倒!每秒分配400M字节!但实际上,我的代码中没有分配任何这么大的东西,有点太离谱了吧?!如果看最后面三行,也比较搞笑,0、1、2代的分配几乎完全相同。这实际上说明有LOH在压缩,或者有大量的对象冲进了第2代,然后又被立刻释放掉。

开始debug吧!

GC问题很难debug,因为:

1. 如果在GC中间过程中用adplus -hang模式抓了一个dump,基本上从dump里面看不到任何高CPU占用的原因。
2. 即时你通过性能监视器找到了GC的问题,也抓到了dump,但是很难分析。

实际上,通用的做法是每隔一小段时间,你就抓一次dump。如果看起来都差不多,那么有可能就能分析出哪里的问题了。

步骤1 - 我们在GC里面不?

如果我们的OS是server,那么每个CPU有一个GC线程(如果超线程的话,就是2个)。如果是非server的,那么只有一个GC线程。我们正在看到的这个dump,是在一个双核的、带有.NET2.0的机器上产生的。

如果我们不在GC过程中,那么我们会有两个线程(每个CPU一个):

18 Id: 134c.918 Suspend: 1 Teb: 7ffa8000 Unfrozen
ChildEBP RetAddr Args to Child
01e1fe68 7c822124 77e6baa8 00000398 00000000 ntdll!KiFastSystemCallRet
01e1fe6c 77e6baa8 00000398 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
01e1fedc 79e77fd1 00000398 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
01e1ff20 79e77f9a 00000398 ffffffff 00000000 mscorwks!PEImage::LoadImage+0x199
01e1ff70 79e77f50 ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
01e1ff80 79f3549b ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17
01e1ffa8 79f6ece3 00000000 b28c067c 01e1ffec mscorwks!SVR::gc_heap::gc_thread_function+0x2e
01e1ffb8 77e66063 000e7660 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x9b
01e1ffec 00000000 79f6ec79 000e7660 00000000 kernel32!BaseThreadStart+0x34

上面的代码表明,GC正在等着干活……在我抓到的dump中,GC看起来这个样子:

16 Id: f28.1150 Suspend: 1 Teb: fff82000 Unfrozen
ChildEBP RetAddr Args to Child
0248fd28 7d4d8c46 000002dc 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15
0248fd98 79e77fd1 000002dc ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
0248fddc 79e77f9a 000002dc ffffffff 00000000 mscorwks!PEImage::LoadImage+0x199
0248fe2c 79e77f50 ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
0248fe3c 79f35e1a ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17
0248fe54 7a0d5a3b 001afbf0 0000000d 00000002 mscorwks!SVR::t_join::join+0x61
0248ff54 79f391bf 00000002 001afbf0 00000000 mscorwks!SVR::gc_heap::plan_phase+0xd78
0248ff70 79f39954 00000002 ffffffff 001afbf0 mscorwks!SVR::gc_heap::gc1+0x57
0248ff88 79f35422 00000000 00000000 001afbf0 mscorwks!SVR::gc_heap::garbage_collect+0x37c
0248ffa8 79f6ece3 00000000 914b1904 0248ffec mscorwks!SVR::gc_heap::gc_thread_function+0x68
0248ffb8 7d4e0729 001afbf0 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x9b
0248ffec 00000000 79f6ec79 001afbf0 00000000 kernel32!BaseThreadStart+0x34

看上面的粗体,哦,正在Collect。就是说,我们闯到了GC的肚子里面。

步骤2 - GC为什么开始工作了?

先看一下,CPU都被谁用掉了?

0:029> !runaway

User Mode Time

Thread Time

14:11b8 0 days 0:00:55.687

16:1150 0 days 0:00:45.500

17:7a8 0 days 0:00:43.875

21:1244 0 days 0:00:23.140

0:ea0 0 days 0:00:00.046

29:fc8 0 days 0:00:00.000

28:11f0 0 days 0:00:00.000

0:021> .time

Debug session time: Tue Jun 20 09:46:04.000 2006 (GMT+2)

System Uptime: 4 days 6:36:51.031

Process Uptime: 0 days 0:16:53.000

Kernel time: 0 days 0:00:45.000

User time: 0 days 0:02:48.000

上面来看,大约有17分钟被程序用掉了。我们看一下14号在作什么?

14 Id: f28.11b8 Suspend: 1 Teb: fff88000 Unfrozen

ChildEBP RetAddr Args to Child

020afc8c 7d4d8c46 00000224 00000000 020afcd0 ntdll!

ZwWaitForSingleObject+0x15

020afcfc 79e77fd1 00000224 00009c40 00000000 kernel32!

WaitForSingleObjectEx+0xac

020afd40 79e77f9a 00000224 00009c40 00000000 mscorwks!

PEImage::LoadImage+0x199

020afd90 79e77f50 00009c40 00000000 00000000 mscorwks!

CLREvent::WaitEx+0x117

020afda0 79f5b69c 00009c40 00000000 00000000 mscorwks!

CLREvent::Wait+0x17

020afe20 7a1121c3 001862f8 00009c40 00000000 mscorwks!

ThreadpoolMgr::SafeWait+0x73

020afe94 79f71123 00000000 00000000 00000000 mscorwks!

ThreadpoolMgr::WorkerThreadStart+0xf1

020affb8 7d4e0729 0019cab8 00000000 00000000 mscorwks!

ThreadpoolMgr::intermediateThreadProc+0x49

020affec 00000000 79f710dd 0019cab8 00000000 kernel32!

BaseThreadStart+0x34

哦,很清闲,什么都没干。但是,那17分钟中,有56秒在用着CPU,什么意思呢???我们继续看一下21号线程的托管堆。

0:021> !clrstack
OS Thread Id: 0x1244 (21)
ESP EIP
029ef1e8 7d61c824 [HelperMethodFrame: 029ef1e8]
029ef254 02920df3 LargeObjectHeap.GetLotsOfDatesXML(Int32)
029ef2a4 02920b20 LargeObjectHeap.Button1_Click(System.Object, System.EventArgs)
029ef2b4 6881bdc6 System.Web.UI.WebControls.Button.OnClick(System.EventArgs)
029ef2c8 6881bfbc System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String)
029ef2dc 6881bf38 System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String)
029ef2e0 687d91e0 System.Web.UI.Page.RaisePostBackEvent(System.Web.UI.IPostBackEventHandler, System.String)
029ef2e8 687d912a System.Web.UI.Page.RaisePostBackEvent(System.Collections.Specialized.NameValueCollection)
029ef2f8 687dcbbf System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
029ef4b0 687db521 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
029ef4e0 687db487 System.Web.UI.Page.ProcessRequest()
029ef518 687db3a7 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
029ef520 687db33a System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
029ef534 02920795 ASP.largeobjectheap_aspx.ProcessRequest(System.Web.HttpContext)
029ef538 686888df System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
029ef56c 6865a071 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
029ef5ac 6865a39b System.Web.HttpApplication.ResumeSteps(System.Exception)
029ef5f4 6865912d System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
029ef610 6865e0bd System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
029ef644 6865dd72 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
029ef650 6865c447 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
029ef800 79f1ef33 [ContextTransitionFrame: 029ef800]
029ef850 79f1ef33 [GCFrame: 029ef850]
029ef9a8 79f1ef33 [ComMethodFrame: 029ef9a8]

看上面的call stack,我们看到了LargeObjectHeap.GetLotsOfDatesXML(),这个咚咚触发了LOH的回收,然后按次序触发了2代、1代、0代。

但是只有一个大对象,并不会导致高CPU的占用啊!那我们看一下实际的代码吧!

String GetLotsOfDatesXML(int i)

{

String dates = "<Dates>";

for (int j = 0; j < i; j++)

{

DateTime dt = DateTime.Now.Add(new TimeSpan(j, 0, 0, 0));

dates += "<Date><Month>" + dt.Month + "</Month><Day>" + dt.Day + "</Day><DayOfWeek>" + dt.DayOfWeek + "</DayOfWeek><Date>";

dates += "<Date><Month>" + dt.Month + "</Month><Day>" + dt.Day + "</Day><DayOfWeek>" + dt.DayOfWeek + "</DayOfWeek><Date>";

}

dates += "</Dates>";

return dates;

}

如果外面传来的i小点还好,但是如果很大呢?对于确切地i是多少,我们需要一点一点地开始找。从callstack上面,我们看到是LargeObjectHeap.Button1_Click调用了GetLotsOfDatesXML方法。

protected void Button1_Click(object sender, EventArgs e)

{

String str = GetLotsOfDatesXML(Int32.Parse(txtNumIterations.Text));

}

在这里,txtNumIterations是一个textbox控件。下面,基本上都是!do和!dso的工作了。

0:021> !dso
OS Thread Id: 0x1244 (21)
ESP/REG Object Name
029ef0f0 0b1a2270 System.String <String is invalid or too large to print>
029ef1a8 0b1a2270 System.String <String is invalid or too large to print>
029ef1bc 0b1a2270 System.String <String is invalid or too large to print>
029ef228 06a759e4 System.String </DayOfWeek><Date>
029ef28c 06a76df0 ASP.largeobjectheap_aspx
029ef2b4 06a77b84 System.ComponentModel.EventHandlerList
029ef2bc 06a77a84 System.Web.UI.WebControls.Button
029ef2c8 06a76df0 ASP.largeobjectheap_aspx
029ef304 06a76880 System.Web.HttpContext
...

0:021> !do 06a76df0
Name: ASP.largeobjectheap_aspx
MethodTable: 02746ccc
EEClass: 028d24cc
Size: 380(0x17c) bytes
(C:/WINDOWS/Microsoft.NET/Framework/v2.0.50727/Temporary ASP.NET Files/debuggersamples/e7443224/5232f845/App_Web_h0ctkxwz.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fa3e0 4001fe0 4 System.String 0 instance 02a7cba4 _id
790fa3e0 4001fe1 8 System.String 0 instance 00000000 _cachedUniqueID
68a2af44 4001fe2 c ...em.Web.UI.Control 0 instance 00000000 _parent
68a91070 4001fe3 2c System.Int32 0 instance 5 _controlState
68a85ea0 4001fe4 10 ...m.Web.UI.StateBag 0 instance 00000000 _viewState
68a2af44 4001fe5 14 ...em.Web.UI.Control 0 instance 00000000 _namingContainer
68a273d0 4001fe6 18 System.Web.UI.Page 0 instance 06a76df0 _page
...
68a7d910 4000004 16c ...ebControls.Button 0 instance 06a77a84 Button1
68a95f40 4000005 170 ...bControls.TextBox 0 instance 06a77be4 txtNumIterations
68a2bc80 4000006 174 ...Controls.HtmlForm 0 instance 06a77688 form1

好,继续看一下这个textbox。

0:021> !do 06a77be4
Name: System.Web.UI.WebControls.TextBox
MethodTable: 68a95f40
EEClass: 68a95ebc
Size: 80(0x50) bytes
(C:/WINDOWS/assembly/GAC_32/System.Web/2.0.0.0__b03f5f7f11d50a3a/System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fa3e0 4001fe0 4 System.String 0 instance 02a85a04 _id
790fa3e0 4001fe1 8 System.String 0 instance 00000000 _cachedUniqueID
68a2af44 4001fe2 c ...em.Web.UI.Control 0 instance 06a77688 _parent
68a91070 4001fe3 2c System.Int32 0 instance 5 _controlState
68a85ea0 4001fe4 10 ...m.Web.UI.StateBag 0 instance 06a788f0 _viewState
68a2af44 4001fe5 14 ...em.Web.UI.Control 0 instance 06a76df0 _namingContainer
68a273d0 4001fe6 18 System.Web.UI.Page 0 instance 06a76df0 _page
68a92e2c 4001fe7 1c ...+OccasionalFields 0 instance 06a78974 _occasionalFields
68a2b378 4001fe8 20 ...I.TemplateControl 0 instance 00000000 _templateControl
...

0:021> !do 06a788f0
Name: System.Web.UI.StateBag
MethodTable: 68a85ea0
EEClass: 68a85e30
Size: 16(0x10) bytes
(C:/WINDOWS/assembly/GAC_32/System.Web/2.0.0.0__b03f5f7f11d50a3a/System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name
79113dfc 400235f 4 ...tions.IDictionary 0 instance 06a78900 bag
79104f64 4002360 8 System.Boolean 0 instance 1 marked
79104f64 4002361 9 System.Boolean 0 instance 0 ignoreCase

0:021> !do 06a78900
Name: System.Collections.Specialized.HybridDictionary
MethodTable: 7a747ad4
EEClass: 7a7aa890
Size: 20(0x14) bytes
(C:/WINDOWS/assembly/GAC_MSIL/System/2.0.0.0__b77a5c561934e089/System.dll)
Fields:
MT Field Offset Type VT Attr Value Name
7a747bac 4001145 4 ...ed.ListDictionary 0 instance 06a78924 list
790fea70 4001146 8 ...ections.Hashtable 0 instance 00000000 hashtable
79104f64 4001147 c System.Boolean 0 instance 0 caseInsensitive

0:021> !do 06a78924
Name: System.Collections.Specialized.ListDictionary
MethodTable: 7a747bac
EEClass: 7a7aa918
Size: 28(0x1c) bytes
(C:/WINDOWS/assembly/GAC_MSIL/System/2.0.0.0__b77a5c561934e089/System.dll)
Fields:
MT Field Offset Type VT Attr Value Name
7a747c78 4001148 4 ...ry+DictionaryNode 0 instance 06a78940 head
790fed1c 4001149 10 System.Int32 0 instance 1 version
790fed1c 400114a 14 System.Int32 0 instance 1 count
791117c8 400114b 8 ...ections.IComparer 0 instance 00000000 comparer
790f9c18 400114c c System.Object 0 instance 00000000 _syncRoot

0:021> !do 06a78940
Name: System.Collections.Specialized.ListDictionary+DictionaryNode
MethodTable: 7a747c78
EEClass: 7a7aa9b8
Size: 20(0x14) bytes
(C:/WINDOWS/assembly/GAC_MSIL/System/2.0.0.0__b77a5c561934e089/System.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790f9c18 4001158 4 System.Object 0 instance 06a66bd8 key
790f9c18 4001159 8 System.Object 0 instance 06a78914 value
7a747c78 400115a c ...ry+DictionaryNode 0 instance 00000000 next

0:021> !do 06a66bd8
Name: System.String
MethodTable: 790fa3e0
EEClass: 790fa340
Size: 26(0x1a) bytes
(C:/WINDOWS/assembly/GAC_32/mscorlib/2.0.0.0__b77a5c561934e089/mscorlib.dll)
String: Text
...

找到了Text属性,看看是多少?

0:021> !do 06a78914
Name: System.Web.UI.StateItem
MethodTable: 68a131b4
EEClass: 68a13144
Size: 16(0x10) bytes
(C:/WINDOWS/assembly/GAC_32/System.Web/2.0.0.0__b03f5f7f11d50a3a/System.Web.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790f9c18 4002362 4 System.Object 0 instance 06a78184 value
79104f64 4002363 8 System.Boolean 0 instance 1 isDirty

0:021> !do 06a78184
Name: System.String
MethodTable: 790fa3e0
EEClass: 790fa340
Size: 28(0x1c) bytes
(C:/WINDOWS/assembly/GAC_32/mscorlib/2.0.0.0__b77a5c561934e089/mscorlib.dll)
String: 40000
Fields:
MT Field Offset Type VT Attr Value Name
790fed1c 4000096 4 System.Int32 0 instance 6 m_arrayLength
790fed1c 4000097 8 System.Int32 0 instance 5 m_stringLength
790fbefc 4000098 c System.Char 0 instance 34 m_firstChar
790fa3e0 4000099 10 System.String 0 shared static Empty
>> Domain:Value 001a8868:790d6584 001ca990:790d6584 <<
79124670 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 001a8868:06a303f0 001ca990:06a34118 <<

靠,循环了4万次!

结论:

地球人都知道,用+=会产生3*n个对象,如果用StringBuilder,就不会有这个问题了。

看到很多人在问如何分析dump,所以就写下了这篇短文,抛砖引玉。

一、安装 DebuggingToolsforWindows: 从以下 Microsoft 网站下载 DebuggingToolsforWindows: http://www.microsoft.com/whdc/devtools/debugging/installx86.mspx ,微软经常更新DebuggingToolsforWindows工具的,所以我们下载一个最新版本的,把DebuggingToolsforWindows 安装到 C:/Debuggers 文件夹,从命令行中运行工具需要一个简短的路径,这样更加容易使用。

二、为 WinDbg 中设置符号路径:

1.打开 WinDbg。
2.在 文件 菜单上, 单击 符号文件路径 。
3.在 符号路径 对话框中, 键入以下符号路径: srv*c:/symbols*http://msdl.microsoft.com/download/symbols
4.关闭 WinDbg, 然后键入 是 Yes ,以保存基本区信息。

三、SOS 扩展

SOS.dll 中提供的 Son of Strike 扩展 (SOS),用于调试 WinDbg 中的托管代码。在启动了调试程序并将其附加到托管进程(或加载故障转储)后,您可以通过键入以下代码加载 SOS.dll:
.loadby sos mscorwks

如果您正在调试的应用程序使用的是不同版本的 mscorwks.dll,则该命令无法执行,那么应找到该应用程序使用的 mscorwks.dll 版本的 SOS.dll,然后运行以下命令:

.load <path_to_sos>/sos.dll

SOS.dll 随 .NET Framework 安装在 %windir%/microsoft.net/framework/<.NET 版本> 目录下。SOS.dll 扩展提供了大量用于检查托管堆的有用命令。有关所有这些命令的文档,请参阅 SOS 调试扩展 (SOS.dll)。  

抱歉!评论已关闭.