Microsoft MVP성태의 닷넷 이야기
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일
 

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)
11576정성태7/3/20182919Math: 29. GeoGebra 기하 (6) - 대수의 4칙 연산파일 다운로드1
11575정성태7/2/20183490Math: 28. GeoGebra 기하 (5) - 선분을 n 등분하는 방법파일 다운로드1
11574정성태7/2/20182843Math: 27. GeoGebra 기하 (4) - 선분을 n 배 늘이는 방법파일 다운로드1
11573정성태7/2/20182685Math: 26. GeoGebra 기하 (3) - 평행선
11572정성태7/1/20182391.NET Framework: 783. C# 컴파일러가 허용하지 않는 (유효한) 코드를 컴파일해 테스트하는 방법
11571정성태7/1/20182543.NET Framework: 782. C# - JIRA에 등록된 Project의 Version 항목 추가하는 방법파일 다운로드1
11570정성태7/2/20183793Math: 25. GeoGebra 기하 (2) - 임의의 선분과 특정 점을 지나는 수직선파일 다운로드1
11569정성태7/1/20183243Math: 24. GeoGebra 기하 (1) - 수직 이등분선파일 다운로드1
11568정성태7/12/20186584Math: 23. GeoGebra 기하 - 컴퍼스와 자를 이용한 작도 프로그램 [1]
11567정성태6/28/20182983.NET Framework: 781. C# - OpenCvSharp 사용 시 포인터를 이용한 속도 향상파일 다운로드1
11566정성태6/28/20185885.NET Framework: 780. C# - JIRA REST API 사용 정리 [4]파일 다운로드1
11565정성태6/28/20183202.NET Framework: 779. C# 7.3에서 enum을 boxing 없이 int 변환하기 - 세 번째 이야기파일 다운로드1
11564정성태6/27/20183303.NET Framework: 778. (Unity가 사용하는) 모노 런타임의 __makeref 오류
11563정성태6/27/20182919개발 환경 구성: 386. .NET Framework Native compiler 프리뷰 버전 사용법
11562정성태6/26/20182554개발 환경 구성: 385. 레지스트리에 등록된 원격지 스크립트 COM 객체 실행 방법
11561정성태6/26/20185562.NET Framework: 777. UI 요소의 접근은 반드시 그 UI를 만든 스레드에서! [3]파일 다운로드1
11560정성태3/2/20192500.NET Framework: 776. C# 7.3 - 초기화 식에서 변수 사용 가능(expression variables in initializers)파일 다운로드1
11559정성태1/27/20206016개발 환경 구성: 384. 영문 설정의 Windows 10 명령행 창(cmd.exe)의 한글 지원 [4]
11558정성태6/25/20183072.NET Framework: 775. C# 7.3 - unmanaged(blittable) 제네릭 제약파일 다운로드1
11557정성태6/22/20183638.NET Framework: 774. C# - blittable 타입이란?파일 다운로드1
11556정성태6/25/20186524.NET Framework: 773. C# 7.3 - 구조체의 고정 크기를 갖는 fixed 배열 필드에 대한 직접 접근 가능 [1]파일 다운로드1
11555정성태6/25/20183008.NET Framework: 772. C# 7.3 - 사용자 정의 타입에 fixed 적용 가능(Custom fixed)파일 다운로드1
11554정성태6/25/20183002.NET Framework: 771. C# 7.3 - 자동 구현 속성에 특성 적용 가능(Attribute on backing field)
11553정성태6/25/20183485.NET Framework: 770. C# 7.3 - 개선된 메서드 선택 규칙 3가지(Improved overload candidates)파일 다운로드1
11552정성태6/25/20183492.NET Framework: 769. C# 7.3에서 개선된 문법 4개(Support == and != for tuples, Ref Reassignment, Constraints, Stackalloc initializers)파일 다운로드1
11551정성태6/14/20182243개발 환경 구성: 383. BenchmarkDotNet 사용 시 주의 사항
... 31  32  33  34  [35]  36  37  38  39  40  41  42  43  44  45  ...