Linux Superluminal 프로파일러의 시스템 프리징 버그 추적기
Superluminal의 Linux 버전 개발을 진행 중이던 우리 팀에게 예상치 못한 문제가 터졌습니다. 얼마 전부터 소수의 테스터들과 함께 비공개 알파 테스트를 진행하고 있었는데, 한 테스터인 Aras가 Superluminal로 프로파일링 캡처 중에 시스템이 주기적으로 완전히 멈춘다고 보고했거든요.
Superluminal은 "그냥 작동한다"는 것이 우리의 자부심이었습니다. 이 문제는 정확히 그 반대였죠. 결국 우리는 경력 중 가장 까다로웠던 버그 중 하나를 추적하게 되었습니다. 이 과정에서 Linux 커널 내부로 깊이 들어가게 되었고, 커널 스핀락에 대해 평생 알고 싶지 않던 것들까지 전부 배우게 되었습니다. 그리고 그 과정에서 여러 이슈를 찾아내고 해결하는 데 도움을 주게 되었죠.
초기 분석
문제의 구체적인 상황은 이랬습니다. Aras의 Fedora 42 머신(커널 6.17.4-200)에서 Superluminal 캡처 실행 중 주기적으로 짧은 시간 동안 시스템이 멈추는 현상이 발생했습니다.
이런 종류의 버그를 원격으로 디버깅하기는 정말 어렵습니다. 처음엔 VM에서 재현해보려고 여러 Fedora 버전과 커널로 시도했지만 성공하지 못했습니다. 결국 물리 머신에 Fedora를 설치한 후에야 문제를 재현할 수 있었어요.
재현에 성공했으니 이제 본격적으로 조사를 시작할 수 있었습니다.
Superluminal의 캡처 파일을 열어서 타임라인을 살펴봤습니다.
각 스레드의 실행 상황이 보이는데, 녹색은 CPU가 실제로 일 하고 있다는 뜻(스레드가 스케줄됨)이고, 다른 색깔은 스레드가 뭔가를 기다리며 대기 중이라는 의미입니다. 바로 의심스러운 부분들(파란색으로 표시된 부분)이 눈에 띄었습니다. 모든 스레드가 동일한 시간 동안 바쁜 상태로 보이는 영역이 있거든요. 이건 프로파일링하는 작업과 맞지 않습니다.
각 영역마다 250밀리초 이상 CPU가 완전히 바쁜 상태로 표시됩니다. 이 부분을 확대해서 스레드를 펼쳐보니 흥미로운 것을 발견했습니다.
이 스레드가 '바쁜' 상태라고 보고되고 있지만, 실제로는 이 기간 동안 샘플이 전혀 수집되지 않고 있었습니다. 이 패턴은 모든 스레드에서 동일하게 나타났어요.
문제를 재현할 때 dmesg 출력을 보니 다음 같은 메시지들이 나타났습니다. 그리고 이것이 Superluminal에서 보이는 250밀리초와 정확히 일치했습니다.
[ +0.014286] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 1.723 msecs
[ +0.232451] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 250.424 msecs
[ +0.000001] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 250.424 msecs
[ +0.250938] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 250.936 msecs
이 정보들을 종합하면 커널에서 뭔가 250밀리초 이상 걸리는 작업이 발생하고 있다는 건 분명합니다. 다만 CPU가 왜 바쁜지는 아직 모릅니다. 콜스택이나 샘플이 없으니까요.
그럼 그 뭔가가 뭔지 알아내야 하는데...
커널 디버깅
보통 애플리케이션에서 이런 프리징이 발생하면 비교적 간단합니다. 디버거를 붙이고, 프리징이 일어날 때 멈춘 다음, 스레드와 스택을 확인하면 되거든요. 하지만 이건 커널 레벨의 프리징이라 그렇게 단순하지 않습니다.
다행히 이전 작업에서 커널을 직접 컴파일하는 방법을 이미 배웠습니다. 커스텀 커널이 있으면 커널 디버깅을 활성화하기는 간단합니다. 다만 다른 머신에서 커널을 디버깅해야 한다는 점이 있네요.
문제는 우리가 이것을 가지고 있지 않다는 것이었습니다:
너무 오래된 기억이 아니라면 이것이 뭔지 바로 알 수 있을 겁니다. 혹은 TX와 RX선을 함께 납땜해서 멀티플레이로 Doom을 즐겼던 추억도 있을지도요.
아직 젊으신 분들을 위해 설명하자면: 이것은 COM 포트 또는 시리얼 포트입니다.
과거 컴퓨터들은 기본적으로 메인보드에 이것을 가지고 있었습니다. 하지만 현대의 머신들은 대부분 없습니다. Linux 커널 디버거는 디버거와 피디버거 간의 통신에 이것을 사용합니다. 즉, 두 머신 모두 시리얼 포트를 가져야 한다는 뜻이죠. 결국 우리는 위 사진처럼 시리얼 포트 PCIe 카드를 구입해야 했습니다.
이제 이것을 갖추니 원격 머신에 gdb로 연결해서 커널 상태를 조사할 수 있었습니다. 여기서부턴 버그를 찾는 게 간단할 줄 알았습니다. 프리징을 재현한 다음 원격 머신에서 커널로 진입해서 뭐가 일어나고 있는지 보면 되니까요.
... 적어도 그렇게 되어야 맞았습니다. 그런데 커널이 이 프리징 상태에 빠지면 디버거도 응답하지 않더군요. 프리징 중에 디버거로 진입하려는 모든 시도는 gdb가 크래시되거나 타임아웃되어 실패했습니다.
디버깅은 불가능해 보였습니다. 좋은 상황이 아니었죠. 그럼 다른 방법이 있을까요?
최소 재현 사례 찾기
이런 종류의 이슈, 즉 어떤 코드가 문제를 일으키는지 전혀 알 수 없을 때는 문제의 범위를 최대한 좁혀보는 게 도움이 됩니다.