Microsoft MVP성태의 닷넷 이야기
글쓴 사람
홈페이지
첨부 파일
 

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://docs.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.


그러고 보면... 덤프를 통해 많은 것을 알아냈죠? ^^




[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]





[최초 등록일: ]
[최종 수정일: 11/2/2017 ]

Creative Commons License
이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.
by SeongTae Jeong, mailto:techsharer@outlook.com

비밀번호

댓글 쓴 사람
 




... 31  32  33  34  [35]  36  37  38  39  40  41  42  43  44  45  ...
NoWriterDateCnt.TitleFile(s)
11365정성태11/25/20172869오류 유형: 429. 이벤트 로그 - User Policy could not be updated successfully
11364정성태8/9/20183481사물인터넷: 11. Raspberry Pi Zero(OTG)를 다른 컴퓨터에 연결해 가상 마우스로 쓰는 방법 (절대 좌표) [2]
11363정성태8/9/20183981사물인터넷: 10. Raspberry Pi Zero(OTG)를 다른 컴퓨터에 연결해 가상 마우스 + 키보드로 쓰는 방법 (두 번째 이야기)
11362정성태12/26/20194473오류 유형: 428. 윈도우 업데이트 KB4048953 - 0x800705b4 [2]
11361정성태11/22/20174299오류 유형: 427. 이벤트 로그 - Filter Manager failed to attach to volume '\Device\HarddiskVolume??' 0xC03A001C
11360정성태11/22/20175652오류 유형: 426. 이벤트 로그 - The kernel power manager has initiated a shutdown transition.
11359정성태11/16/20175772오류 유형: 425. 윈도우 10 Version 1709 (OS Build 16299.64) 업그레이드 시 발생한 문제 2가지
11358정성태8/9/20186963사물인터넷: 9. Visual Studio 2017에서 Raspberry Pi C++ 응용 프로그램 제작 [1]
11357정성태11/15/20176182개발 환경 구성: 336. 윈도우 10 Bash 쉘에서 C++ 컴파일하는 방법
11356정성태5/13/20207482사물인터넷: 8. Raspberry Pi Zero(OTG)를 다른 컴퓨터에 연결해 가상 마우스 + 키보드로 쓰는 방법 [3]
11355정성태4/27/20205322사물인터넷: 7. Raspberry Pi Zero(OTG)를 다른 컴퓨터에 연결해 가상 마우스로 쓰는 방법 [2]파일 다운로드2
11354정성태8/9/20186876사물인터넷: 6. Raspberry Pi Zero(OTG)를 다른 컴퓨터에 연결해 가상 키보드로 쓰는 방법 [4]
11353정성태8/9/20186048사물인터넷: 5. Raspberry Pi Zero(OTG)를 다른 컴퓨터에 연결해 가상 이더넷 카드로 쓰는 방법 [1]
11352정성태8/9/20184073사물인터넷: 4. Samba를 이용해 윈도우와 Raspberry Pi간의 파일 교환 [1]
11351정성태12/22/20174984.NET Framework: 698. C# 컴파일러 대신 직접 구현하는 비동기(async/await) 코드파일 다운로드1
11350정성태11/1/20173497디버깅 기술: 108. windbg 분석 사례 - Redis 서버로의 호출을 기다리면서 hang 현상 발생
11349정성태10/31/20173664디버깅 기술: 107. windbg - x64 SOS 확장의 !clrstack 명령어가 출력하는 Child SP 값의 의미
11348정성태10/31/20173877디버깅 기술: 106. windbg - x64 역어셈블 코드에서 닷넷 메서드 호출의 인자를 확인하는 방법
11347정성태10/28/20176007오류 유형: 424. Visual Studio - "클래스 다이어그램 보기" 시 "작업을 완료할 수 없습니다. 해당 인터페이스를 지원하지 않습니다." 오류 발생
11346정성태10/25/20172992오류 유형: 423. Windows Server 2003 - The client-side extension could not remove user policy settings for 'Default Domain Policy {...}' (0x8007000d)
11338정성태10/25/20173409.NET Framework: 697. windbg - SOS DumpMT의 "BaseSize", "ComponentSize" 값에 대한 의미파일 다운로드1
11337정성태10/24/20173250.NET Framework: 696. windbg - SOS DumpClass/DumpMT의 "Vtable Slots", "Total Method Slots", "Slots in VTable" 값에 대한 의미파일 다운로드1
11336정성태10/20/20173503.NET Framework: 695. windbg - .NET string의 x86/x64 메모리 할당 구조
11335정성태10/18/20173884.NET Framework: 694. 닷넷 - <Module> 클래스의 용도
11334정성태10/18/20173588디버깅 기술: 105. windbg - k 명령어와 !clrstack을 조합한 호출 스택을 얻는 방법
11333정성태10/17/20174128오류 유형: 422. 윈도우 업데이트 - Code 9C48 Windows update encountered an unknown error.
... 31  32  33  34  [35]  36  37  38  39  40  41  42  43  44  45  ...