windbg 분석 사례 - Semaphore 잠금으로 인한 Hang 현상 (닷넷)
지난 글에서,
C# - 최댓값이 1인 SemaphoreSlim 보다 Mutex 또는 lock(obj)를 선택하는 것이 나은 이유
; https://www.sysnet.pe.kr/2/0/13558
Mutex를 사용해 hang 현상이 발생한 경우 어떻게 잠금을 추적할 수 있는지 설명했는데요, 동일한 상황에서 (최댓값이 1인) SemaphoreSlim을 사용했을 때 디버깅이 어떻게 바뀌는지 살펴보겠습니다.
문제의 상황에서 덤프 파일을 뜨면, 가장 먼저 해야 할 것이 바로 "Debug Diagnostics"로 대강의 상황을 파악하는 것입니다.
실제 사례를 통해 Debug Diagnostics 도구가 생성한 닷넷 웹 응용 프로그램의 성능 장애 보고서 설명
; https://www.sysnet.pe.kr/2/0/12067
위의 방법에 따라 닷넷 프로세스를 분석했더니 6개의 스레드가 다음과 같은 호출 스택으로 나왔습니다.
[[GCFrame]]
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.ObjWait)] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
mscorlib_ni!System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout(Int32, UInt32, System.Threading.CancellationToken)+8b
mscorlib_ni!System.Threading.SemaphoreSlim.Wait(Int32, System.Threading.CancellationToken)+151
SuperSimpleTcp.SimpleTcpServer.SendInternal(System.String, Int64, System.IO.Stream)+9e
SuperSimpleTcp.SimpleTcpServer.Send(System.String, Byte[])+a2
...[생략]...
문제는, ^^; 저 hang 상태를 유발한 Semaphore.Wait을 다른 스레드에서 찾을 수 없었다는 점입니다. 이후의 분석은 덤프 파일을 windbg로 열어 추적을 해야 하는데요, 위의 hang 상태에 빠진 스레드 6개 중 1개의 스레드로 문맥을 변경한 다음 "clrstack -a"로 SemaphoreSlim 인스턴스를 얻는 것으로 시작할 수 있습니다.
// DebugDiag로 분석한 스레드 중 1개를 선택, 이 글에서는 "59번 스레드"
0:000> ~59s
ntdll!NtWaitForMultipleObjects+0x14:
00007ffc`f53b59a4 c3 ret
// call stack과 그 스택으로부터 얻을 수 있는 SemaphoreSlim 인스턴스를 알아냄
0:059> !clrstack -a
OS Thread Id: 0x320c (59)
Child SP IP Call Site
000000d03d13e530 00007ffcf53b59a4 [GCFrame: 000000d03d13e530]
000000d03d13e658 00007ffcf53b59a4 [HelperMethodFrame_1OBJ: 000000d03d13e658] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
000000d03d13e770 00007ffce43dac4b System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout(Int32, UInt32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\system\threading\SemaphoreSlim.cs @ 469]
PARAMETERS:
this (<CLR reg>) = 0x0000021f6acc0ff8
millisecondsTimeout (<CLR reg>) = 0x00000000ffffffff
startTime (<CLR reg>) = 0x0000000000000000
cancellationToken = <no data>
...[생략]...
그럼 해당 세마포어 인스턴스의 상태를 볼까요? ^^
0:059> !DumpObj /d 0000021f6acc0ff8
Name: System.Threading.SemaphoreSlim
MethodTable: 00007ffce3506740
EEClass: 00007ffce374bc90
Size: 64(0x40) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ffce34885a0 4001a88 28 System.Int32 1 instance 0 m_currentCount
00007ffce34885a0 4001a89 2c System.Int32 1 instance 1 m_maxCount
00007ffce34885a0 4001a8a 30 System.Int32 1 instance 6 m_waitCount
00007ffce3485dd8 4001a8b 8 System.Object 0 instance 0000000000000000 m_lockObj
00007ffce3504398 4001a8c 10 ....ManualResetEvent 0 instance 0000000000000000 m_waitHandle
00007ffce34d4f38 4001a8d 18 ...horeSlim+TaskNode 0 instance 0000000000000000 m_asyncHead
00007ffce34d4f38 4001a8e 20 ...horeSlim+TaskNode 0 instance 0000000000000000 m_asyncTail
00007ffce34a4ac0 4001a8f 1008 ...olean, mscorlib]] 0 shared static s_trueTask
>> Domain:Value 0000021d6a3b80e0:NotInit 0000021d6a4d3350:0000021d6a9a0058 <<
00007ffce34fa680 4001a91 1010 ...bject, mscorlib]] 0 shared static s_cancellationTokenCanceledEventHandler
>> Domain:Value 0000021d6a3b80e0:NotInit 0000021d6a4d3350:0000021d6a9a00a8 <<
m_maxCount를 통해 Semaphore가 "new SemaphoreSlim(1, 1)" 조건으로 생성된 것임을 짐작게 합니다. 또한, m_currentCount가 0이므로 이미 다른 곳에서 SemaphoreSlim.Wait을 호출해 한 번의 lock 조건을 소진한 상태이고, m_waitCount가 6인 것으로 봐서 해당 lock을 대기하고 있는 곳이 총 6개, 결국 DebugDiag가 분석한 6개의 스레드와 일치하는 결과를 보입니다.
따라서, 6개의 스레드가 동일한 SemaphoreSlim 1개에 걸려 hang 상태가 발생한 것입니다.
여기서 결정적인 문제점 하나가 나오는데요, m_lockObj가 null로 나오는 것에서 이미 저 SemaphoreSlim은 Dispose를 호출한 상태라는 점입니다. 바로
이 문제를 지난 글에서 다뤘던 것입니다.
문제의 덤프 파일을 발생시켰던 응용 프로그램은 call stack에도 나오듯이 SuperSimpleTcp를 사용한 경우였습니다.
C# - SuperSimpleTcp 사용 시 주의할 점
; https://www.sysnet.pe.kr/2/0/13532
SimpleTcpServer.cs 파일의 SendInternal에 보면 이런 코드가 나옵니다.
private void SendInternal(string ipPort, long contentLength, Stream stream)
{
if (!_clients.TryGetValue(ipPort, out ClientMetadata client)) return;
if (client == null) return;
long bytesRemaining = contentLength;
int bytesRead = 0;
byte[] buffer = new byte[_settings.StreamBufferSize];
try
{
client.SendLock.Wait();
while (bytesRemaining > 0)
{
bytesRead = stream.Read(buffer, 0, buffer.Length);
if (bytesRead > 0)
{
if (!_ssl) client.NetworkStream.Write(buffer, 0, bytesRead);
else client.SslStream.Write(buffer, 0, bytesRead);
bytesRemaining -= bytesRead;
_statistics.SentBytes += bytesRead;
}
}
if (!_ssl) client.NetworkStream.Flush();
else client.SslStream.Flush();
_events.HandleDataSent(this, new DataSentEventArgs(ipPort, contentLength));
}
finally
{
if (client != null) client.SendLock.Release();
}
}
try/finally를 했기 때문에 쌍이 잘 맞습니다. 문제는, DisconnectClient 코드에서 나옵니다.
public void DisconnectClient(string ipPort)
{
if (string.IsNullOrEmpty(ipPort)) throw new ArgumentNullException(nameof(ipPort));
if (!_clients.TryGetValue(ipPort, out ClientMetadata client))
{
Logger?.Invoke($"{_header}unable to find client: {ipPort}");
}
else
{
if (!_clientsTimedout.ContainsKey(ipPort))
{
Logger?.Invoke($"{_header}kicking: {ipPort}");
_clientsKicked.TryAdd(ipPort, DateTime.Now);
}
}
if (client != null)
{
if (!client.TokenSource.IsCancellationRequested)
{
client.TokenSource.Cancel();
Logger?.Invoke($"{_header}requesting disposal of: {ipPort}");
}
client.Dispose();
}
}
ClientMetaData.cs에 정의된 client 인스턴스의 Dispose 메서드를 보면,
public void Dispose()
{
if (TokenSource != null)
{
if (!TokenSource.IsCancellationRequested)
{
TokenSource.Cancel();
TokenSource.Dispose();
}
}
if (_sslStream != null)
{
_sslStream.Close();
}
if (_networkStream != null)
{
_networkStream.Close();
}
if (_tcpClient != null)
{
_tcpClient.Close();
_tcpClient.Dispose();
}
SendLock.Dispose();
ReceiveLock.Dispose();
}
단순히 SendLock.Dispose() 호출만을 하고 있습니다. 즉, (
이전에 설명한 대로) 다른 SendInternal에서 Wait하고 있는 스레드들은 영원히 hang 상태에 빠져든 체로, 일종의 메모리 leak을 유발하게 되는 것입니다.
SuperSimpleTcp가 생성한 SemaphoreSlim은,
internal SemaphoreSlim SendLock = new SemaphoreSlim(1, 1);
internal SemaphoreSlim ReceiveLock = new SemaphoreSlim(1, 1);
lock(obj), Mutex 역할과 동일합니다. 하지만 그래도 SemaphoreSlim을 사용할 수밖에 없는 이유는 SendInternalAsync와 같은 비동기 함수를 제공하고 있기 때문인데요, 예전 글에 설명했던 대로,
C# - Mutex의 비동기 버전
; https://www.sysnet.pe.kr/2/0/13157
Mutex의 경우 비동기 구현을 하려면 결국 동기 방식의 스레드를 쓰거나 아니면 SemaphoreSlim으로 우회해야 합니다. (또한, lock, 즉 Monitor.Enter/Exit은 비동기 구문을 지원하지 않습니다.)
결국 비동기로 인해 SemaphoreSlim를 쓸 수밖에 없었던 것입니다. 만약, 비동기를 포기한다면 SendInternalAsync를 사용하지 않고 오직 SendInternal만 사용한다면 SemaphoreSlim 대신 lock을 사용하는 것이 문제를 그나마 쉽게 해결할 수 있습니다.
private void SendInternal(string ipPort, long contentLength, Stream stream)
{
if (!_clients.TryGetValue(ipPort, out ClientMetadata client)) return;
if (client == null) return;
long bytesRemaining = contentLength;
int bytesRead = 0;
byte[] buffer = new byte[_settings.StreamBufferSize];
bool lockTaken = false;
try
{
// client.SendLock.Wait();
Monitor.Enter(client.SendLock, ref lockTaken);
while (bytesRemaining > 0)
{
bytesRead = stream.Read(buffer, 0, buffer.Length);
if (bytesRead > 0)
{
if (!_ssl) client.NetworkStream.Write(buffer, 0, bytesRead);
else client.SslStream.Write(buffer, 0, bytesRead);
bytesRemaining -= bytesRead;
_statistics.SentBytes += bytesRead;
}
}
if (!_ssl) client.NetworkStream.Flush();
else client.SslStream.Flush();
_events.HandleDataSent(this, new DataSentEventArgs(ipPort, contentLength));
}
finally
{
if (lockTaken)
{
Monitor.Exit(client.SendLock);
}
// if (client != null) client.SendLock.Release();
}
}
이와 함께, 혹시라도 SendInternalAsync를 사용할 수도 있으므로 비동기 관련 메서드들은 모두 private 처리하는 것이 좋습니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]