和我一起作TESS的windbg lab
时间：2010-10-14 来源：虹桥路3号
Lab1 CPU很闲但是程序没有响应
原文地址
http://blogs.msdn.com/b/tess/archive/2008/02/04/net-debugging-demos-lab-1-hang.aspx
操作步骤
1、产生压力：tinyget -srv:localhost -uri:/BuggyBits/FeaturedProducts.aspx -threads:30 -loop:50
2、观察taskmgr的输出：w3wp.exe的CPU为0，内存几乎没有变化
3、模拟手工操作：打开IE，输入地址：http://localhost/buggybits/featuredproducts.aspx，观察最下面的response time，我这里为17秒。
4、抓dump：adplus -hang -pn w3wp.exe -quiet -o c:\dumps
分析过程
a、加载sos：.loadby sos mscorwks
b、查看所有托管线程的callstack：~* e!clrstack。输出分为两类：
//类别1，类似的callstack一共23个，最上面的语句都是Monitor.Enter
OS Thread Id: 0xee0 (40)
ESP EIP
05c5f0cc 7c9585ec [GCFrame: 05c5f0cc]
05c5f208 7c9585ec [HelperMethodFrame: 05c5f208] System.Threading.Monitor.Enter(System.Object)
05c5f25c 05600df3 DataLayer.GetFeaturedProducts()
05c5f298 05600c7c FeaturedProducts.Page_Load(System.Object, System.EventArgs)
//其他代码
以及：
//类别2，有一个SleepInternal方法
OS Thread Id: 0x514 (24)
ESP EIP
0585ee08 7c9585ec [HelperMethodFrame: 0585ee08] System.Threading.Thread.SleepInternal(Int32)
0585ee5c 05600dfd DataLayer.GetFeaturedProducts()
0585ee98 05600c7c FeaturedProducts.Page_Load(System.Object, System.EventArgs)
c、上面的步骤2和步骤3中，指明了这很可能是一个block的问题，所以，使用命令：!syncblk来查看，是否有阻塞发生。而且上面的步骤b中的类别1，我们看到了Monitor.Enter方法。
d、!syncblk的输出如下：
0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
26 000fd17c 47 1 04c09698 514 24 02a86628 System.Object
-----------------------------
Total 31
CCW 2
RCW 0
ComClassFactory 0
Free 14
注意上面的MonitorHeld字段，是47，它意味着有（47-1）/2=23个线程被上面的Thread列（24）所阻塞，24号列正在拿着02a86628这个对象。
e、分析到这里就比较清楚了，线程24的方法中，通过调用Monitor.Enter正拿着一个对象，然后执行一个比较耗时的动作，这里用Thread.Sleep来模拟。由于只有Monitor.Exit的时候，该对象才可以被其他线程所使用，所以执行同样方法的线程就卡在Monitor.Enter这句话上了。都在等待，没有事情做，CPU就很低。
f、看上面步骤地5.b，GetFeaturedProducts方法的当前ip是05600dfd ，我们需要得到这个方法的md，执行命令：!ip2md 05600dfd ，结果如下：
0:024> !ip2md 05600dfd
MethodDesc: 02429048
Method Name: DataLayer.GetFeaturedProducts()
Class: 055b18ac
MethodTable: 0242905c
mdToken: 06000008
Module: 024285cc
IsJitted: yes
m_CodeOrIL: 05600dd0
g、然后我们有三种方法可以看代码：
根据md来看：!dumpil 02429048 （这个地址是上面步骤f中的输出的第一行MethodDesc的值）
根据native code来看：!u 05600dd0 （这个地址是上面步骤f中的输出的最后一行的m_CodeOrIL的值）
根据module来看：!dumpmodule 024285cc （这个地址是上面步骤分钟的输出的倒数第三行的Module的值）
h、我选择上面第三种模式来看，!dumpmodule之后会得到module所在的assembly的dll的名字，然后用reflector打开
i、定位到DataLayer.GetFeaturedProducts方法上，代码如下：
lock (this.syncobj)
{
Thread.Sleep(5000);
// 其他代码
}
到这里，问题已经很清楚了。
Lab2 程序崩溃
原文地址
http://blogs.msdn.com/b/tess/archive/2008/02/08/net-debugging-demos-lab-2-crash.aspx
操作步骤
1、打开 http://localhost/BuggyBits/Reviews.aspx，点击5次refresh按钮，然后看到巨大的黑色粗体字：Service Unavailable
分析过程
检察eventlog，点开始-运行，输入：eventvwr，先看Application的，会有如下错误：
Process ID: 1808
Exception: System.NullReferenceException
以及
Process ID: 3544
Exception: System.NullReferenceException
以及
Process ID: 7234
Exception: System.NullReferenceException
以及
Process ID: 2343
Exception: System.NullReferenceException
以及
Process ID: 9087
Exception: System.NullReferenceException
3、上面的错误，我们可以看到，W3WP一共crash了5次，然后看System的日志，可以看到：
事件类型: 错误
事件来源: W3SVC
事件种类: 无
事件 ID: 1002
日期: 2010-6-27
事件: 12:35:28
用户: N/A
计算机: VPC2003
描述:
应用程序池 'LabAppPool' 被自动禁用，原因是为此应用程序池提供服务的进程中出现一系列错误。
有关更多信息，请参阅在 http://go.microsoft.com/fwlink/events.asp 的帮助和支持中心。
4、打开IIS，察看应用程序池，你会发现LabAppPool已经被disable掉了。
5、右键查看该apppool的属性，在快速失败保护中会发现，如果5分钟之内有5次crash，则该apppool会被禁用掉。
6、好了，这是一个典型的crash问题，并导致apppool被disable掉，对客户端显示HTTP503错误。现在开始debug
7、抓一个crash的dump，我们会发现产生了3个dump，分别是1st chance的AV、1st chance的process shutdown和2nd chance的netclr full，先打开第一个av的dump
a、由于是crash的dump，所以windbg会自动切换到导致AV的那个线程，我这里是18号。
b、加载sos，会有如下信息：
0:018> .loadby sos mscorwks
------------------------------------------------------------
sos.dll needs a full memory dump for complete functionality.
You can create one with .dump /ma <filename>
------------------------------------------------------------
因为这是一个mini dump，所以很多信息我们看不到。解决办法之一是在adplus的时候，用参数-FullOnFirst，但是这个参数有副作用，我们后面会看到。
c、查看托管线程，如下：
0:018> !clrstack
PDB symbol for mscorwks.dll not loaded
OS Thread Id: 0x64c (18)
ESP EIP
0221f950 05500efb Review.Finalize()
0221fc1c 79fbcca7 [ContextTransitionFrame: 0221fc1c]
0221fcec 79fbcca7 [GCFrame: 0221fcec]
可以看到，Review.Finalize方法导致了AV错误。
d、运行!threads，输出如下：
0:018> !threads
ThreadCount: 4
UnstartedThread: 0
BackgroundThread: 4
PendingThread: 0
DeadThread: 0
Hosted Runtime: yes
PreEmptive GC Alloc Lock
ID OSID ThreadOBJ State GC Context Domain Count APT Exception
16 1 2a4 000dbce8 3808220 Enabled 00000000:00000000 001028a8 1 Ukn (Threadpool Worker)
18 2 64c 000e7de0 b220 Disabled 00000000:00000000 001028a8 0 Ukn (Finalizer)
19 3 538 000ec2c0 1220 Enabled 00000000:00000000 000d8fd8 0 Ukn
20 4 594 000ff408 80a220 Enabled 00000000:00000000 000d8fd8 0 Ukn (Threadpool Completion Port)
可以看到发生AV的18号线程是GC的finalizer线程。那么具体的exception在哪里呢？
e、执行命令，!dso。输出如下：
0:018> !dso
Error requesting details
Unable to determine bounds of gc heap
ooh，我们在一个mini的dump里面，很多东西是看不到的。so，需要抓一个fulldump来看。
f、重新运行adplus，增加参数：-FullOnFirst，重新看dump。
g、看!dso的结果：
0:018> !dso
OS Thread Id: 0x908 (18)
ESP/REG Object Name
esi 029b9158 Review
0221f990 029b9158 Review
0221f9dc 029b9158 Review
0221f9e8 029b9158 Review
0221f9fc 029b9158 Review
0221fa00 029b9158 Review
0221fa10 029b9158 Review
0221fae8 029b9158 Review
0221fcb0 029b9158 Review
没有exception，只有一个Review对象，继续看，执行!do 029b9158
MT Field Offset Type VT Attr Value Name
790fd8c4 4000008 4 System.String 0 instance 00000000 quote
790fd8c4 4000009 8 System.String 0 instance 00000000 source
注意上面的两个string，都是0，这意味着都是null，那么，是否可能是null.SomeMethod导致的呢？
h、看步骤c中的Review.Finalizer方法，代码如下：
~Review()
{
if (quote.ToString() != string.Empty)
{
quote = null;
}
}
嗯，问题找到了，在于上面的quote.ToString造成的，因为某个原因，quote这个字符串变成了null，所以出现AV了。
i、实际上如果查看页面代码，我们能看到一个Clear方法把这个变量变成了null。
Lab3 内存暴涨
原文地址
http://blogs.msdn.com/b/tess/archive/2008/02/15/net-debugging-demos-lab-3-memory.aspx
操作步骤
1、产生压力：tinyget -srv:localhost -uri:/BuggyBits/Links.aspx -loop:4000
2、观察taskmgr的输出，w3wp的内存每秒钟大概增长100M。
3、内存到700M左右的时候，抓一个hang dump
分析过程
1、由于这是一个memory的问题，所以我们要先看GC Heap的情况，运行命令：!eeheap -gc，结果如下：
GC Heap Size 0x2b307720(724596512)
由于dump一共870M，而GC占用了720M左右，所以我们的重点在于托管内存的分析。
2、看heap的整体状况，运行!dumpheap -stat，结果如下：
790fd8c4 49787 721599752 System.String
嗯，720M的托管内存中，String占用了绝大多数。
3、看一下string的情况，根据2/8原则，大小相同的string也许会很多，这里我们过滤一下，看看10K以上大小的字符串，运行命令：!dumpheap -mt 790fd8c4 -min 10000
0331d6dc 790fd8c4 20020
03322534 790fd8c4 20020
0332738c 790fd8c4 20020
0332c1e4 790fd8c4 20020
0333103c 790fd8c4 20020
大部分都是20K的字符串，随便找一个，我们需要看它被谁分配的
4、运行!gcroot 0331d6dc，结果如下：
Scan Thread 16 OSTHread 318
Scan Thread 18 OSTHread c38
Scan Thread 19 OSTHread a40
Scan Thread 20 OSTHread c00
Scan Thread 24 OSTHread 998
Scan Thread 14 OSTHread 4cc
Finalizer queue:Root:0331d6b8(Link)->
0331d6c8(System.Text.StringBuilder)->
0331d6dc(System.String)
在14号线程中，Link引用了这个字符串。而且我们看到，link是在Finalizer Queue中的。
5、查看finalizequeue，输出如下：
057e0bcc 35998 575968 Link
一共35998个Link对象。由于该对象存在于Finalizequeue中，所以一定显示的实现了Finalize方法。
6、查看该方法，代码如下：
~Link()
{
//some long running operation when cleaning up the data
Thread.Sleep(5000);
}
7、换个方向，看上面步骤4中的那个Link对象，!do 0331d6b8，输出结果如下：
MT Field Offset Type VT Attr Value Name
790fdc5c 4000006 4 ...ext.StringBuilder 0 instance 0331d6c8 url
790fd8c4 4000007 8 System.String 0 instance 029bb0b8 name
再看第一个url对象，运行!do 0331d6c8 ，结果如下：
MT Field Offset Type VT Attr Value Name
791016bc 40000b1 8 System.IntPtr 1 instance dc1d8 m_currentThread
79102290 40000b2 c System.Int32 1 instance 2147483647 m_MaxCapacity
790fd8c4 40000b3 4 System.String 0 instance 0331d6dc m_StringValue
注意最后一行的那个m_StringValue，对比一下步骤7中的!gcroot输入。
从这里我们看到，Link中包含了一个StringBuilder，而StringBuilder中包含了一个20K的字符串。
8、看代码：
public Link(string name, string url)
{
this.name = name;
this.url.Append(url);
}
可以看到，Link对象的构造方法中，引用了字符串。
9、再回头看上面的步骤6，Link自作聪明的实现了Finalize方法，但是该方法执行的时间太长（这里是5秒钟），导致垃圾回收的时候，迟迟不能把该对象回收掉。因为Link引用了字符串url，所以相应的字符串也无法被回收。这样内存就上涨的很快了。
Lab4 CPU很忙
原文地址
http://blogs.msdn.com/b/tess/archive/2008/02/22/net-debugging-demos-lab-4-high-cpu-hang.aspx
操作步骤
1、产生压力：tinyget -srv:localhost -uri:/BuggyBits/AllProducts.aspx -threads:5 -loop:1
2、观察taskmgr的输出，w3wp的CPU为99%，这是一个典型的高CPU的Hang。抓一个hang的dump，然后等待10秒钟，再抓一个；10秒钟之后再抓一个。一共抓3个。
分析过程
1、打开这三个dump，加载sos之后，分别查看!runaway的输出。
第一个dump的结果：
0:000> !runaway
User Mode Time
Thread Time
27:848 0 days 0:00:06.279
26:c84 0 days 0:00:03.054
16:f10 0 days 0:00:02.784
28:d14 0 days 0:00:02.403
23:f0c 0 days 0:00:02.323
第二个dump的结果：
0:000> !runaway
User Mode Time
Thread Time
26:848 0 days 0:00:06.990
25:c84 0 days 0:00:06.138
22:f0c 0 days 0:00:05.718
16:f10 0 days 0:00:05.387
27:d14 0 days 0:00:04.546
第三个dump的结果：
0:000> !runaway
User Mode Time
Thread Time
25:848 0 days 0:00:12.167
26:d14 0 days 0:00:09.373
22:f0c 0 days 0:00:08.422
24:c84 0 days 0:00:07.811
16:f10 0 days 0:00:07.250
2、从上面三个dump来看，只有16和26号线程的时间一直在增长。
3、查看三个dump的!threadpool，都是100%
4、查看16和26号的托管callstack，如下：
OS Thread Id: 0xd14 (26)
ESP EIP
04faf034 7c9585ec [HelperMethodFrame: 04faf034]
04faf0a0 058f0981 AllProducts.Page_Load(System.Object, System.EventArgs)
5、查看所有托管线程的callstack，与上述代码类似，如25号线程。这里我们猜测，tinyget的压力不是一下子上来的，25号线程是后跑起来的，所以第一个dump的runaway中没有它的比较大的时间输出。
6、查看其他线程，加载合适的symbol之后，你会发现24号线程在作String.Concat和GC的操作。
7、查看上述的Page_load方法，里面调用了一个循环10000次的方法，然后针对输出的DataTable，进行了大量的String.Concat操作。我们知道，大量的Concat操作，同时也会在内存上产生大量的字符串对象，对内存会有压力，对GC也会有压力。
作者：鞠强
相关阅读 更多 +
