21.10.1.1. 성능 카운터 셋업 및 NSH `perf` 명령어 추적

21.10.1.1. 성능 카운터 셋업 및 NSH perf 명령어 추적

아무리 좋은 체중계가 있어도 올라가지 않으면 몸무게를 알 수 없듯, perf_counter를 사용하려면 우리 모듈의 클래스 내부에 타이머 객체를 선언하고 측정하고 싶은 구간에 센서를 매달아야 한다.

이 과정은 마치 하드웨어에 탐침(Probe)을 꽂는 것과 유사하게 진행된다.

1. 카운터 객체 생성 (Allocation)

먼저 PayloadAutoDrop 클래스 헤더 파일에 성능 카운터(Performance Counter) 객체를 담을 포인터 변수를 하나 선언한다. PX4의 perf_counter_t 타입이 바로 이 탐침이다.

#include <perf/perf_counter.h>

class PayloadAutoDrop : ... {
    ...
private:
    // 내 루프의 소요 시간(Elapsed Time)을 담을 전용 포인터
    perf_counter_t _loop_perf;
};

그리고 스레드(Task)가 처음 메모리에 올라올 때 호출되는 생성자(Constructor) 혹은 필수 초기화 루틴 내부에서 perf_alloc() 함수를 이용해 시스템에 내 전용 카운터를 등록(Registration)한다.

// [모듈 생성자 내부]
PayloadAutoDrop::PayloadAutoDrop() :
    ModuleParams(nullptr),
    // 1번 인자: 동작 방식 지정 (PC_ELAPSED: 소요 시간 측정 방식)
    // 2번 인자: 콘솔 창에 출력될 내 카운터의 유니크한 라벨(이름)
    _loop_perf(perf_alloc(PC_ELAPSED, "payload_loop_latency"))
{
    // ...
}

이제 픽스호크 커널은 "payload_loop_latency" 라는 이름표를 단 64비트짜리 특수 누적 레지스터를 당신의 모듈에 할당해 주었다.

2. 측정 블록 지정 (perf_begin & perf_end)

이제 측정을 시작할 것이다. 우리는 Run() 함수 안에서 로직이 실행되는 순수한 연산 시간만을 측정해야 하므로, 루프 진입 직후에 타이머 스위치(perf_begin)를 켜고 빠져나가기 직전에 끄면(perf_end) 된다.

void PayloadAutoDrop::Run() {
    // [측정 시작] 이때의 시간을 나노초 레벨로 기록한다.
    perf_begin(_loop_perf);

    // --------------------------------------------------------
    // [ 측정 대상 코드 구간 ]
    // uORB 구독, FSM 스위치 케이스, 노이즈 필터링 등 모든 연산 수행...
    // --------------------------------------------------------
    if (_vehicle_status_sub.updated()) { /* ... */ }
    switch (_current_state) { /* ... */ }

    // [측정 종료] 지금 시간에서 시작 시간을 뺀 뒤 누적 레지스터에 기록한다!
    perf_end(_loop_perf);
}

이 perf_begin과 perf_end 함수는 일반적인 C++ 함수가 아니라, CPU 아키텍처(ARM Cortex)의 하드웨어 타이머 레지스터를 직접 긁어오는 초경량 인라인(Inline) 매크로로 짜여있다.
따라서 이 두 줄을 삽입함으로써 생기는 I/O 레이턴시는 사실상 ’0’에 수렴하며, 어떠한 관찰자 효과(Observer Effect)도 일으키지 않는다.

3. 카운터 메모리 반납 (Deallocation)

모듈이 죽을 때 카운터를 커널에 반납하지 않으면 시스템 메모리에 흉측한 흉터(Memory Leak)가 남게 된다.
이전 장에서 배운 파괴자(Destructor) 루틴 안에 반드시 반납 코드(perf_free)를 세팅해야 한다.

PayloadAutoDrop::~PayloadAutoDrop() {
    // 내가 쓰던 카운터를 시스템에 정중하게 반납한다.
    perf_free(_loop_perf);
}

4. 실시간 터미널(NSH)에서 내 카운터 까보기

기체에 시동을 걸고 모듈이 수만 번의 루프를 돈 뒤, 기체를 책상 위에 올리고 터미널(nsh)을 연결해 보자.
이제 그 거대한 결과물을 볼 시간이다. NSH 커맨드 창에 단순히 perf 라고 타이핑해 보라.

픽스호크 내부에서 돌아가는 수십 개의 데몬들이 물고 있는 수백 개의 카운터 정보가 폭포수처럼 쏟아져 내릴 것이다. 그중 당신이 만든 "payload_loop_latency" 라벨을 찾아보라.

nsh> perf
...
ekf2_main: 18520 events, 342us avg, min 210us, max 670us
commander_run: 5420 events, 120us avg, min 80us, max 300us
payload_loop_latency: 120500 events, 24us avg, min 18us, max 54us
...

이 경이로운 출력창을 해석해보면 이렇다.

  • events: 지금까지 내 Run() 루프가 12만 번 불렸다.
  • avg: 루프를 한 번 도는 데 평균적으로 단 24us(마이크로초) 가 걸렸다. (초경량 모듈 완성!)
  • max: 가장 오래 걸렸을 때도 겨우 54us가 소요되었다 (가장 불길한 병목 수치).

만약 이 max 수치가 당신의 목표 스케줄 주기(예: 20ms = 20,000us)를 넘어 30,000us 따위로 찍혀있다면? 당신의 모듈에는 어딘가에 치명적인 동기화 락(Lock) 대기나 무한 루프 버그가 똬리를 틀고 있다는 확실한 증거다.
코드 레벨의 타이밍 검증을 마쳤다면, 이제 시스템 전체 관점에서 내 모듈이 램(RAM)과 CPU를 얼마나 잡아먹고 있는지, 하드웨어 리소스 관점에서의 NSH 트러블슈팅(커맨드 top, free) 기법을 21.10.2장에서 분석해 보자.