SqlConnection 객체 생성 시 무한 대기 문제
고객사 닷넷 프로그램이 어느 순간부터 무한 대기 상태에 빠지며 종료가 안 된다는 보고가 왔습니다.
해당 프로그램을 개발한 측에서 나름 분석을 시도하며 프로세스 덤프도 뜨고 DebugDiag 분석을 돌린 것도 함께 보내주었는데요. 무한 대기의 원인은 다음과 같이 SqlConnection.Open에서 Mutex 획득을 시도했기 때문입니다.
[Managed to Native Transition]
System.dll!System.Diagnostics.SharedUtils.SafeWaitForMutexOnce(System.Threading.Mutex mutexIn, ref System.Threading.Mutex mutexOut) Line 263 C#
System.dll!System.Diagnostics.SharedUtils.SafeWaitForMutex(System.Threading.Mutex mutexIn, ref System.Threading.Mutex mutexOut) Line 240 C#
System.dll!System.Diagnostics.SharedUtils.EnterMutexWithoutGlobal(string mutexName, ref System.Threading.Mutex mutex) Line 88 C#
System.dll!System.Diagnostics.SharedPerformanceCounter.GetCounter(string counterName, string instanceName, bool enableReuse, System.Diagnostics.PerformanceCounterInstanceLifetime lifetime) Line 715 C#
System.dll!System.Diagnostics.SharedPerformanceCounter.SharedPerformanceCounter(string catName, string counterName, string instanceName, System.Diagnostics.PerformanceCounterInstanceLifetime lifetime) Line 68 C#
System.dll!System.Diagnostics.PerformanceCounter.InitializeImpl() Line 247 C#
System.dll!System.Diagnostics.PerformanceCounter.RawValue.set(long value) Line 478 C#
System.Data.dll!System.Data.ProviderBase.DbConnectionPoolCounters.Counter.Counter(string categoryName, string instanceName, string counterName, System.Diagnostics.PerformanceCounterType counterType) Unknown
System.Data.dll!System.Data.ProviderBase.DbConnectionPoolCounters.DbConnectionPoolCounters(string categoryName, string categoryHelp) Unknown
System.Data.dll!System.Data.SqlClient.SqlPerformanceCounters.SqlPerformanceCounters() Unknown
System.Data.dll!System.Data.SqlClient.SqlPerformanceCounters.SqlPerformanceCounters() Unknown
[Native to Managed Transition]
[Managed to Native Transition]
System.Data.dll!System.Data.SqlClient.SqlConnectionFactory.SqlConnectionFactory() Unknown
[Native to Managed Transition]
[Managed to Native Transition]
System.Data.dll!System.Data.SqlClient.SqlConnection.SqlConnection() Unknown
[Native to Managed Transition]
[Managed to Native Transition]
System.Data.dll!System.Data.SqlClient.SqlConnection.SqlConnection() Unknown
ConsoleApplication1.exe!ConsoleApplication1.Program.Main(string[] args) Line 22 C#
상황은 간단합니다. SqlConnection 생성자부터 .NET Reflector 등을 이용해 코드를 확인해 보면, 내부적으로 성능 카운터(Performance Counter)를 초기화하는데 그 과정에서 시스템 전역적인 Mutex로 동기화가 이뤄지는 것입니다. 이런 경우 mutex 이름만 알아내면 이것을 재현해 볼 수 있는데, 역시 .NET Reflector 등을 이용해 조사하면 ".net data provider for sqlserver"라는 이름임을 알 수 있습니다.
따라서, 재현을 위해 다음과 같이 스레드 하나에서 Mutex를 열고, 다른 스레드에서는 SqlConnection 객체를 생성해 보면 됩니다.
using System;
using System.Data.SqlClient;
using System.Security.AccessControl;
using System.Security.Principal;
using System.Threading;
class Program
{
static EventWaitHandle _ewh = new EventWaitHandle(false, EventResetMode.ManualReset);
static void Main(string[] args)
{
Thread t1 = new Thread(threadFunc);
t1.Start();
_ewh.WaitOne();
Console.WriteLine("Opening DB Connection...");
SqlConnection con = new SqlConnection(); // SqlConnection 객체 생성
Console.WriteLine("Opened");
}
private static void threadFunc()
{
string mutexName = "Global\\.net data provider for sqlserver";
bool flag;
MutexSecurity mutexSecurity = new MutexSecurity();
SecurityIdentifier identity = new SecurityIdentifier(WellKnownSidType.AuthenticatedUserSid, null);
mutexSecurity.AddAccessRule(new MutexAccessRule(identity, MutexRights.Synchronize | MutexRights.Modify, AccessControlType.Allow));
using (Mutex mutex = new Mutex(false, mutexName, out flag, mutexSecurity))
{
Console.WriteLine("Enter of MUTEX");
mutex.WaitOne();
_ewh.Set();
Thread.Sleep(-1); // mutex 해제 없이 무한 대기
mutex.ReleaseMutex();
}
Console.WriteLine("Exit of MUTEX");
}
}
이 프로그램을 실행한 화면 출력은,
Enter of MUTEX
Opening DB Connection...
"Global\\.net data provider for sqlserver" 이름의 mutex가 해제되지 않는 것으로 인해 SqlConnection 생성자가 수행이 완료되지 않고 있는 것을 보여줍니다.
정리해 보면, 고객사의 경우 어떤 식으로든 해당 mutex를 열고 있는 프로그램이 있다는 이야기가 됩니다.
(
첨부 파일은 이 글의 예제 코드를 포함합니다.)
그런데, 왜? 이런 일이 발생했을까요? 100% 장담할 수는 없지만, 최근 그 고객사는 DB 관련 모니터링 프로그램을 설치했다는 차이만 있었습니다. 물론, 그 프로그램 때문이라고 어설프게 말해서는 안 됩니다. ^^
이런 상황에서 정확한 원인을 식별하려면, 해당 문제가 발생했을 때 Sysinternals의 handle.exe 프로그램을 사용해서 확인할 수 있습니다.
sysinternals - handle.exe
; https://learn.microsoft.com/en-us/sysinternals/downloads/handle
대략 다음과 같은 식으로 실행해서 그 순간에 열린 모든 프로세스 별 핸들 목록을 보관해 둡니다.
handle.exe -a > report.log
그런 다음 그 파일을 대상으로 검색을 해보면,
findstr /I /c:".net data provider for sqlserver" report.log
출력 결과는 대충 이렇습니다.
145C: Key HKLM\SYSTEM\ControlSet001\Services\.NET Data Provider for SqlServer\Performance
1460: Mutant \Sessions\1\BaseNamedObjects\.NET Data Provider for SqlServer_Perf_Library_Lock_PID_41c8
2B68: Section \BaseNamedObjects\netfxcustomperfcounters.1.0.net data provider for sqlserver
2B4: Mutant \BaseNamedObjects\.net data provider for sqlserver
2B8: Section \BaseNamedObjects\netfxcustomperfcounters.1.0.net data provider for sqlserver
2C4: Mutant \BaseNamedObjects\.net data provider for sqlserver
해당 목록에서 "\BaseNamedObjects\.net data provider for sqlserver" 문자열을 포함하고 Mutant로 식별된 핸들을 추리면 2개로 문제가 좁혀집니다.
2B4: Mutant \BaseNamedObjects\.net data provider for sqlserver
2C4: Mutant \BaseNamedObjects\.net data provider for sqlserver
다시 report.log 파일을 열어 위의 핸들을 검색하면 어느 프로세스에 속해 있는지 나옵니다. 그중의 하나는 고객사의 pid일 것이고, 나머지 하나는 문제를 유발한 프로그램의 pid일 것입니다.
(그런데, 해당 문제가 한 달에 한번 정도 간헐적으로 발생한다고 하니... 원인 찾기가 그리 녹록치는 않을 것 같습니다. ^^)
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]