21.10.2.1. `top`, `free`, `work_queue` 출력 데이터 분석을 통한 병목 도출

21.10.2.1. top, free, work_queue 출력 데이터 분석을 통한 병목 도출

앞 장에서 보았던 top 명령어 출력창으로 조종석 기장처럼 돌아가 보자.
이 top 화면은 단순히 숫자들이 춤추는 전광판이 아니라, 개발자가 미처 놓친 논리적 결함을 고발하는 잔혹한 진술서다.

우리는 이 출력 창에서 세 가지 치명적인 병목(Bottleneck)의 징후를 추적해 낼 것이다.

1. 스택(Stack) 고갈: 시한폭탄의 카운트다운

가장 먼저 top 명령어 출력의 USED/STACK 컬럼을 노려봐야 한다.

nsh> top
 PID COMMAND                   CPU(ms) CPU(%)  USED/STACK PRIO(BASE) STATE 
  32 logger                      19542  3.437  1288/ 3560 250 (250)  w:sem 
 104 payload_autodrop               12  0.031  1028/ 1050 100 (100)  w:sem

여기서 / 뒤에 있는 숫자는 커널이 내 모듈(스레드)에게 허락해 준 ’스택(Stack) 메모리의 총량’이며, 앞의 숫자는 ’지금까지 내 모듈이 가장 깊숙이 함수를 찔러 들어갔을 때 집어먹었던 스택의 최대치(High-water Mark)’다.

위 로그의 payload_autodrop을 보라. 총 1050바이트의 스택을 받았는데 지금 1028바이트나 처먹었다. 남은 마진(Margin)이 고작 22바이트다.
만약 내 코드에서 알게 모르게 깊은 재귀 함수(Recursion)를 돌리거나, double array[50] 같은 크고 아름다운 배열을 함수 지역 변수로 선언해 버리면 이 22바이트의 마진은 순식간에 박살(Overflow) 난다.

스택 오버플로우는 드론계의 흑사병이다. 에러 로그도 없이 갑자기 드론이 공중에서 전원이 나간 듯 픽픽 떨어지게 만드는 주범이다. 이 끔찍한 병을 예방하는 CMake 스택 증설 처방전(STACK_MAIN 재설정 기준)을 21.10.2.1.1장에서 즉시 조제해 보겠다.

2. 우선순위(Priority) 역전: 하극상의 징후

다음으로 눈여겨볼 컬럼은 PRIO(BASE) 다. 이것은 CPU 스케줄러가 이 데몬에게 부여한 티어(등급)다.

top 로그를 보면 로거(logger)나 자세 제어기(mc_att_control) 데몬들은 PRIO가 250이라는 초고득점을 마크하고 있다 (NuttX에서 숫자가 높을수록 최우선으로 실행됨).
우리의 payload_autodrop은 기본값인 100 언저리로 세팅되어 있을 것이다.

만약 내가 짠 모듈이 EKF(위치 추정)보다 빨리 반응해야 한다는 오만함에 빠져 이 PRIO를 255로 올려버리면 어떻게 될까?
내 모듈이 1초에 50번씩 깨어날 때마다 CPU는 EKF와 센서의 연산을 일제히 멈추고 내 모듈부터 대접한다. 결국 EKF 필터가 밀리면서 위치 정보가 엉키고 기체는 제멋대로 날뛰게 된다. (우선순위 역전, Priority Inversion).
시스템 통합(SI) 엔지니어는 반드시 이 PRIO 값의 서열이 전체 픽스호크 아키텍처 다이어그램의 철학을 위배하지 않는지 수시로 감시(Audit)해야 한다.

3. work_queue status: 꽉 막힌 컨베이어 벨트

마지막으로 우리가 소환해 낼 명령어는 work_queue status 다.
PX4의 모듈들은 대부분 각자만의 스레드(Thread)를 통째로 가지지 않고, 몇 개의 거대한 ’일용직 대기소(Work Queue)’에 모여 컨베이어 벨트처럼 루프(Run())를 배분받아 실행된다. (우리의 payload_autodrop 모듈도 보통 wq:nav_and_controllers 대기소 소속이다).

nsh> work_queue status
...
Work Queue: wq:nav_and_controllers (priority: 250)
  Threads: 1, Max execution time: 105 us, Cycle: 4000 us
  Tasks:
    fw_pos_control_l1 (1)
    navigator (1)
    payload_autodrop (1) --> Waiting: 15400 us (WARNING!)
...

이 명령어를 쳤을 때 나타나는 Waiting 혹은 큐 대기 시간(Queue Delay Time) 수치를 주목하라.
만약 내 모듈(payload_autodrop) 옆에 Waiting 타임이 10,000us(10ms) 이상으로 비정상적으로 길게 찍혀있다면?

이것은 내 앞에 대기 중인 다른 모듈(예: navigator)이 무식하게 무거운 연산을 돌리느라 컨베이어 벨트를 꽉 붙잡고 놔주지 않아서, 내 모듈이 10ms 넘게 숨을 못 쉬고 기다렸다는 명백한 교통체증의 증거다.
이러한 병목을 발견했을 때, 남의 눈치 보지 않고 내 모듈만 따로 떼어내어 독방(Independent Thread)으로 유배시키는 극한의 리팩토링 오프로딩(Offloading) 기술을 21.10.2.1.2장에서 전수하겠다.