windbg 분석 사례 - Redis 서버로의 호출을 기다리면서 hang 현상 발생
덤프 파일이 하나 왔습니다. ^^
우선, 간편하게 "DebugDiag Analysis"로 분석 결과를 뽑았더니 hang 현상에 맞게 1,000개가 넘는 스레드가 41번 스레드에서 이미 획득한 lock을 대기하고 있다고 알려줍니다.
The following threads in test_app.dmp are waiting to enter a .NET Lock
( 35 36 37 38 39 40 42 43 52 53 54 55 ...[생략]... 1081 )
93.54% of threads blocked (1014 threads)
Look at the callstack of thread 41 to see why that thread id waiting on and why it is not releasing the lock.
명령어 연습 겸, 정말 그런지 확인해 보겠습니다.
대기 스레드 중 아무거나 하나 선택해서 스레드 문맥 전환 후 콜스택을 보겠습니다.
0:0001> ~1081s
0:1081> !clrstack
OS Thread Id: 0x1a18 (1081)
Child SP IP Call Site
000000004108b2d8 0000000077c1c2ea [GCFrame: 000000004108b2d8]
000000004108b4d0 0000000077c1c2ea [GCFrame: 000000004108b4d0]
000000004108b508 0000000077c1c2ea [HelperMethodFrame: 000000004108b508] System.Threading.Monitor.Enter(System.Object)
000000004108b600 000007fe9b683e74 TestApp.MyService.MyMethod()
000000004108b948 000007fef96f9e03 [HelperMethodFrame_2OBJ: 000000004108b948] System.Runtime.Remoting.Messaging.Message.Dispatch(System.Object)
000000004108baa0 000007fe9a5dfc53 System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage)
...[생략]...
000000004108e170 000007fe9ad481ab DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)
000000004108e240 000007fe9ad35b8e System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
000000004108e3c0 000007fe9ad35502 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
000000004108e410 000007fe9ad34d61 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)
000000004108e658 000007fef9712403 [ContextTransitionFrame: 000000004108e658]
정말 최상위 메서드가 Monitor.Enter인 걸로 봐서 대기 스레드가 맞습니다. 그럼 예전에 설명했던 방법에 따라,
windbg - C# Monitor Lock을 획득하고 있는 스레드 찾는 방법
; https://www.sysnet.pe.kr/2/0/11268
우선 현재 열려있는 동기화 목록을 구합니다.
0:1081> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
1 000000000d8940f8 1 1 000000003b7dc3e0 17fc 1065 00000002ffc23028 TestApp.TestGlobal
27 0000000011717498 1 1 000000003b922510 22f0 1073 00000000ff9e47d0 TestApp.TestGlobal
55 0000000011717038 1 1 000000003b7d75c0 fa4 1054 00000002bfb4c5b8 TestApp.TestGlobal
84 0000000011715748 2029 1 00000000110c32a0 2154 41 000000023f5d82e0 System.RuntimeType
97 0000000011717858 1 1 000000003b921d40 22fc 1072 00000003bfc3b418 TestApp.TestGlobal
158 00000000117205c8 1 1 000000003b7dbc10 22e0 1064 000000027fbb3bf0 TestApp.TestGlobal
162 0000000011717128 1 1 000000003b921570 243c 1071 00000000ff9d8720 TestApp.TestGlobal
...[생략]...
371 000000001171e1e8 1 1 000000003b922ce0 1654 1074 00000000ff9f9ea0 TestApp.TestGlobal
376 000000001171f018 1 1 000000003b924c20 1538 1078 000000037fc6d158 TestApp.TestGlobal
407 000000000d894238 1 1 000000003b9234b0 170c 1075 00000002bfb63cf0 TestApp.TestGlobal
-----------------------------
Total 409
CCW 3
RCW 5
ComClassFactory 1
Free 110
한눈에 봐도 84번 인덱스의 SyncBlock이 문제로 보이는데요, 개별 값의 의미는 다음과 같습니다.
Index 84
SyncBlock 0000000011715748
MonitorHeld 2029
Recursion 1
Owning Thread Info 00000000110c32a0
Owner native ThreadID 2154
Owner thread index 41
SyncBlock Type Instance 000000023f5d82e0
SyncBlock Type Name System.RuntimeType
근데 왜 MonitorHeld가 2029일까요? 우선 소유자 lock = 1이니 2028일 듯 싶고, 이것을 반으로 나눈다면 정확히 1,014개가 됩니다. 대기 스레드의 수와 일치하는군요. 따라서 "DebugDiag Analysis"의 분석 결과를 신뢰할 수 있습니다. ^^
자, 그럼 k 명령어로 clr!CLREventBase::WaitEx 함수의 첫 번째 인자에 기록된 값과 syncblk으로 확인한 0000000011715748 잠금 값이 일치하는지 보겠습니다.
0:1081> kv
# Child-SP RetAddr : Args to Child : Call Site
00 00000000`4108ae58 000007fe`fdc11430 : 00000000`13a4fcb0 00000000`00000004 00000000`4108be00 00000000`00000010 : ntdll!NtWaitForMultipleObjects+0xa
01 00000000`4108ae60 00000000`779d16e3 : 00000000`4108af98 00000000`4108af90 00000000`00000000 000007fe`f97a0b08 : KERNELBASE!WaitForMultipleObjectsEx+0xe8
02 00000000`4108af60 000007fe`f9864902 : 00000000`ffffffff 00000000`11715760 00000000`4108b2d8 00000000`00000001 : kernel32!WaitForMultipleObjectsExImplementation+0xb3
03 00000000`4108aff0 000007fe`f98647b7 : 00000000`00000001 00000000`11715760 00000000`00000000 00000000`11715760 : clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x62
04 00000000`4108b050 000007fe`f9864646 : 00000000`00000001 00000000`4108b129 00000000`00000001 00000000`ffffffff : clr!Thread::DoAppropriateAptStateWait+0x53
05 00000000`4108b090 000007fe`f986449d : 00000000`00000000 00000000`00000001 00000000`11715760 00000000`00000000 : clr!Thread::DoAppropriateWaitWorker+0x186
06 00000000`4108b180 000007fe`f9864737 : 00000000`4108b818 00000000`00000001 00000000`00000001 00000000`00000000 : clr!Thread::DoAppropriateWait+0x7d
07 00000000`4108b200 000007fe`f9885c9e : 00000000`11715748 00000000`ffffffff 00000000`00000000 00000000`3b925bc0 : clr!CLREventBase::WaitEx+0xc0
...[생략]...
함수의 인자 값(00000000`11715748)과 syncblk의 값(0000000011715748)이 정확히 일치합니다.
자, 그럼 lock을 소유하고 있는 문제의 스레드로 가보겠습니다.
0:1081> ~41s
0:041> !clrstack
OS Thread Id: 0x2154 (41)
Child SP IP Call Site
00000000123bbaa8 0000000077c1c07a [HelperMethodFrame: 00000000123bbaa8] System.Threading.Thread.SleepInternal(Int32)
00000000123bbb90 000007fe9b32e5d0 MyLibrary.RedisWrapper.Open()
00000000123bbe70 000007fe9b32da12 TestApp.MyService.MyMethod()
...[생략]...
RedisWrapper 타입의 Open 메서드에서 Sleep 메서드가 호출되고 있는 것입니다. 혹시 Thread.Sleep(-1)을 호출한 것일까요? 확인을 위해 RedisWrapper 타입을 구현한 모듈을 다음과 같이 찾아낼 수 있습니다.
0:041> !name2ee *!MyLibrary.RedisWrapper
...[생략]...
--------------------------------------
Module: 000007fe9a7cd110
Assembly: MyLibrary.dll
Token: 0000000002000029
MethodTable: 000007fe9b448d08
EEClass: 000007fe9b4640f8
Name: MyLibrary.RedisWrapper
--------------------------------------
...[생략]...
다음의 글에 따라 DLL을 추출하고,
windbg - 풀 덤프 파일로부터 .NET DLL을 추출/저장하는 방법
; https://www.sysnet.pe.kr/2/0/10943
.NET Reflector를 통해 확인해 보니 RedisWrapper.Open 메서드가 다음과 같이 구현하고 있습니다.
Socket socket = ...;
sockt.Connect(host, port);
byte [] buffer = Encoding.UTF8.GetBytes(redisDatabase);
socket.Send(buffer, buffer.Length, SocketFlags.None);
while (item.Available == 0)
{
Thread.Sleep(1);
}
즉, Socket.Send까지는 정상적으로 했는데 Receive를 하기 위해 Redis 서버로부터의 응답을 기다리면서 무한 반복 현상이 발생한 것입니다.
따라서 이런 경우 루프를 도는 횟수를 제한하도록 코드를 수정해야만 합니다.
그렇다면 socket.Send로 보낸 문자열을 혹시 알 수 있을까요? 이를 위해 !dso 명령을 실행해 보면 됩니다.
0:041> !dso
OS Thread Id: 0x2154 (41)
RSP/REG Object Name
00000000123BBBC8 000000033f663188 System.Net.Sockets.Socket
00000000123BBBD8 000000033f663188 System.Net.Sockets.Socket
00000000123BBBE8 000000033f663260 System.Net.Sockets.Socket+MultipleAddressConnectAsyncResult
...[생략]...
00000000123BBBF0 000000033f663518 System.String check_msg_redis
00000000123BEFE8 000000033f5f5e80 System.Web.ThreadContext
00000000123BF028 0000000100000000 System.Byte[]
00000000123BF038 000000033f5f4db8 System.Web.HttpContext
00000000123BF040 000000033f5f4160 System.Web.Hosting.IIS7WorkerRequest
00000000123BF070 000000033f5f57d0 System.Web.RootedObjects
대략 눈 짐작으로 "check_msg_redis"인 것을 알 수 있습니다. ("check_msg_redis" 값은 이 글에서 지어낸 것입니다. 실제 Redis 서버와 통신한 덤프의 문자열은 다른 것이었습니다.) 게다가 연결 소켓 정보도 000000033f663188 값을 통해 더 조사할 수 있겠고.
만약 눈 짐작이 안된다면 역어셈블 코드를 봐야 합니다.
0:041> !U /d 000007fe9b32e5d0
Normal JIT generated code
MyLibrary.RedisWrapper.Open()
Begin 000007fe9b32dde0, size b7d
000007fe`9b32dde0 48894c2408 mov qword ptr [rsp+8],rcx
000007fe`9b32dde5 55 push rbp
000007fe`9b32dde6 53 push rbx
000007fe`9b32dde7 4881ecc8020000 sub rsp,2C8h
000007fe`9b32ddee 488d6c2430 lea rbp,[rsp+30h]
000007fe`9b32ddf3 48896500 mov qword ptr [rbp],rsp
000007fe`9b32ddf7 33c0 xor eax,eax
000007fe`9b32ddf9 48894568 mov qword ptr [rbp+68h],rax
000007fe`9b32ddfd 48894560 mov qword ptr [rbp+60h],rax
000007fe`9b32de01 48894558 mov qword ptr [rbp+58h],rax
000007fe`9b32de05 48894548 mov qword ptr [rbp+48h],rax
000007fe`9b32de09 48894540 mov qword ptr [rbp+40h],rax
000007fe`9b32de0d 48894538 mov qword ptr [rbp+38h],rax
000007fe`9b32de11 48894530 mov qword ptr [rbp+30h],rax
000007fe`9b32de15 48894528 mov qword ptr [rbp+28h],rax
000007fe`9b32de19 48894518 mov qword ptr [rbp+18h],rax
000007fe`9b32de1d 48894508 mov qword ptr [rbp+8],rax
...[생략]...
000007fe`9b32e568 488985f0010000 mov qword ptr [rbp+1F0h],rax
000007fe`9b32e56f 488b85f0010000 mov rax,qword ptr [rbp+1F0h]
000007fe`9b32e576 48894538 mov qword ptr [rbp+38h],rax
000007fe`9b32e57a 488b4d38 mov rcx,qword ptr [rbp+38h]
000007fe`9b32e57e e8253f0f00 call 000007fe`9b4224a8 (Encoding.UTF8.GetBytes(System.String), mdToken: 0000000006000025)
000007fe`9b32e583 488985f8010000 mov qword ptr [rbp+1F8h],rax
000007fe`9b32e58a 488b85f8010000 mov rax,qword ptr [rbp+1F8h]
000007fe`9b32e591 48894540 mov qword ptr [rbp+40h],rax
000007fe`9b32e595 4c8b4540 mov r8,qword ptr [rbp+40h]
000007fe`9b32e599 4d8b4008 mov r8,qword ptr [r8+8]
000007fe`9b32e59d 488b4508 mov rax,qword ptr [rbp+8]
000007fe`9b32e5a1 803800 cmp byte ptr [rax],0
000007fe`9b32e5a4 488b4d08 mov rcx,qword ptr [rbp+8]
000007fe`9b32e5a8 4533c9 xor r9d,r9d
000007fe`9b32e5ab 488b5540 mov rdx,qword ptr [rbp+40h]
000007fe`9b32e5af e86cb6c9ff call 000007fe`9afc9c20 (System.Net.Sockets.Socket.Send(Byte[], Int32, System.Net.Sockets.SocketFlags), mdToken: 0000000006002f5f)
000007fe`9b32e5b4 898500020000 mov dword ptr [rbp+200h],eax
000007fe`9b32e5ba 90 nop
000007fe`9b32e5bb 48c7454800000000 mov qword ptr [rbp+48h],0
000007fe`9b32e5c3 eb0d jmp 000007fe`9b32e5d2
000007fe`9b32e5c5 90 nop
000007fe`9b32e5c6 b901000000 mov ecx,1
000007fe`9b32e5cb e81050dbff call 000007fe`9b0e35e0 (System.Threading.Thread.Sleep(Int32), mdToken: 0000000006001738)
>>> 000007fe`9b32e5d0 90 nop
문자열의 정보는 Encoding.UTF8.GetBytes의 첫 번째 인자에 전달되므로 rbp + 38h의 메모리에 있습니다.
rcx = rbp + 38h
그럼 rbp 값을 알아야 하는데 지난 글에 설명한 대로,
windbg - x64 SOS 확장의 !clrstack 명령어가 출력하는 Child SP 값의 의미
; https://www.sysnet.pe.kr/2/0/11349
!clrstack으로부터 구한 Child SP 값과,
MyLibrary.RedisWrapper.Open
Child SP 00000000123bbb90
IP 000007fe9b32e5d0
prologue 코드의 내용에 따라,
000007fe`9b32dde0 48894c2408 mov qword ptr [rsp+8],rcx
000007fe`9b32dde5 55 push rbp
000007fe`9b32dde6 53 push rbx
000007fe`9b32dde7 4881ecc8020000 sub rsp, 2C8h
000007fe`9b32ddee 488d6c2430 lea rbp,[rsp+30h]
000007fe`9b32ddf3 48896500 mov qword ptr [rbp],rsp
다음과 같이 구할 수 있습니다.
0:041> ? 00000000123bbb90 + 30h
Evaluate expression: 305904576 = 00000000`123bbbc0
RBP == 00000000`123bbbc0
0:041> ? 00000000`123bbbc0 + 38h
Evaluate expression: 305904632 = 00000000`123bbbf8
0:041> dq 00000000`123bbbf8 L1
00000000`123bbbf8 00000003`3f663538
0:041> !do 00000003`3f663538
Name: System.String
MethodTable: 000007fe9a0e4660
EEClass: 000007fe9a0c8130
Size: 72(0x48) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: check_msg_redis
Fields:
MT Field Offset Type VT Attr Value Name
000007fe9a09f5e0 40000aa 8 System.Int32 1 instance 16 m_stringLength
000007fe9a09cfa8 40000ab c System.Char 1 instance 2a m_firstChar
000007fe9a0e4660 40000ac 18 System.String 0 shared static Empty
>> Domain:Value 0000000002210ad0:NotInit 000000000e781470:NotInit <<
마지막으로 하나 더 짚어볼 것이 있다면?
syncblk의 결과에 lock의 Owner 타입이 System.RuntimeType로 나옵니다.
0:1081> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
1 000000000d8940f8 1 1 000000003b7dc3e0 17fc 1065 00000002ffc23028 TestApp.TestGlobal
27 0000000011717498 1 1 000000003b922510 22f0 1073 00000000ff9e47d0 TestApp.TestGlobal
55 0000000011717038 1 1 000000003b7d75c0 fa4 1054 00000002bfb4c5b8 TestApp.TestGlobal
84 0000000011715748 2029 1 00000000110c32a0 2154 41 000000023f5d82e0 System.RuntimeType
97 0000000011717858 1 1 000000003b921d40 22fc 1072 00000003bfc3b418 TestApp.TestGlobal
...[생략]...
-----------------------------
Total 409
CCW 3
RCW 5
ComClassFactory 1
Free 110
이게 나올 수 있는 경우가 다음과 같은 식으로 lock을 소유할 때입니다.
lock (typeof(MyType))
{
// ...
}
그리고 마이크로소프트의 경우 이렇게
type에 대한 lock을 걸지 말라는 권고 사항이 있습니다.
Managed Threading Best Practices
; https://learn.microsoft.com/en-us/dotnet/standard/threading/managed-threading-best-practices
Don't use types as lock objects. That is, avoid code such as lock(typeof(X)) in C# or SyncLock(GetType(X)) in Visual Basic, or the use of Monitor.Enter with Type objects. For a given type, there is only one instance of System.Type per application domain. If the type you take a lock on is public, code other than your own can take locks on it, leading to deadlocks. For additional issues, see Reliability Best Practices.
그러고 보면... 덤프를 통해 많은 것을 알아냈죠? ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]