Windbg - SOS 디버깅 사례 System.NullReferenceException 예외 추적
Release 모드로 빌드된 Windows Forms 응용 프로그램 실행 중 별다른 콜스택 정보 없이 예외가 발생했다면서 비정상 종료 메시지만 나오는 상황이었습니다.
메시지 창이 뜬 시점에 프로세스 풀 덤프를 남긴 후 windbg에서 살펴봤습니다.
CLR 2.0이었기 때문에 다음과 같이 sos를 로드하고,
0:000> .loadby sos mscorjit
예외 정보를 확인(!PrintException)하려 했지만,
0:000> !pe
There is no current managed exception on this thread
다른 스레드에서 발생한 듯싶군요. ^^ 그럼, !threads를 이용해 예외가 발생한 스레드를 확인해 보면 됩니다.
0:000> !threads
ThreadCount: 771
UnstartedThread: 0
BackgroundThread: 770
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive Lock
ID OSID ThreadOBJ State GC GC Alloc Context Domain Count APT Exception
0 1 2544 0000000000694bb0 6020 Enabled 0000000003b10b90:0000000003b113c0 000000000068c370 0 STA
2 2 1cac 00000000006a0630 b220 Enabled 0000000000000000:0000000000000000 000000000068c370 0 MTA (Finalizer)
5 4 2e8 000000001b3ec740 b220 Enabled 0000000000000000:0000000000000000 000000000068c370 2 MTA System.NullReferenceException (0000000002a87b58)
6 f 27bc 000000001b41f690 380b220 Enabled 0000000000000000:0000000000000000 000000000068c370 0 MTA (Threadpool Worker)
(Managed 환경 기준으로) 5번 스레드임을 알았으니 문맥 전환을 해주고 다시 예외 정보를 확인합니다.
0:000> ~5s
ntdll!NtWaitForSingleObject+0x14:
00007ff9`82ba6154 c3
0:005> !pe
Exception object: 0000000002a87b58
Exception type: System.NullReferenceException
Message: Object reference not set to an instance of an object.
InnerException: <none>
StackTrace (generated):
SP IP Function
000000001E2CE820 00007FF9128C862B MyTestEXE!MyTestEXE.SampleType.CallMyMethod(MyTestEXE.SampleType, System.Text.StringBuilder)+0x4cb
000000001E2CEBB0 00007FF9128C335D MyTestEXE!MyTestEXE.MainForm.SecondThreadFunc(System.Object)+0x8ad
000000001E2CEF10 00007FF96CEF2C8B mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x9b
000000001E2CEF60 00007FF96D598C6D mscorlib_ni!System.Threading.ThreadHelper.ThreadStart(System.Object)+0x5d
물론, !clrstack 명령을 이용하셔도 됩니다.
0:005> !clrstack
OS Thread Id: 0x2e8 (5)
Child-SP RetAddr Call Site
000000001e2ce820 00007ff9128c335d MyTestEXE.SampleType.CallMyMethod(MyTestEXE.SampleType, System.Text.StringBuilder)
000000001e2cebb0 00007ff96cef2c8b MyTestEXE.MainForm.SecondThreadFunc(System.Object)
000000001e2cef10 00007ff96d598c6d System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000001e2cef60 00007ff972148f32 System.Threading.ThreadHelper.ThreadStart(System.Object)
그런데, 아쉽게도 소스 코드 위치를 알 수가 없습니다. 이런 경우 문제 추적을 위해 도움이 되는 방법이 해당 상황을 재현시켜 보는 것입니다. 즉, 메서드가 수행된 시점에 관련 객체들의 상태 정보와 메서드에 들어온 인자 값들의 상태 정보를 알아내면 높은 확률로 재현할 수 있는 환경을 마련할 수 있습니다. ^^
이를 위해 clrstack 명령에 -a 옵션을 주면 다음과 같이 인자 값(이 코드에서는 current와 log)과 객체(this)의 주소를 알아낼 수 있습니다.
0:005> !clrstack -a
OS Thread Id: 0x2e8 (5)
Child-SP RetAddr Call Site
000000001e2ce820 00007ff9128c335d MyTestEXE.SampleType.CallMyMethod(MyTestEXE.SampleType, System.Text.StringBuilder)
PARAMETERS:
this = 0x00000000029c63f0
current = 0x00000000029f90a8
log = 0x0000000002a87250
LOCALS:
0x000000001e2ce840 = 0x0000000000000000
0x000000001e2ce848 = 0x0000000000000000
0x000000001e2ce850 = 0x0000000000000000
0x000000001e2ce858 = 0x0000000000000000
0x000000001e2ce859 = 0x0000000000000001
0x000000001e2ce860 = 0x0000000000000000
0x000000001e2ce868 = 0x0000000000000000
...[이하 생략]...
첫 번째 인자인 "MyTestEXE.SampleType current" 값을 다음과 같이 확인할 수 있습니다.
0:005> !dumpobj 0x00000000029f90a8
Name: MyTestEXE.SampleType
MethodTable: 00007ff912768818
EEClass: 00007ff912894250
Size: 224(0xe0) bytes
(D:\MyTestEXE\bin\debug\MyTestEXE.exe)
Fields:
MT Field Offset Type VT Attr Value Name
00007ff96d03f130 4000012 90 System.Int32 1 instance 51964 Position
00007ff96d037ec0 4000013 8 System.String 0 instance 00000000029f9188 RawData
00007ff96d025cb0 4000014 10 System.Object[] 0 instance 00000000029f9ef0 Lines
0000000000000000 4000015 18 0 instance 00000000029f9fb8 Values
00007ff96d03f130 4000016 94 System.Int32 1 instance 70 Count
00007ff96d03f130 4000017 98 System.Int32 1 instance 0 Limit
00007ff96d037ec0 4000018 20 System.String 0 instance 000000000386aea8 MachineName
...[이하 생략]...
위의 출력은 SampleType 클래스의 멤버들을 "Value" 값과 함께 보여줍니다. 이 중에서 System.Int32와 같이 기본 자료형인 경우 "Value" 칼럼에 나온 값을 그대로 필드 값이라고 보면 됩니다. 반면 System.String, System.Object[]와 같은 참조형들은 Value에 대해 다시 한번 dumpobj를 호출해 그 객체의 내부 값을 확인해 봐야 합니다.
0:005> !dumpobj 000000000386aea8
Name: System.String
MethodTable: 00007ff96d037ec0
EEClass: 00007ff96cc3e560
Size: 46(0x2e) bytes
(C:\WINDOWS\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: WIN2008X86
Fields:
MT Field Offset Type VT Attr Value Name
00007ff96d03f130 4000096 8 System.Int32 1 instance 11 m_arrayLength
00007ff96d03f130 4000097 c System.Int32 1 instance 10 m_stringLength
00007ff96d039908 4000098 10 System.Char 1 instance 57 m_firstChar
00007ff96d037ec0 4000099 20 System.String 0 shared static Empty
>> Domain:Value 000000000068c370:0000000002931308 <<
00007ff96d0397b8 400009a 28 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 000000000068c370:0000000002931b08 <<
위에서 보는 것처럼, MyTestEXE.SampleType의 MachineName 필드의 값은 "WIN2008X86"이었음을 알 수 있습니다.
운이 좋다면, 문제가 발생한 환경을 재현하는 데 성공할 것입니다. 이 방법은 간혹, CPU 100% 현상을 보일 때에도 유용하게 써먹을 수 있습니다. 같은 구간을 무한 반복해서 실행하는 코드의 경우, 해당 메서드의 수행 환경만 잘 살펴봐도 왜 그런 현상에 빠졌는지를 유추해 볼 수 있기 때문입니다.
이 외에, !pe 출력의 결과로 나온 offset 값을 통해 System.NullReferenceException 예외가 발생한 코드를 대략적으로 찾아낼 수도 있습니다.
0:005> !pe
Exception object: 0000000002a87b58
Exception type: System.NullReferenceException
Message: Object reference not set to an instance of an object.
InnerException: <none>
StackTrace (generated):
SP IP Function
000000001E2CE820 00007FF9128C862B MyTestEXE!MyTestEXE.SampleType.CallMyMethod(MyTestEXE.SampleType, System.Text.StringBuilder)+0x4cb
000000001E2CEBB0 00007FF9128C335D MyTestEXE!MyTestEXE.MainForm.SecondThreadFunc(System.Object)+0x8ad
000000001E2CEF10 00007FF96CEF2C8B mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x9b
000000001E2CEF60 00007FF96D598C6D mscorlib_ni!System.Threading.ThreadHelper.ThreadStart(System.Object)+0x5d
이에 대해서는 예전 글에서 한번 설명한 적이 있습니다.
Windbg - 비정상 종료된 닷넷 프로그램의 StackTrace에서 보이는 offset 값 의미
; https://www.sysnet.pe.kr/2/0/1095
문제가 발생한 CallMyMethod의 jitted code address를 알아내고,
0:005> !name2ee MyTestEXE!MyTestEXE.SampleType.CallMyMethod
Module: 00007ff912762e38 (MyTestEXE.exe)
Token: 0x0000000006000008
MethodDesc: 00007ff9127687e8
Name: MyTestEXE.SampleType.CallMyMethod(MyTestEXE.SampleType, System.Text.StringBuilder)
JITTED Code Address: 00007ff9128c8160
그 값에 !pe 출력 결과에서 얻은 IP 주소(00007FF9128C862B)와 0x4cb 오프셋 값을 더한 위치(= 7FF9128C8AF6)를 계산하고, 그 위치를 JITTED Code Address 주소를 역어셈블한 코드에서 찾아내면 됩니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]