Da jeg kom tilbage fra forældreorlov, blev jeg involveret i at fejlsøge nogle OutOfMemoryExceptions, en af mine kolleger havde oplevet. Det var ikke så meget det, at der kom exceptions, men af en eller anden grund væltede disse exceptions hele afviklingsmiljøet. Vores .NET-kode afvikles i en CLR indlæst i en anden proces. Problemet var således, at disse exceptions rev værtsprocessen med sig i faldet. Det var ikke særlig hensigtsmæssigt.
Desværre var det relativt omfattende at reproducere fejlen, så derfor satte jeg mig for, at forsøge at genskabe problemet under lidt enklere forhold. Det er jo heldigvis ikke særlig svært, at fremprovokere en OutOfMemoryException, så jeg skulle bare finde en lille applikation i vores framework, som jeg kunne lade det gå ud over. Ikke længe efter kunne jeg således reproducere problemet, og så var det jo bare at finde ud af, hvorfor vores almindelige fejlhåndtering af en eller anden grund var sat ud af spil.
Jeg fyrede op under min applikation og koblede WinDbg på sagen. Hvor svært kunne det være. Desværre opførte applikationen sig eksemplarisk i selskab med WinDbg. Godt nok fik jeg en OutOfMemoryException som forventet, men vores fejlhåndtering virkede pludselig efter hensigten.
Min første tanke var således, at der var en eller anden sindrig race condition i fejlhåndteringen. En debugger ændrer som bekendt timingen i afviklingen, så det kunne jo være, at WinDbg introducerede den lille forskel, der var afgørende for om det virkede eller ej. Det måtte undersøges.
Jeg læste en masse kode igennem, men kunne ikke finde evidens for at der skulle være en race condition. Så debuggede jeg noget mere, forstyrrede et par kolleger, rev mig lidt i håret og var i det hele taget ikke just springfuld af ideer til, hvorfor pokker det opførte sig fint, så snart jeg pudsede WinDbg på problemet.
Efter at have spildt en rum tid med forskellige mindre undersøgelser, kastede jeg mig over Mario Hewardts seneste bog Advanced .NET Debugging. Den havde jeg læst lige inden, jeg gik på orlov, og jeg erindrede, at der vist var et afsnit om debugging af OutOfMemoryExceptions.
Bogen beskriver blandt andet en interessant registry setting, der kan bruges til hjælp af debugging af netop OutOfMemoryExceptions.
Sætter vi
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\.NETFramework\GCBreakOnOOM (DWORD)
til andet end 0, vil afviklingsmiljøet indskyde en break-instruktion i applikationen ved det første tegn på out of memory. Bogen beskriver godt nok flere værdier, men jeg kan kun konstatere at mulighederne er nul og ikke nul. Står nøglen til andet end nul, indskyder CLRen således et debug break, lige så snart den konstaterer out of memory.
Denne setting får altså afviklingsmiljøet til at opføre sig helt anderledes, og jeg havde ganske rigtigt pillet ved den, inden jeg gik på orlov og derefter glemt alt om det. Det forklarede, hvorfor problemet ikke forekom, når WinDbg var koblet på processen. I det tilfælde stoppede applikationen blot, og jeg kunne fortsætte, som om intet var hændt. Vores værtsproces havde det til gengæld ikke særlig godt med en umotiveret break-instruktion, og det var forklaringen på, hvorfor jeg kunne hive den ned med en OutOfMemoryException.
Men det forklarede jo ikke, hvorfor min kollega, der oprindelig havde rapporteret dette problem, så denne opførsel. Jeg blev dog nødt til at afklare, hvorvidt han eventuelt skulle have pillet ved denne eksotiske setting (en søgning giver ikke mange hits, så jeg regnede ikke med, at han var faldet over den ved et tilfælde, men jeg kunne jo lige så godt spørge). Til min overraskelse viste det sig, at han faktisk havde sat GCBreakOnOOM! Under min orlov havde han været forbi min plads og var faldet over Hewardts bog, som han havde lånt. Ved et tilfælde havde han læst om OutOfMemoryExceptions, set den omtalte setting, oprettet den i sit registry og derefter glemt alt om det.
Så hang tingene sammen igen, men hvad er chancerne for, at min kollega og jeg ikke alene begge sætter denne setting men også glemmer alt om det efterfølgende? Jeg er sikker på, at der er en relevant lektie et eller andet sted i denne oplevelse.
Lad mig afrunde dette indlæg med et par noter omkring GCBreakOnOOM.
Som nævnt får denne registry setting, afviklingsmiljøet til at opføre sig specielt i tilfældet af out of memory. Lige så snart CLRen opdager, at den skal til at smide en OutOfMemoryException, indskyder den en break-instruktion. Lad os se på et eksempel.
private static void Main(string[] args) {
GenerateOOM();
}
private static void GenerateOOM() {
var list = new List<double?>(10000000);
while (true) {
list.Add(0);
}
}
Hvis vi kobler WinDbg på efter at have kørt ovenstående, vil vi således ikke se en exception, idet break-instruktionen indskydes inden afviklingsmiljøet smider OutOfMemoryException.
0:000> !threads
ThreadCount: 2
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive Lock
ID OSID ThreadOBJ State GC GC Alloc Context Domain Count APT Exception
0 1 b60 0000000000c63350 a020 Enabled 0000000002941c70:0000000002943a60 0000000000c5a360 0 MTA
2 2 fc4 0000000000c6b420 b220 Enabled 0000000000000000:0000000000000000 0000000000c5a360 0 MTA (Finalizer)
Ingen exception her. Lad os se på vores stak (bemærk desuden, at vi befinder os på den relevante tråd, da vi har indskudt en break-instruktion på denne).
0:000> !clrstack
OS Thread Id: 0xb60 (0)
Child-SP RetAddr Call Site
000000000028e710 000007ff00170336 System.Collections.Generic.List`1[[System.Nullable`1[[System.Double, mscorlib]], mscorlib]].set_Capacity(Int32)
000000000028e760 000007ff001701d2 System.Collections.Generic.List`1[[System.Nullable`1[[System.Double, mscorlib]], mscorlib]].Add(System.Nullable`1<Double>)
000000000028e7a0 000007ff00170129 TestBench.Program.GenerateOOM()
000000000028e800 000007feefa3d502 TestBench.Program.Main(System.String[])
Læg mærke til at set_Capacity ligger øverst på stakken, så det er altså den operation, vi er i gang med. set_Capacity er en hyppig årsag til out of memory. Det er nemlig her, at List<T>s underliggende array bliver udvidet med en ny af dobbelt størrelse, og derfor vil det ofte være den direkte årsag til out of memory. Lad os se om vores native stak giver yderligere detaljer.
0:000> k
Child-SP RetAddr Call Site
00000000`0028e338 000007fe`efc2dd33 KERNELBASE!DebugBreak+0x2
00000000`0028e340 000007fe`efc2dda3 mscorwks!`string'+0x55a93
00000000`0028e3b0 000007fe`ef916df3 mscorwks!`string'+0x55b03
00000000`0028e3e0 000007fe`efe65c79 mscorwks!AllocateArrayEx+0x323
00000000`0028e530 000007ff`00170437 mscorwks!JIT_NewArr1+0x239
00000000`0028e710 000007ff`00170336 0x7ff`00170437
00000000`0028e760 000007ff`001701d2 0x7ff`00170336
00000000`0028e7a0 000007ff`00170129 0x7ff`001701d2
00000000`0028e800 000007fe`efa3d502 0x7ff`00170129
00000000`0028e830 000007fe`ef8f9fd3 mscorwks!CallDescrWorker+0x82
00000000`0028e880 000007fe`ef90a3af mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`0028e920 000007fe`ef87dc7f mscorwks!MethodDesc::CallDescr+0x24f
00000000`0028eb70 000007fe`ef861c74 mscorwks!ClassLoader::RunMain+0x22b
00000000`0028edd0 000007fe`ef899955 mscorwks!Assembly::ExecuteMainMethod+0xbc
00000000`0028f0c0 000007fe`ef9adb07 mscorwks!SystemDomain::ExecuteMainMethod+0x491
00000000`0028f690 000007fe`ef86855c mscorwks!ExecuteEXE+0x47
00000000`0028f6e0 000007fe`f3964989 mscorwks!CorExeMain+0xac
00000000`0028f740 000007fe`f3a05b21 mscoreei!CorExeMain+0x41
00000000`0028f770 00000000`7716f56d MSCOREE!CorExeMain_Exported+0x57
00000000`0028f7a0 00000000`772a3281 KERNEL32!BaseThreadInitThunk+0xd
Ej heller her er der spor af en exception, men vi kan se, at AllocateArrayEx bliver kaldt. Vi er med andre ord kommet ind før CLRen har kastet sin OutOfMemoryException. I debugging-terminologi er dette før first chance exception. Vi har altså alle muligheder for at inspicere tilstanden af applikationen inden the shit hits the fan så at sige.
Det vil også sige, at hvis vi kører videre, vil vi få den ventede exception.
0:000> g
(484.b60): C++ EH exception - code e06d7363 (first chance)
(484.b60): CLR exception - code e0434f4d (first chance)
(484.b60): CLR exception - code e0434f4d (!!! second chance !!!)
KERNELBASE!RaiseException+0x39:
000007fe`fd49aa7d 4881c4c8000000 add rsp,0C8h
Bingo! Eftersom vi ikke gør noget for at fange exceptions, fortsætter koden med både first og second chance.
Herefter har vi vores exception, og debugging af problemet fra dette punkt svarer til det, vi ville se, hvis vi havde sat Adplus til at lave et crash dump.
0:000> !threads
ThreadCount: 2
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive Lock
ID OSID ThreadOBJ State GC GC Alloc Context Domain Count APT Exception
0 1 b60 0000000000c63350 a020 Enabled 0000000002941e90:0000000002943a60 0000000000c5a360 0 MTA System.OutOfMemoryException (0000000002941c70)
2 2 fc4 0000000000c6b420 b220 Enabled 0000000000000000:0000000000000000 0000000000c5a360 0 MTA (Finalizer)
Som forventet finder vi en OutOfMemoryException på vores hovedtråd:
0:000> !pe
Exception object: 0000000002941c70
Exception type: System.OutOfMemoryException
Message: <none>
InnerException: <none>
StackTrace (generated):
SP IP Function
000000000028E710 000007FF00170438 mscorlib_ni!System.Collections.Generic.List`1[[System.Nullable`1[[System.Double, mscorlib]], mscorlib]].set_Capacity(Int32)+0x48
000000000028E760 000007FF00170337 mscorlib_ni!System.Collections.Generic.List`1[[System.Nullable`1[[System.Double, mscorlib]], mscorlib]].Add(System.Nullable`1<Double>)+0x27
000000000028E7A0 000007FF001701D3 TestBench!TestBench.Program.GenerateOOM()+0x83
000000000028E800 000007FF0017012A TestBench!TestBench.Program.Main(System.String[])+0xa
StackTraceString: <none>
HResult: 8007000e
Kigger vi på native stak, finder vi ligeledes de relevante kald i mscorwks og derefter kernelbase til håndtering af exceptions.
0:000> k
Child-SP RetAddr Call Site
00000000`0028e330 000007fe`ef8cf0bd KERNELBASE!RaiseException+0x39
00000000`0028e400 000007fe`efa1e38f mscorwks!RaiseTheExceptionInternalOnly+0x295
00000000`0028e4d0 000007fe`efe65cca mscorwks!UnwindAndContinueRethrowHelperAfterCatch+0x63
00000000`0028e530 000007ff`00170437 mscorwks!JIT_NewArr1+0x28a
00000000`0028e710 000007ff`00170336 0x7ff`00170437
00000000`0028e760 000007ff`001701d2 0x7ff`00170336
00000000`0028e7a0 000007ff`00170129 0x7ff`001701d2
00000000`0028e800 000007fe`efa3d502 0x7ff`00170129
00000000`0028e830 000007fe`ef8f9fd3 mscorwks!CallDescrWorker+0x82
00000000`0028e880 000007fe`ef90a3af mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`0028e920 000007fe`ef87dc7f mscorwks!MethodDesc::CallDescr+0x24f
00000000`0028eb70 000007fe`ef861c74 mscorwks!ClassLoader::RunMain+0x22b
00000000`0028edd0 000007fe`ef899955 mscorwks!Assembly::ExecuteMainMethod+0xbc
00000000`0028f0c0 000007fe`ef9adb07 mscorwks!SystemDomain::ExecuteMainMethod+0x491
00000000`0028f690 000007fe`ef86855c mscorwks!ExecuteEXE+0x47
00000000`0028f6e0 000007fe`f3964989 mscorwks!CorExeMain+0xac
00000000`0028f740 000007fe`f3a05b21 mscoreei!CorExeMain+0x41
00000000`0028f770 00000000`7716f56d MSCOREE!CorExeMain_Exported+0x57
00000000`0028f7a0 00000000`772a3281 KERNEL32!BaseThreadInitThunk+0xd
00000000`0028f7d0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d