和我一起作Tess的windbg lab - Lab4, High 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个。

3、打开这三个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

4、从上面三个dump来看,只有16和26号线程的时间一直在增长。

5、查看三个dump的!threadpool,都是100%

6、查看16和26号的托管callstack,如下:

  OS Thread Id: 0xd14 (26)
  ESP       EIP    
  04faf034 7c9585ec [HelperMethodFrame: 04faf034]
  04faf0a0 058f0981 AllProducts.Page_Load(System.Object, System.EventArgs)

7、查看所有托管线程的callstack,与上述代码类似,如25号线程。这里我们猜测,tinyget的压力不是一下子上来的,25号线程是后跑起来的,所以第一个dump的runaway中没有它的比较大的时间输出。

8、查看其他线程,加载合适的symbol之后,你会发现24号线程在作String.Concat和GC的操作。

9、查看上述的Page_load方法,里面调用了一个循环10000次的方法,然后针对输出的DataTable,进行了大量的String.Concat操作。我们知道,大量的Concat操作,同时也会在内存上产生大量的字符串对象,对内存会有压力,对GC也会有压力。

 

Over

posted @ 2010-06-27 14:02 鞠强 阅读(...) 评论(...) 编辑 收藏

hello

world