산업용 카메라 제어 앱이 1개월 뒤에 갑자기 떨어질 때(전편) - 핸들 누수의 발견 방법과 장기 가동용 로그 설계

Windows 앱이 장시간 운전 후에 갑자기 떨어질 때, 처음에 메모리 누수를 의심하고 싶어지는 경우는 꽤 많습니다.
다만 실제로는 핸들 누수가 주범이고, 수 주 뒤에 겨우 이차 장애로 표면화되고 있는 케이스도 적지 않습니다.

이번에 소개하는 것은 산업용 카메라를 제어하고 있는 Windows 앱이 약 1개월의 연속 가동 후에 갑자기 떨어지는 사상을 조사한 사례입니다. 구분을 진행한 결과, 원인은 카메라 재접속 주변의 실패 경로에서 일어나고 있던 핸들 누수였습니다.

전편에서는 핸들 누수란 무엇인가, 이 사상을 어떻게 구분했는가, 재발 방지를 위해 어떤 로그를 남겨야 하는가를 정리합니다.
후편에서는 산업용 카메라 제어 앱이 1개월 뒤에 갑자기 떨어질 때(후편) - Application Verifier란 무엇인가와 이상계 테스트 기반의 만드는 방법으로 이상계 테스트 기반의 이야기를 합니다.

고유 명사나 일부의 로그 항목은 감추고 있지만, 사고방식 자체는 Windows의 장치 제어 앱 전반에서 꽤 공통됩니다.

1. 먼저 결론(한마디로)

• 장시간 운전 후에만 떨어지는 제어 앱에서는 Private Bytes뿐만 아니라 Handle Count도 반드시 본다
• 핸들 누수는 통상계가 아니라 timeout / reconnect / 도중 실패 / early return의 경로에 숨기 쉽다
• 실제로 떨어지는 행은 누설한 장소가 아니라 나중에 새로운 핸들을 만들 수 없게 된 장소인 경우가 많다
• 우선 필요한 로그는 operation/session의 문맥, process의 handle count, resource의 open/close 대응, Win32 / HRESULT / SDK 에러
• 월 단위의 재현을 기다리기보다 접속·절단·재접속·실패 경로를 짧은 루프로 몇천 번 돌리는 편이 빠르다
• 후편에서 다루는 Application Verifier는 꽤 유효하지만, 그 전에 자체 로그로 lifetime의 무너짐을 쫓을 수 있게 해 두는 것이 토대입니다

요컨대 이런 안건에서 먼저 해야 할 것은,
「장기간 뒤에 떨어졌다」는 것을 바라보는 것이 아니라, 자원의 증가 방식과 실패 경로를 관측할 수 있는 형태로 하는 것입니다.

핸들 누수는 찾아졌을 때는 이미 이차 장애의 얼굴을 하고 있는 경우가 많습니다.
그래서 떨어진 순간의 예외만 보고 있으면 꽤 방향을 잘못 잡은 쪽으로 걷게 되기 쉽습니다.

2. 핸들 누수란 무엇인가

2.1. 여기서 말하는 「핸들」

여기서 말하는 핸들은 Windows의 프로세스가 OS의 자원을 참조하기 위한 식별자입니다.
예를 들어 다음 같은 것이 대상이 됩니다.

제어 앱에서 특히 문제가 되기 쉬운 것은 「어떤 조작을 위해 일시적으로 연 자원을 도중 실패의 경로에서 닫기 잊는다」 패턴입니다.

예를 들어 다음과 같은 흐름입니다.

• 재접속할 때마다 event를 1개 만든다
• callback 등록이나 촬상 개시가 도중에 실패한다
• success path에서는 close되지만, failure path에서는 close되지 않는다
• 평소의 짧은 테스트에서는 성공 경로만 지나므로 놓친다

이 타입은 코드 리뷰에서도 실운용에서도 꽤 평범하게 숨습니다.

2.2. 왜 장시간 운전에서만 표면화되기 쉬운가

핸들 누수는 1회에 화려하게 망가진다고는 할 수 없습니다.
오히려 까다로운 것은 1회의 실패로 1개만 누설되는 작은 기울기의 누수입니다.

flowchart LR
    A[통상 운전] --> B[가끔 timeout / reconnect]
    B --> C[실패 경로에서 Event Handle을 만든다]
    C --> D[CloseHandle이 호출되지 않는다]
    D --> E[Handle Count가 조금만 증가]
    E --> F[몇백 번 반복]
    F --> G[CreateEvent / SDK open이 실패]
    G --> H[다른 장소에서 크래시 / 정지]

1회의 reconnect로 1개밖에 누설되지 않는다면, 수 분에서는 아무것도 일어나지 않습니다.
다만 24/7로 도는 장치 제어 앱에서는 timeout, 재초기화, 절단 복구 같은 경계 조건이 몇 번이나 일어납니다.
그 결과 수 주 뒤에만 표면화된다는 묘한 보이는 방식이 됩니다.

여기서 중요한 것은 핸들 누수 그 자체가 크래시 행이 된다고는 할 수 없는 것입니다.
많은 것은 다음 같은 부서지는 방식입니다.

• 새로운 event / file / thread를 만드는 API가 실패한다
• SDK가 내부에서 필요한 자원을 만들 수 없고, 일반적인 실패 코드만 돌려준다
• 실패 후의 에러 핸들링이 얇아서 null / invalid handle을 밟고 떨어진다
• timeout이 늘어 결과적으로 watchdog이나 상위 제어에 kill된다

즉 크래시 지점은 「마지막 피해자」이지 「최초의 범인」이라고는 할 수 없습니다.

2.3. 메모리 누수와의 차이

장시간 운전 후의 불량에서는 우선 메모리 누수를 의심하고 싶어집니다.
물론 그 자체는 자연스럽지만, 핸들 누수는 다른 축으로 보는 편이 빠를 때가 있습니다.

그래서 장시간 운전의 구분에서는 「메모리만 본다」로는 한 눈으로 운전하고 있는 상태가 되기 쉽습니다.
적어도 Handle Count와 Thread Count는 함께 보는 편이 꽤 정리하기 쉬워집니다.

3. 사례: 산업용 카메라 제어 앱이 1개월 뒤에 갑자기 떨어진다

3.1. 일어나고 있던 증상

사상은 심플했습니다.

• 산업용 카메라를 제어하는 Windows 앱이 24/7로 돌고 있다
• 통상 시에는 평범하게 동작
• 약 1개월 정도 지나면 어느 날 갑자기 앱이 떨어진다
• 재기동하면 또 잠시는 동작

먼저 곤란한 것은 「떨어질 때까지가 길다」는 것입니다.
1회당의 재현에 1개월 기다리는 것은 조사로서 꽤 가혹합니다.

또한 까다로웠던 것은 떨어지는 장소가 매번 딱 같지는 않았던 점입니다.
어떤 때는 재접속 개시 직후, 어떤 때는 촬상 개시 시, 어떤 때는 SDK 호출의 실패 후였습니다.

이 보이는 방식이면 처음에는 다음 중 어느 것도 의심할 수 있습니다.

• 카메라 SDK 쪽의 불안정성
• 통신이나 디바이스 절단 기인의 일시 장애
• 메모리 누수
• 스레드 주변의 race
• 로그에 나오지 않은 초기화 실패

즉, 「왠지 의심스러운 것」이 너무 많은 상태였습니다.

3.2. 처음에 본 지표

그래서 처음에 한 것은 process 전체의 자원의 증가 방식을 보는 것이었습니다.
이번 사례에서는 관측 결과는 대체로 다음과 같은 방향이었습니다.

이 시점에서 시선은 꽤 좁혀졌습니다.
「1개월 뒤에 떨어진다」가 아니라 「도중에 뭔가를 조금씩 누설하고 있어 그 결과 1개월 뒤에 떨어진다」고 보는 편이 자연스러웠기 때문입니다.

3.3. 진짜 원인이었던 누수 장소

최종적으로 원인이었던 것은 카메라 재접속 시의 초기화 실패 경로에서 작성한 event handle의 close 누락이었습니다.

흐름을 간략화하면 대체로 다음과 같은 형태입니다.

sequenceDiagram
    participant App as 제어 앱
    participant OS as Windows
    participant SDK as 카메라 SDK

    App->>OS: CreateEvent
    App->>SDK: callback 등록
    SDK-->>App: 도중 실패 / timeout
    Note over App: failure path에서 return
    Note over App: CloseHandle이 호출되지 않는다

    loop 몇 번이고 reconnect
        App->>OS: Handle Count가 조금씩 증가
    end

    App->>OS: 다음 CreateEvent / Open
    OS-->>App: 실패
    App-->>App: 이차 장애로서 크래시

코드의 이미지로서는 이런 누수입니다.

handle = CreateEvent(...)

if (!RegisterCallback(handle))
{
    return Error;   // CloseHandle(handle)이 빠져 있다
}

if (!StartAcquisition())
{
    return Error;   // 여기서도 close가 빠진다
}

...
CloseHandle(handle)

짧은 테스트에서 놓치기 쉬운 이유도 꽤 이해하기 쉽습니다.

• 정상 기동 -> 정상 종료에서는 close된다
• 실패하는 것은 reconnect의 도중뿐
• 그 failure path를 대량으로 밟는 테스트가 없다
• 운영에서는 수 주 걸쳐 조금씩 축적된다

즉, 「통상계만 보면 안 보이지만 이상계에서는 평범하게 누설된다」는 구조였습니다.

수정 방침은 화려하지 않습니다.

• create/open과 close/dispose의 책임을 가까이 둔다
• 도중 실패여도 반드시 해제되도록 finally / destructor / session object 쪽에 치우친다
• callback 등록이나 촬상 개시의 전후로 ownership을 명확히 한다
• 「누가 닫는가」를 comments가 아니라 코드의 책임으로 표현한다

여기는 특별한 테크닉이라기보다 자원 수명을 코드에 매립하는 정리입니다.

4. 어떻게 구분했는가

4.1. 월 단위의 재현을 기다리지 않고 시간 단축한다

이런 조사에서 1개월을 매번 기다리는 것은 자가당착입니다.
해야 할 것은 의심스러운 경로를 단시간에 몇 번이나 지나는 것입니다.

이번 사례에서는 다음 같은 루프를 돌려 재현을 압축했습니다.

flowchart LR
    A[기동] --> B[카메라 open]
    B --> C[촬상 개시]
    C --> D[의사 timeout / 절단]
    D --> E[재접속]
    E --> F[촬상 재개]
    F --> G{N회 반복}
    G -- 예 --> D
    G -- 아니오 --> H[종료 시의 차분을 확인]

포인트는 통상의 「찍혀 있는」 시간이 아니라 경계의 수명 조작에 시간을 쓰는 것입니다.

구체적으로는 다음 같은 시나리오가 효과가 있습니다.

• open -> start -> stop -> close를 대량으로 돌린다
• timeout을 의도적으로 발생시켜 reconnect를 돌린다
• callback 등록 직후에 실패시킨다
• 절단 중단, 재접속 중단, shutdown 경합을 넣는다

1개월분의 실운용을 완벽하게 재현할 필요는 없습니다.
오히려 의심하고 있는 lifetime edge를 몇천 번 밟는 쪽이 원인에는 훨씬 가깝습니다.

4.2. Handle Count의 기울기로 본다

핸들 누수 조사에서는 절대값만 봐도 알기 어려운 경우가 있습니다.
중요한 것은 돌아와야 할 조작 후에 돌아오고 있는가와 몇 번의 조작으로 몇 개 증가하는가입니다.

보는 방식으로는 대체로 다음 순서가 이해하기 쉽습니다.

1. 워밍업 후의 baseline을 정한다
2. reconnect / start-stop / close 후에 Handle Count를 기록한다
3. 1사이클별의 차분을 본다
4. 몇 사이클 모은 기울기도 본다

예를 들어 이런 관점입니다.

leakSlope =
    (currentHandleCount - baselineHandleCount)
    / reconnectCount

절대값 2000이 많은지 적은지는 앱에 따라 흔들립니다.
다만 reconnect 1회당 +1로 돌아오지 않는다면 그것은 꽤 의심스럽습니다.

여기서의 요령은 Handle Count 단독으로 보는 것이 아니라 최소한 다음을 병기하는 것입니다.

• Handle Count
• Private Bytes
• Thread Count
• ReconnectCount
• 지금 어느 phase인지

이것으로 「메모리가 증가하고 있는가」, 「스레드가 증가하고 있는가」, 「재접속할 때마다 자원이 돌아오지 않는가」를 꽤 빠르게 알 수 있습니다.

4.3. create/open과 close/dispose의 대응을 본다

process 전체의 Handle Count가 의심스러운 것을 알아도 그것만으로는 누수 장소까지 갈 수 없습니다.
다음으로 필요한 것은 자원의 라이프사이클을 쌍으로 해서 보는 로그입니다.

예를 들어 다음 같은 structured log입니다.

CameraSession session=421 cameraId=CAM01 phase=ReconnectStart reason=FrameTimeout handleCount=1824 privateBytesMB=418

CameraResource session=421 resourceId=evt-884 kind=Event name=FrameReady action=Create osHandle=0x00000ABC handleCount=1825

CameraResource session=421 resourceId=evt-884 kind=Event name=FrameReady action=Close osHandle=0x00000ABC handleCount=1824

여기서 중요한 것은 osHandle에만 의지하지 않는 것입니다.
Windows의 핸들값은 나중에 재이용되는 경우가 있으므로, 로그상에서는 최소한 다음을 가지게 하는 편이 쫓기 쉽습니다.

• sessionId
• resourceId
• kind
• action(Create/Open/Register/Close/Dispose/Unregister)
• osHandle
• phase

이렇게 해 두면 Create는 있는데 Close가 없다는 한쪽 폐의 흐름이 찾기 쉬워집니다.

4.4. 핸들 누수는 「떨어진 장소」가 아니라 「누설한 장소」를 찾는다

여기는 꽤 중요합니다.

핸들 누수는 자주 다음처럼 보입니다.

• 떨어진 행: CreateEvent 실패
• 정말의 누수: 수일 전부터 failure path에서 CloseHandle이 빠져 있었다

즉 마지막에 떨어진 API는 피해의 출구이며 원인의 입구라고는 할 수 없습니다.

그래서 조사의 순서로서는,

1. 어느 자원이 계속 증가하고 있는지를 본다
2. 어느 조작 경계에서 돌아오지 않는가를 본다
3. create/open과 close/dispose의 대응이 무너져 있는 곳을 찾는다
4. 마지막에 크래시 지점을 읽는다

이 순서 쪽이 꽤 길을 잃기 어렵습니다.

5. 재발 방지를 위해 필요한 로그

5.1. 우선 남겨야 할 최소 세트

이번 조사에서 효과가 있었던 것은 단순히 로그량을 늘리는 것이 아닙니다.
「나중에 원인에 다다를 수 있는 정보」를 정리해 늘리는 것이었습니다.

최소한 다음은 남겨 두고 싶습니다.

이것으로 충분, 이라고는 하지 않습니다.
다만 적어도 이것이 없으면 「떨어졌다」는 사실만 남는 로그가 되기 쉽습니다.

5.2. 실제로 강화한 로그

이 사례에서는 로그를 다음 방향으로 강화했습니다.

1. 정기 heartbeat
   • 1~5분마다 Handle Count / Private Bytes / Thread Count / ReconnectCount를 낸다
2. 카메라 session 단위의 경계 로그
   • OpenStart
   • CallbackRegistered
   • AcquisitionStart
   • TimeoutDetected
   • ReconnectStart
   • ReconnectDone
   • CloseStart
   • CloseDone
3. 자원 라이프사이클 로그
   • event / thread / file / timer / SDK registration token의 Create/Open/Register와 Close/Dispose/Unregister
4. 에러의 정규화
   • 예외 message만으로 끝내지 말고 win32Error, HRESULT, sdkError, phase를 동시에 낸다

중요한 것은 성공 시와 실패 시에 로그의 형을 바꾸지 않는 것입니다.
이상 시에만 다른 형식이 되면 나중에 집계하기 어려워집니다.

5.3. 어느 입자도로 취할까

여기서 하기 쉬운 것이 「일단 전부 INFO로 뱉는다」입니다.
다만 그것을 하면 나중에 읽을 때 로그의 벽이 됩니다. 이것은 꽤 괴롭습니다.

입자도로서는 대체로 다음 구분이 현실적입니다.

• 정기 감시
  • Handle Count, Private Bytes, Thread Count, ReconnectCount
• 조작 경계
  • session의 start / done / fail
• 자원 경계
  • create/open/register와 close/dispose/unregister
• 이상 시 상세
  • error code, stack, dump 채취 트리거

매 프레임의 상세 로그는 보통 불필요합니다.
오히려 「어느 책임이 열고, 어느 책임이 닫았는가」를 읽을 수 있는 로그 쪽이 장시간 불량에는 효과가 있습니다.

6. 대략적인 구분 사용

• 수일~수 주 뒤에만 떨어진다
  • 우선 Handle Count / Private Bytes / Thread Count의 heartbeat를 넣는다
• retry / reconnect / shutdown이 있다
  • 그 경계만을 대량으로 돌리는 harness를 먼저 만든다
• native SDK / P/Invoke / Win32를 많이 쓴다
  • 후편의 Application Verifier를 적용할 가치가 높습니다
• GUI도 동거하고 있다
  • Handle Count에 더해 GDI Objects / USER Objects도 보는 편이 좋습니다
• 떨어진 순간의 예외만으로는 아무것도 알 수 없다
  • operation / session / resource lifecycle의 structured log를 먼저 갖추는 편이 빠릅니다

마지막의 1항목은 꽤 중요합니다.
불량 조사에서는 해석 기술 그 자체보다 관측할 수 있는 형태로 해 두고 있는가가 승부를 결정하는 경우가 자주 있습니다.

7. 정리

잡아 두고 싶은 점은 다음입니다.

증상의 읽는 방식:

• 장시간 운전 후에만 떨어진다면 메모리뿐만 아니라 Handle Count도 본다
• 핸들 누수는 통상계가 아니라 이상계의 failure path에 숨기 쉽다
• 크래시 지점은 누설한 지점이 아니라 이차 장애의 출구인 경우가 많다

재발 방지로 효과가 있는 설계:

• create/open과 close/dispose의 책임을 가까이 둔다
• session / operation 단위로 문맥을 가진 로그를 남긴다
• process 자원과 resource lifecycle을 양쪽 다 기록한다

테스트로 효과가 있는 진행 방식:

• 월 단위의 재현을 기다리지 않고 timeout / reconnect / shutdown을 짧은 루프로 돌린다
• 「부서지지 않는 것」뿐만 아니라 「부서졌을 때에 쫓을 수 있는 것」을 합격 조건으로 한다
• 후편에서는 Application Verifier를 써서 메모리 부족이나 핸들 이상 같은 나오기 어려운 부서지는 방식을 앞당겨 표면화시킵니다

제어 앱에서는 통상계가 통과하는 것도 중요하지만,
부서졌을 때에 「무엇이 일어났는지 알 수 있는」 것이 장기 운용에서는 꽤 효과가 있습니다.

핸들 누수는 바로 그 차이가 효과가 있는 타입의 불량입니다.
일어난 순간에만 보는 것이 아니라 증가 방식, 경계, 책임의 쌍으로 보도록 하면 꽤 쫓기 쉬워집니다.

후편: 산업용 카메라 제어 앱이 1개월 뒤에 갑자기 떨어질 때(후편) - Application Verifier란 무엇인가와 이상계 테스트 기반의 만드는 방법

8. 참고 자료

• GetProcessHandleCount function (processthreadsapi.h)
• Process.HandleCount Property (System.Diagnostics)
• 후편: 산업용 카메라 제어 앱이 1개월 뒤에 갑자기 떨어질 때(후편) - Application Verifier란 무엇인가와 이상계 테스트 기반의 만드는 방법

관련 기사

같은 태그를 공유하는 최신 기사입니다. 더 가까운 주제로 지식을 넓힐 수 있습니다.

관련 토픽

이 기사와 가까운 토픽 페이지입니다. 기사를 출발점 삼아 관련 서비스와 다른 기사로 이어집니다.

관련 사례

실제 정리와 개선 진행 방식이 가까운 사례 페이지입니다.

이 주제와 연결되는 서비스

이 기사는 다음 서비스 페이지로 이어집니다. 가까운 입구부터 확인해 주세요.

저자 프로필

기사 저자의 프로필 페이지입니다.

Go Komura

합동회사 코무라소프트 대표

Windows 소프트웨어 개발, 기술 상담, 장애 조사를 중심으로 재현이 어려운 장애 조사와 기존 자산이 남아 있는 프로젝트에 강점이 있습니다.