記一次 .NET 某半導(dǎo)體CIM系統(tǒng)崩潰分析
一、背景
1. 講故事
前些天有一位朋友在公眾號(hào)上找到我,說(shuō)他們的WinForm程序部署在20多臺(tái)機(jī)器上,只有兩臺(tái)機(jī)器上的程序會(huì)出現(xiàn)崩潰的情況,自己找了好久也沒分析出來(lái),讓我?guī)兔聪略趺椿厥?,就喜歡這些有點(diǎn)調(diào)試基礎(chǔ)的,dump也不需要我指導(dǎo)怎么去抓,接下來(lái)我們就上windbg開始分析吧。
二、WinDbg分析
1. 為什么會(huì)崩潰
尋找崩潰的表象比較簡(jiǎn)單,使用 windbg 的 !analyze -v 命令即可。
0:000> !analyze -v
...
EXCEPTION_RECORD: (.exr -1)
ExceptionAddress: 0000000000000000
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 0
...
STACK_TEXT:
0000003f`76f7ed58 00007ffa`f7c66d88 : 0000003f`00006120 00007ffa`f7bf98da 00000000`00000000 0000e4f5`bb3ba231 : user32!NtUserWaitMessage+0xa
0000003f`76f7ed60 00007ffa`f7bf9517 : 0000003f`00006120 0000003f`76f7ee80 00000000`00000000 00000000`00000000 : System_Windows_Forms_ni+0x2b6d88
0000003f`76f7ee10 00007ffa`f7bf8c2c : 0000003f`0006ec30 0000003f`00000001 0000003f`000c88c0 00000000`00000000 : System_Windows_Forms_ni+0x249517
0000003f`76f7ef10 00007ffa`f7bf8a25 : 0000003f`00006120 00000000`ffffffff 0000003f`00054848 0000003f`76f7f300 : System_Windows_Forms_ni+0x248c2c
0000003f`76f7efa0 00007ffa`9b4a0a08 : 0000003f`00007970 00000000`ffffffff 0000003f`000c88c0 0000003f`770bda90 : System_Windows_Forms_ni+0x248a25
0000003f`76f7f000 00007ffa`fab13753 : 00000000`00000001 0000003f`76f7f530 00007ffa`fac6710d 00000000`00000001 : 0x00007ffa`9b4a0a08
0000003f`76f7f040 00007ffa`fab1361c : 0000003f`00003330 00007ffa`f9acd94c 00000000`20000001 0000003f`00000000 : clr!CallDescrWorkerInternal+0x83
0000003f`76f7f080 00007ffa`fab144d3 : 00000000`00000000 00000000`00000004 0000003f`76f7f300 0000003f`76f7f3b8 : clr!CallDescrWorkerWithHandler+0x4e
0000003f`76f7f0c0 00007ffa`fac6f75a : 0000003f`76f7f200 00000000`00000000 00000000`00000000 00000000`00000000 : clr!MethodDescCallSite::CallTargetWorker+0x2af
0000003f`76f7f250 00007ffa`fac6f596 : 00000000`00000000 00000000`00000001 0000003f`00000000 00000000`00000000 : clr!RunMain+0x1ba
0000003f`76f7f430 00007ffa`fac6f4d4 : 0000003f`770bda90 0000003f`000015b0 0000003f`770bda90 0000003f`77093490 : clr!Assembly::ExecuteMainMethod+0xba
0000003f`76f7f720 00007ffa`fac6ea02 : 0000003f`76f7fd88 0000003f`76de0000 00000000`00000000 00000000`00000000 : clr!SystemDomain::ExecuteMainMethod+0x6b9
0000003f`76f7fd60 00007ffa`fac6e9b2 : 0000003f`76de0000 0000003f`76f7fee0 00000000`00000000 00007ffb`03c420e8 : clr!ExecuteEXE+0x43
0000003f`76f7fdd0 00007ffa`fac6e8f4 : ffffffff`ffffffff 00000000`00000000 00000000`00000000 00000000`00000000 : clr!_CorExeMainInternal+0xb2
0000003f`76f7fe60 00007ffb`03be6cf5 : 00000000`00000000 00000000`00000091 00000000`00000000 0000003f`76f7fe48 : clr!CorExeMain+0x14
0000003f`76f7fea0 00007ffb`03c8ea5b : 00000000`00000000 00007ffa`fac6e8e0 00000000`00000000 00000000`00000000 : mscoreei!CorExeMain+0xe0
0000003f`76f7fef0 00007ffb`0dc716ad : 00007ffb`03be0000 00000000`00000000 00000000`00000000 00000000`00000000 : mscoree!_CorExeMain_Exported+0xcb
0000003f`76f7ff20 00007ffb`0f924629 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
0000003f`76f7ff50 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d
STACK_COMMAND: ~0s; .ecxr ; kb
...
從卦中看,真的吸了一口涼氣,尼瑪這dump沒記錄到 crash 信息,有些朋友說(shuō)這個(gè) int 3 不是嗎?簡(jiǎn)單的說(shuō)不是,它是一個(gè)軟trap,抓dump的時(shí)候會(huì)有一個(gè)進(jìn)程的凍結(jié),這個(gè)凍結(jié)就是 int 3,所以你看dump中有這個(gè)異常 99% 都是正常的。
2. 異常哪里去了
按往常的套路,我都會(huì)推薦procdump這款工具讓朋友再抓一下,在重抓之前先看看可還有其他線索,可以用 !t 看看托管線程上是否掛了異常。
0:000> !t
ThreadCount: 76
UnstartedThread: 0
BackgroundThread: 69
PendingThread: 0
DeadThread: 6
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 26c4 0000003f770bda90 26020 Preemptive 0000000000000000:0000000000000000 0000003f77093490 0 STA
...
74 77 c544 0000003f1a08c470 21220 Preemptive 0000000000000000:0000000000000000 0000003f77093490 0 Ukn System.ExecutionEngineException 0000003f000011f8
75 78 18a88 0000003f1a329ae0 8029220 Preemptive 0000000000000000:0000000000000000 0000003f77093490 0 MTA (Threadpool Completion Port)
從卦中可以看到有一個(gè)線程拋了 System.ExecutionEngineException 異常,這是一個(gè)災(zāi)難性的情況,表示 CLR 在執(zhí)行自身代碼的時(shí)候崩掉了,驚訝之余趕緊看看它的線程棧為什么會(huì)崩。
0:074> k
# Child-SP RetAddr Call Site
00 0000003f`1bafea90 00007ffa`fb0283aa clr!WKS::gc_heap::background_mark_simple+0x36
01 0000003f`1bafeac0 00007ffa`fb028701 clr!WKS::gc_heap::revisit_written_page+0x2fe
02 0000003f`1bafeb50 00007ffa`fb01ffec clr!WKS::gc_heap::revisit_written_pages+0x251
03 0000003f`1bafec10 00007ffa`facefd01 clr!WKS::gc_heap::background_mark_phase+0x298
04 0000003f`1bafeca0 00007ffa`fb021fe5 clr!WKS::gc_heap::gc1+0xc0
05 0000003f`1bafed10 00007ffa`fab33e1e clr!WKS::gc_heap::bgc_thread_function+0x169
06 0000003f`1bafed50 00007ffb`0dc716ad clr!Thread::intermediateThreadProc+0x7d
07 0000003f`1baff810 00007ffb`0f924629 kernel32!BaseThreadInitThunk+0xd
08 0000003f`1baff840 00000000`00000000 ntdll!RtlUserThreadStart+0x1d
0:074> r
rax=000000001f808000 rbx=0000003f1bafe870 rcx=0000003efac80140
rdx=0000003f01000000 rsi=0000000000000000 rdi=0000003f1bafe380
rip=00007ffafb020c06 rsp=0000003f1bafea90 rbp=0000003f01c63270
r8=0000000000000000 r9=0000003f01c64000 r10=0000003f04271000
r11=0000000000000001 r12=00007ffa9bca83c0 r13=0000003f01c632a8
r14=ffffffffffffffff r15=0000003f01c63000
iopl=0 nv up ei pl zr na po nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010244
clr!WKS::gc_heap::background_mark_simple+0x36:
00007ffa`fb020c06 41f70000000080 test dword ptr [r8],80000000h ds:00000000`00000000=????????
從卦中信息看,當(dāng)前是一個(gè) bgc 線程,在后臺(tái)標(biāo)記對(duì)象的時(shí)候踩到了0區(qū)導(dǎo)致的崩潰,經(jīng)驗(yàn)告訴我,是不是此時(shí)的托管堆損壞了? 可以用 !verifyheap 驗(yàn)證下。
0:000> !verifyheap
No heap corruption detected.
從卦中信息看,當(dāng)前托管堆并沒有損壞,作為一個(gè)經(jīng)常為sos輸出坑過(guò)的人,現(xiàn)在我是不相信這個(gè)輸出的,所以我要找一下這個(gè) r8 對(duì)象到底是什么對(duì)象,接下來(lái)反匯編下 background_mark_simple 方法。
0:074> ub 00007ffa`fb020c06
clr!WKS::gc_heap::background_mark_simple+0x1a:
00007ffa`fb020bea 0941d3 or dword ptr [rcx-2Dh],eax
00007ffa`fb020bed e048 loopne clr!WKS::gc_heap::background_mark_simple+0x67 (00007ffa`fb020c37)
00007ffa`fb020bef 8b0dd3253c00 mov ecx,dword ptr [clr!WKS::gc_heap::mark_array (00007ffa`fb3e31c8)]
00007ffa`fb020bf5 44850481 test dword ptr [rcx+rax*4],r8d
00007ffa`fb020bf9 7548 jne clr!WKS::gc_heap::background_mark_simple+0x73 (00007ffa`fb020c43)
00007ffa`fb020bfb 44090481 or dword ptr [rcx+rax*4],r8d
00007ffa`fb020bff 4c8b02 mov r8,qword ptr [rdx]
00007ffa`fb020c02 4983e0fe and r8,0FFFFFFFFFFFFFFFEh
0:074> r rdx
rdx=0000003f01000000
0:074> !lno rdx
Before: 0000003f00ffff38 512 (0x200) xxx.xxx
After: 0000003f01000138 32 (0x20) System.String
Heap local consistency confirmed.
0:074> ? 0000003f01000000 - 0000003f00ffff38
Evaluate expression: 200 = 00000000`000000c8
0:074> !do 0000003f00ffff38
Name: xxx.xxx
MethodTable: 00007ffa9c0ac278
EEClass: 00007ffa9c095b20
Size: 512(0x200) bytes
Fields:
MT Field Offset Type VT Attr Value Name
...
00007ffaf9d1da88 40012e6 c8 System.String 0 instance 0000000000000000 <OPPORTUNITY>k__BackingField
...
經(jīng)過(guò)我上面的一頓分析,原來(lái)bgc標(biāo)記的對(duì)象是 <OPPORTUNITY>k__BackingField 字段,同時(shí)也驗(yàn)證了確實(shí)托管堆沒有損壞,接下來(lái)的問(wèn)題是為什么BGC在mark這個(gè)字段的時(shí)候拋出來(lái)了異常呢?
3. 繼續(xù)尋找真相
找不到突破口那就只能從線程棧上去挖,熟悉 bgc 后臺(tái)標(biāo)記的朋友應(yīng)該知道,后臺(tái)標(biāo)記會(huì)分成三個(gè)階段。
- 初始標(biāo)記階段
- 并發(fā)標(biāo)記階段
- 最終標(biāo)記階段
截一張我在 .NET高級(jí)調(diào)試訓(xùn)練營(yíng) PPT里的圖。
接下來(lái)的問(wèn)題是這個(gè)程序目前處于哪一個(gè)階段呢?根據(jù)線程棧上的 revisit_written_pages 方法,很顯然是處于第二階段,在第二階段中為了能夠識(shí)別對(duì)象修改的情況,CLR 使用了 Win32 的GetWriteWatch函數(shù)對(duì)內(nèi)存頁(yè)進(jìn)行監(jiān)控,監(jiān)控到的臟內(nèi)存頁(yè)會(huì)在第三階段做最后的清洗。
說(shuō)了這么多,有沒有源碼支撐呢?這里我們簡(jiǎn)單看一下 coreclr 的源代碼即可。
void gc_heap::revisit_written_pages(BOOL concurrent_p, BOOL reset_only_p)
{
get_write_watch_for_gc_heap(reset_watch_state, base_address, region_size,
(void**)background_written_addresses,
&bcount, is_runtime_suspended);
}
// static
void gc_heap::get_write_watch_for_gc_heap(bool reset, void * base_address, size_t region_size,
void * *dirty_pages, uintptr_t * dirty_page_count_ref,
bool is_runtime_suspended)
{
bool success = GCToOSInterface::GetWriteWatch(reset, base_address, region_size, dirty_pages,
dirty_page_count_ref);
}
bool GCToOSInterface::GetWriteWatch(bool resetState, void * address, size_t size, void * *pageAddresses, uintptr_t * pageAddressesCount)
{
uint32_t flags = resetState ? 1 : 0;
ULONG granularity;
bool success = ::GetWriteWatch(flags, address, size, pageAddresses, (ULONG_PTR*)pageAddressesCount, &granularity) == 0;
if (success)
{
assert(granularity == OS_PAGE_SIZE);
}
return success;
}
給了這么多的代碼,主要是想說(shuō) bgc的并發(fā)標(biāo)記利用了 Windows 提供的功能,結(jié)合朋友說(shuō)的只有兩臺(tái)機(jī)器會(huì)出現(xiàn)這種情況,到這里大概可以給出兩種方案:
- 更新Windows補(bǔ)丁,升級(jí)framework,大概率是兩者的兼容性問(wèn)題,導(dǎo)致內(nèi)存頁(yè)監(jiān)控上出了問(wèn)題。
- 修改配置文件禁用 bgc,這樣就不會(huì)走這些邏輯,從根子上繞過(guò)這個(gè)問(wèn)題。
三、總結(jié)
說(shuō)實(shí)話在我的dump分析旅程中,這個(gè)dump的分析難度還是比較大的,它考驗(yàn)著你對(duì)bgc線程底層運(yùn)作的理解,所幸的是我在調(diào)試訓(xùn)練營(yíng)里用windbg讓大家親眼目睹了后臺(tái)標(biāo)記三階段的詳細(xì)過(guò)程,真是三生有幸!