IE的leak
2006-10-24 22:53 lixiong 阅读(4018) 评论(10) 编辑 收藏 举报IE的leak
问题背景:
客户新开发的B/S办公自动化系统，所有的操作都可以在浏览器上完成。为了支持灵活的UI，页面中使用了很多javascript/DHTML。比如javascript可以根据客户在某一个页面中前半部分的用户输入，动态生成后半部分的HTML表格。
系统上线后受到广泛的好评。随着使用熟练程度提高，用户每天提交的业务也直线上升。但是问题也在这个时候出现了。某些部门发现使用这个系统几个小时后，整个系统的性能有明显的下降，比如切换窗口缓慢。客户的IT人员检查用户的系统后发现，问题发生的时候iexplore进程占用了接近1GB的内存。
万里长征的第一步:
拿到这个问题后，可以肯定的一点就是iexplore的内存泄漏。经过一系列的初步定位后，发现内存泄漏的问题跟某些特定的DHTML相关。比如每次动态操作<table>元素生成报表后，哪怕做了对应的释放调用，内存使用就会增加。根据这个信息，对一部分代码进行简化后，得到可以重现问题的sample:
Frame.htm:
<INPUT Type="Button" OnClick="clkadd()" Value="Click me to add row">
<INPUT Type="Button" OnClick="clkdel()" Value="Click me to
<script>
function clkadd(){
var i;
for(i=0;i<100;i++){
oRow = oTable.insertRow();
var j;
for(j=0;j<4;j++){
oCell = oRow.insertCell();
oCell.innerHTML = "<IFRAME FRAMEBORDER=0 width='100%' height='100%' SRC='hostframe.htm'></IFRAME>"
}
}
}
function clkdel(){
var i;
for(i=0;i<100;i++){
oTable.deleteRow(0);
}
}
</script>
<TABLE name="oTable" id="oTable">
</TABLE>
Hostframe.htm:
<BODY onload="t.focus()">
<INPUT TYPE="text" id="testid" value="some value">
</BODY>
用IE打开frame.htm，按第一个按钮，动态生成一个100*4的table。按第二个按钮可以删除整个table。无论使用IE6还是IE7，连续进行一系列的创建/删除操作后，就可以看到iexplore.exe进程的内存占用明显上升。
作为内存泄漏的排错例子，接下来会用一系列不同的工具和方法来尽可能多地探寻这个问题的根源。首先会抓取性能日志，然后分析内存分配的callstack，接下来还会针对dump做一些分析，最后讨论解决办法。目的在于演示典型的内存泄漏问题的完整排错步骤。
首先使用性能监视器观察内存的具体变化。添加virtual bytes和private bytes，连续点击按钮测试七分钟左右，看到如下的曲线：
从图形中可以看到，private bytes跟virtual bytes一起飙升。Private bytes从最初的18.5MB上升到最后的159MB。Private bytes根virtual bytes增长的斜率近似，所以是很典型的泄漏，暂时排除fragmentation的可能。
对于unmanaged leak,手中的武器非常有限。在没有CLR的世界里，既没有办法检查某内存地址上数据的类型，也无法获取数据之间的引用关系。跟CLR程序不同，直接从dump能找到的线索非常有限。
前面提到过，排错的终极武器是log。如果静态的dump分析没有帮助，那么可以动态地记录内存的操作。考虑下面这种办法:
每次内存分配的时候记录下分配内存的callstack，当释放这块内存的时候，也同时释放记录下的callstack。当问题发生后，所残留的callstack对应的内存都是泄漏掉的。分析callstack就可以找到这些泄漏掉的内存是如何分配的
如何在每次内存分配的时候记录下分配内存的callstack呢？记录callstack很容易，只需要保存发生内存分配时候ESP所指向的地址附近的数据，最后通过symbol文件就可以找到callstack。激活内存分配的操作稍微困难，可以在不同的层次来完成:
1. 如果程序使用C/C++开发，根据第二章的介绍，可以利用CRT Debug Heap进行自动分析。甚至可以重载C/C++中的operation new, operator new []和malloc来实现自己的内存分配函数
2. Windows Heap Manager也提供了callstack trace功能。在激活pageheap的trace功能后，通过HeapAlloc API发生分配时候的callstack被Heap Manager自动保存在进程中。通过检查dump，或者其它的工具能够读取保存下来的callstack
3. 所有的用户台函数分配都要通过VirtualAllocEx完成。可以通过API Hook截获该Virtual系列的内存操作调用，保存成log最后分析
三种方法中第三种实用性最广，但是实现起来难度最大。回头看当前这个IE Leak问题。首先没有IE的源代码，所以第一种方法就没用。如果泄漏掉的内存都是Heap内存的话，可以采取第二种方法。绝大多数微软的产品都不会通过Virtual系列函数直接分配内存。所以这里可以使用第二种方法。如果不太确定，可以先抓去dump，使用!heap命令检查进程中所有Heap的大小，然后跟总体内存使用比较Heap所占的百分比。当virtual bytes到160MB的时候抓dump,使用!heap –s统计Heap使用：
0:000> !heap -s
LFH Key: 0xd4a587a8
Affinity manager status:
- Virtual affinity limit 4
- Current entries in use 3
- Statistics: Swaps=10, Resets=0, Allocs=10
Heap Flags Reserv Commit Virt Free List UCR Virt Lock Fast
(k) (k) (k) (k) length blocks cont. heap
-----------------------------------------------------------------------------
00140000 00000002 131072 87368 88456 4612 336 27 0 2 LFH
00240000 00008000 64 12 12 10 1 1 0 0
00360000 00001002 1088 536 536 17 6 1 0 0 L
00370000 00001002 3136 1380 1412 53 4 4 0 0 L
01050000 00000002 1024 20 20 2 1 1 0 0 L
013e0000 00001002 256 228 228 64 1 1 0 0 L
01550000 00001003 256 256 256 250 1 0 0 bad
01590000 00001003 256 56 56 4 1 1 0 bad
015d0000 00001003 64 8 8 3 2 1 0 bad
015e0000 00001002 64 32 32 18 1 1 0 0 L
02090000 00001002 64 12 12 1 1 1 0 0 L
03210000 00001002 256 32 32 1 1 1 0 0 L
037f0000 00001002 1024 1024 1024 1016 2 0 0 0 L
03260000 00001002 64 44 44 8 1 1 0 0 L
01b30000 00001002 64 16 16 7 1 1 0 0 L
04430000 00001002 64 48 48 40 2 1 0 0 L
041c0000 00001002 64 16 16 3 1 1 0 0 L
04320000 00001002 64768 34984 34984 1271 0 1 1 0 L
-----------------------------------------------------------------------------
从上面的表格可以看到，Heap 140000和Heap 4320000分别reverse了131MB和64MB内存，分别commit了87MB和35MB内存。Commit的内存总合是120MB。由此可以看出泄漏的内存几乎都是Heap
在第二章的题外话中已经介绍过如何利用pageheap的trace功能检查内存泄漏和内存碎片。当时是随机挑选出heap pointer，根据统计信息总结出泄漏的地址都是从一个固定的callstack分配。这样的做法毕竟不够严谨。其实可以采用pageheap跟umdh结合来自动分析pageheap记录下的callstack。Umdh在windbg安装目录下就可以找到。对于激活了heap trace功能的进程来说，umdh可以随时提取出进程中记录的所有callstack，并且保存到文件中。Umdh还可以自动分析两个log文件的差异。所以，在激活heap trace后，在增长前用umdh抓一次log, 内存增长后再抓一次log。然后用umdh自动比较就可以得到严谨的统计结果。详细步骤请参考:
Umdhtools.exe： 如何使用 umdh.exe 来查找内存泄漏
http://support.microsoft.com/kb/268343/zh-cn
下面是使用umdh排查这个问题的详细步骤:
首先要对IE进程激活heap trace.如果使用pageheap.exe工具，可以用:
Pageheap /enable iexplore.exe
Pageheap非常方便，但是不够灵活。上面的命令除了激活heap trace外，同时还激活了heap校验。排查内存泄漏之需要heap trace就可以了，heap校验可能会带来性能上的额外卡销。所以这里使用文章中描述的gflag工具来激活heap trace:
C:\Debuggers>gflags -i iexplore.exe +ust
Current Registry Settings for iexplore.exe executable are: 00001000
ust - Create user mode stack trace database
当umdh读取callstack的时候需要symbol文件。所以要用下面的命令设定symbol path
C:\Debuggers>set _NT_SYMBOL_PATH=SRV*D:\websymbols*http://msdl.microsoft.com/dow
nload/symbols
完成上面两步后，就可以开始测试了。首先启动IE进程，打开发生问题的页面，然后立刻抓取一次heap trace log:
C:\Debuggers>umdh -p:5728 -f:ie1.log
这里的5728是IE的进程号，log文件保存到ie1.log中
接下来点几次按钮，让内存上升30MB左右。这里是保证IE完成了必要的cache，然后再抓一次log:
C:\Debuggers>umdh -p:5728 -f:ie2.log
然后开始狂点按钮，让问题明显化。当内存上涨到160MB左右的时候，抓取第三次log:
C:\Debuggers>umdh -p:5728 -f:ie3.log
Ie3.log有10MB左右。打开ie3.log文件可以看到，文件头列出了当前所有的Heap Handle:
- - - - - - - - - - Heap summary - - - - - - - - - -
00140000
00240000
00360000
00370000
02050000
023E0000
02550000
02590000
025D0000
025E0000
03090000
03050000
04730000
04830000
049A0000
05720000
接下来是所有的保存下来的callstack。
*- - - - - - - - - - Start of data for heap @ 00140000 - - - - - - - - - -
Flags: 58000062
Entry Overhead: 8
*- - - - - - - - - - Heap 00140000 Hogs - - - - - - - - - -
000000AC bytes in 0x1 allocations (@ 0x0000003C + 0x0000001C) by: BackTrace00002
ntdll!RtlAllocateHeapSlowly+00000041
ntdll!RtlAllocateHeap+00000E9F
ntdll!LdrpAllocateUnicodeString+00000035
ntdll!LdrpCheckForKnownDll+0000017D
ntdll!LdrpMapDll+000000F2
ntdll!LdrpLoadImportModule+0000017C
ntdll!LdrpHandleOneOldFormatImportDescriptor+0000005B
ntdll!LdrpHandleOldFormatImportDescriptors+0000001C
ntdll!LdrpWalkImportDescriptor+000001A5
ntdll!LdrpInitializeProcess+00000E3E
ntdll!_LdrpInitialize+000000D0
ntdll!KiUserApcDispatcher+00000025
000000B0 bytes in 0x1 allocations (@ 0x00000050 + 0x00000018) by: BackTrace00003
ntdll!RtlAllocateHeapSlowly+00000041
ntdll!RtlAllocateHeap+00000E9F
ntdll!LdrpAllocateDataTableEntry+00000031
ntdll!LdrpMapDll+00000462
ntdll!LdrpLoadImportModule+0000017C
ntdll!LdrpHandleOneOldFormatImportDescriptor+0000005B
ntdll!LdrpHandleOldFormatImportDescriptors+0000001C
ntdll!LdrpWalkImportDescriptor+000001A5
ntdll!LdrpInitializeProcess+00000E3E
ntdll!_LdrpInitialize+000000D0
ntdll!KiUserApcDispatcher+00000025
分析log文件的一种方法是根据出现次输对callstack进行排序。出现得最多的callstack最值得怀疑。另外一种方法是使用umdh自动分析两次抓到的log文件:
C:\Debuggers>umdh ie2.log ie3.log > cmp23.txt
打开cmp23.txt可以看到:
+ 36a40 ( 3ebc0 - 8180) 1f allocs BackTrace20461
+ 10cd0 ( 119a0 - cd0) 276 allocs BackTrace19986
+ d260 ( d680 - 420) 34 allocs BackTrace19985
+ c69c ( 108d0 - 4234) 4 allocs BackTrace19816
+ 5b30 ( 6260 - 730) 44 allocs BackTrace19221
+ 4654 ( 4aa4 - 450) 45 allocs BackTrace19215
+ 3ba0 ( 3da0 - 200) 7a allocs BackTrace19592
+ 3580 ( 3580 - 0) 8 allocs BackTrace20575
…
- 140 ( 0 - 140) 0 allocs BackTrace13963
- 140 ( 0 - 140) 0 allocs BackTrace04660
- 148 ( 0 - 148) 0 allocs BackTrace13972
- 148 ( 0 - 148) 0 allocs BackTrace04178
- 1a0 ( 0 - 1a0) 0 allocs BackTrace19445
- 268 ( 1810 - 1a78) a allocs BackTrace00531
Total increase == b8cba
总的来说，分析的结果给出了各个callstack相关的统计信息，并且按照内存增长排序。数据用１６进制表示。
拿第一行作说明。BackTrace20461是callstack的ID。在log文件中查找BackTrace20461就可以找到具体的callstack信息：
00002060 bytes in 0x1 allocations (@ 0x00002000 + 0x00000018) by: BackTrace20461
ntdll!RtlAllocateHeapSlowly+00000041
ntdll!RtlAllocateHeap+00000E9F
…
1f allocs表示log3中该callstack一共出现了1f次。3ebc0其实是1f*2060 的近似结果， 2060是该callstack每次导致的内存增长量。我也不太清楚这里的结果为何是一个近似值。3ebc0是log3中该callstack分配的所有内存。8180是log2中该callstack分配的所有内存。差值36a40就是该callstack导致的内存增长。
需要注意的是，Heap Manager用来保存callstack的buffer是有限的。所以无法保证记录下所有的Heap分配的callstack。对log的分析应该是统计意义上的，而不能用作具体的量化。所以这里的数据只表示BackTrace20461对应的callstack相对其它callstack来说导致了更多的内存增量，36a40是一个参考数据，单是并不保证36a40就是实际的内存增长。
根据上面的分析，BackTrace20461和BackTrace19986的增量相对其它增量来说要高一个数量级。找到对应的callstack:
00002060 bytes in 0x1 allocations (@ 0x00002000 + 0x00000018) by: BackTrace20461
ntdll!RtlAllocateHeapSlowly+00000041
ntdll!RtlAllocateHeap+00000E9F
mshtml!_MemAllocClear+00000023
mshtml!CTxtBlk::InitBlock+00000021
mshtml!CTxtArray::AddBlock+0000002A
mshtml!CTxtPtr::InsertRange+00000048
mshtml!CTxtPtr::InsertRepeatingChar+0000005F
mshtml!CMarkup::CreateInitialMarkup+00000093
mshtml!CMarkup::DestroySplayTree+00000370
mshtml!CMarkup::UnloadContents+000002AB
mshtml!CMarkup::TearDownMarkupHelper+00000090
mshtml!CMarkup::TearDownMarkup+00000044
mshtml!CFrameSite::TearDownFrameContent+0000004F
mshtml!CElement::PrivateRelease+00000029
mshtml!CMimeTypes::Release+0000000E
mshtml!CSpliceTreeEngine::RemoveSplice+0000097E
mshtml!CMarkup::SpliceTreeInternal+00000092
mshtml!CDoc::CutCopyMove+000000D8
mshtml!CDoc::Remove+00000017
mshtml!CElement::RemoveOuter+00000063
mshtml!CTableLayout::deleteElement+0000005D
mshtml!CTable::deleteRow+000000AA
mshtml!Method_void_oDolong+0000005C
mshtml!CBase::ContextInvokeEx+000004EF
mshtml!CElement::ContextInvokeEx+00000070
mshtml!CTable::ContextThunk_InvokeEx+000000B5
jscript!IDispatchExInvokeEx2+000000AC
jscript!IDispatchExInvokeEx+00000056
jscript!InvokeDispatchEx+00000078
jscript!VAR::InvokeByName+000000BA
jscript!VAR::InvokeDispName+00000043
jscript!VAR::InvokeByDispID+000000B9
00000070 bytes in 0x1 allocations (@ 0x00000010 + 0x00000018) by: BackTrace19986
ntdll!RtlAllocateHeapSlowly+00000041
ntdll!RtlAllocateHeap+00000E9F
mshtml!_MemAllocClear+00000023
mshtml!CCollectionCache::InitReservedCacheItems+0000006A
mshtml!CMarkup::InitCollections+0000005A
mshtml!CWindow::GetDispID+00000146
mshtml!COmWindowProxy::GetDispID+000000DF
mshtml!COmWindowProxy::subGetDispID+00000017
jscript!IDispatchExGetDispID+0000004B
jscript!GetDex2DispID+00000038
jscript!VAR::GetDispID+000000F2
jscript!CScriptRuntime::GetVarVal+00000031
jscript!CScriptRuntime::Run+000008FC
jscript!ScrFncObj::Call+0000008D
jscript!CSession::Execute+000000A1
jscript!NameTbl::InvokeDef+00000179
jscript!NameTbl::InvokeEx+000000CB
mshtml!CBase::InvokeDispatchWithThis+000001D7
mshtml!CBase::InvokeEvent+000001AD
mshtml!COmWindowProxy::FireEvent+00000146
mshtml!COmWindowProxy::Fire_onload+000000CF
mshtml!CMarkup::OnLoadStatusDone+0000040C
mshtml!CMarkup::OnLoadStatus+0000004C
mshtml!CProgSink::DoUpdate+00000533
mshtml!CProgSink::OnMethodCall+0000000F
mshtml!GlobalWndOnMethodCall+00000101
mshtml!GlobalWndProc+00000181
USER32!InternalCallWinProc+00000028
USER32!UserCallWinProcCheckWow+00000151
USER32!DispatchMessageWorker+00000327
USER32!DispatchMessageW+0000000F
IEFRAME!CTabWindow::_TabWindowThreadProc+00000189
根据上面的分析，成功地找到了可疑的callstack。对该callstack的分析稍后再说，先回顾一下拿到callstack的关键。关键点不在于umdh工具的使用，而是Heap Manager自带的heap trace。在确定了泄露的内存是Heap以后，激活heap trace就可以捕捉到callstack。有了callstack后具体如何分析可以根据实际情况而变化。
如果不使用umdh工具，直接察看激活了heap trace的dump文件也是可以的。在抓取log3的时候同时用adplus抓取iexplore的dump，分析如下:
to be continued...
