Microsoft MVP성태의 닷넷 이야기
오류 유형: 408. SqlConnection 객체 생성 시 무한 대기 문제 [링크 복사], [링크+제목 복사],
조회: 21152
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일

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일 것입니다.

(그런데, 해당 문제가 한 달에 한번 정도 간헐적으로 발생한다고 하니... 원인 찾기가 그리 녹록치는 않을 것 같습니다. ^^)




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







[최초 등록일: ]
[최종 수정일: 11/5/2022]

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

비밀번호

댓글 작성자
 




... 91  92  93  94  95  96  97  [98]  99  100  101  102  103  104  105  ...
NoWriterDateCnt.TitleFile(s)
11521정성태5/15/201819139개발 환경 구성: 377. Azure - 원하는 성능 데이터로 모니터링 대시보드 구성
11520정성태5/12/201821344.NET Framework: 748. C# 7.1 - 참조 어셈블리(Ref Assemblies)
11519정성태5/12/201823293개발 환경 구성: 376. ASP.NET Web Application 프로젝트의 FileSystem 배포(Publish) 시 Before/After Task 설정 방법 [1]
11518정성태5/10/201821473.NET Framework: 747. C# 7.0에서도 부분적으로 가능해진 "타입 추론을 통한 튜플의 변수명 자동 지정"
11517정성태5/10/201819721.NET Framework: 746. Azure runbook 예제 - 6시간 동안 수행 중인 VM을 중지 [1]파일 다운로드1
11516정성태5/9/201820561.NET Framework: 745. Azure runbook을 PowerShell 또는 C# 코드로 실행하는 방법파일 다운로드1
11515정성태5/9/201823137.NET Framework: 744. C# 6 - Expression bodied function [1]
11514정성태5/3/201821050오류 유형: 466. Bitvise - Error in component session/transport/kexHandler [2]
11513정성태5/3/201828235.NET Framework: 743. C# 언어의 공변성과 반공변성 [9]파일 다운로드2
11512정성태5/2/201820388개발 환경 구성: 375. Azure runbook 실행 시 "Errors", "All Logs"에 오류 메시지가 출력되는 경우
11511정성태5/2/201821784개발 환경 구성: 374. Azure - Runbook 기능 소개
11510정성태4/30/201822606.NET Framework: 742. windbg로 확인하는 Finalizer를 가진 객체의 GC 과정파일 다운로드1
11509정성태4/28/201820891.NET Framework: 741. windbg로 확인하는 객체의 GC 여부
11508정성태4/23/201822544개발 환경 구성: 373. MSBuild를 이용해 프로젝트 배포 후 결과물을 zip 파일로 압축하는 방법파일 다운로드1
11507정성태4/20/201823253개발 환경 구성: 372. MSBuild - 빌드 전/후, 배포 전/후 실행하고 싶은 Task 정의
11506정성태4/20/201827595.NET Framework: 740. C#에서 enum을 boxing 없이 int로 변환하기 - 두 번째 이야기 [7]파일 다운로드1
11505정성태4/19/201820453개발 환경 구성: 371. Azure Web App 확장 예제 - Simple WebSite Extension
11504정성태4/19/201821966오류 유형: 465. Azure Web App 확장 - Extplorer File manager 적용 시 오류
11503정성태4/19/201820816오류 유형: 464. PowerShell - Start-Service 명령 오류 (Service 'xxx' cannot be started)
11502정성태4/17/201823153개발 환경 구성: 370. Azure VM/App Services(Web Apps)에 Let's Encrypt 무료 인증서 적용 방법 [3]
11501정성태4/17/201820613개발 환경 구성: 369. New-AzureRmADServicePrincipal로 생성한 계정의 clientSecret, key 값을 구하는 방법파일 다운로드1
11500정성태4/17/201821497개발 환경 구성: 368. PowerShell로 접근하는 Azure의 Access control 보안과 Azure Active Directory의 계정 관리 서비스
11499정성태4/17/201820118개발 환경 구성: 367. Azure - New-AzureRmADServicePrincipal / New-AzureRmRoleAssignment 명령어
11498정성태4/17/201820126개발 환경 구성: 366. Azure Active Directory(Microsoft Enfra ID)의 사용자 유형 구분 - Guest/Member
11497정성태4/17/201817855개발 환경 구성: 365. Azure 리소스의 액세스 제어(Access control) 별로 사용자에게 권한을 할당하는 방법 [2]
11496정성태4/17/201818422개발 환경 구성: 364. Azure Portal에서 구독(Subscriptions) 메뉴가 보이지 않는 경우
... 91  92  93  94  95  96  97  [98]  99  100  101  102  103  104  105  ...