트레이스와 프로파일링 — 멈추지 않고 관찰하기

앞 편에서 본 문제가 있다 — 브레이크포인트를 걸면 사라지는 버그. 타이밍에 의존하는 버그는 멈추는 순간 조건이 달라져 재현되지 않는다.

그래서 필요한 것이 멈추지 않고 기록하는 방법이다. 그리고 "느리다" 를 고치려면 먼저 어디가 느린지 재야 한다.

관찰 수단의 비용 비교

방법	비용	얻는 것
GPIO 토글	몇 클럭	시간 구간(오실로스코프로)
DWT 사이클 카운터	몇 클럭	정확한 사이클 수
RTT	수백 ns	문자열 로그
ITM/SWO	수백 ns~µs	문자열·이벤트
UART `printf`	수 ms	문자열
세미호스팅	수 ms~	문자열

printf 가 압도적으로 비싸다. 115200bps 에서 40바이트를 보내면 약 3.5ms 다. 1ms 주기 제어 루프에 넣으면 그 자체가 시스템을 망가뜨린다.

DWT 사이클 카운터 — 가장 정확한 자

// 한 번만 켜 두면 된다
void cycle_counter_init(void) {
    CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk;
    DWT->CYCCNT = 0;
    DWT->CTRL |= DWT_CTRL_CYCCNTENA_Msk;
}

// 재기
uint32_t t0 = DWT->CYCCNT;
process_frame();
uint32_t cycles = DWT->CYCCNT - t0;
uint32_t us = cycles / (SystemCoreClock / 1000000);

클럭 단위로 재므로 오차가 거의 없다. 168MHz 라면 1 사이클이 약 6ns 다.

// 최악값을 계속 추적한다 — 평균보다 이것이 중요하다
static uint32_t worst;
uint32_t c = DWT->CYCCNT - t0;
if (c > worst) worst = c;

실시간 시스템에서는 최악값이 설계 근거다. 평균 100µs 에 최악 3ms 인 함수는 1ms 주기에 넣을 수 없다.

// 오버플로에 안전하게 — 32비트는 168MHz 에서 약 25초마다 한 바퀴
uint32_t elapsed = (uint32_t)(DWT->CYCCNT - t0);    // 뺄셈은 항상 맞다

GPIO 토글 — 오실로스코프로 보는 법

#define PROBE_HI()  (GPIOB->BSRR = (1 << 0))
#define PROBE_LO()  (GPIOB->BSRR = (1 << (0 + 16)))

void TIM2_IRQHandler(void) {
    PROBE_HI();
    TIM2->SR &= ~TIM_SR_UIF; (void)TIM2->SR;
    control_loop();
    PROBE_LO();
}

      |<-- 폭 = 실행 시간 -->|
   ___|‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾|________________|‾‾‾‾‾
      |<------------ 간격 = 주기 ------------>|

폭 / 간격 = 이 ISR 의 CPU 점유율

여러 핀을 쓰면 겹침까지 보인다.

// 핀 3개로 세 작업의 실행 구간을 동시에 관찰
PROBE_A_HI(); task_a(); PROBE_A_LO();

로직 애널라이저로 보면 어느 인터럽트가 어느 것을 선점했는지가 한눈에 나온다. 우선순위 설계를 검증하는 가장 직접적인 방법이다.

측정 자체의 비용이 한두 클럭이라 타이밍을 거의 안 바꾼다는 것이 큰 장점이다.

RTT — 빠른 로그

// SEGGER RTT — SRAM 의 링 버퍼에 쓰고 디버거가 읽어 간다
SEGGER_RTT_printf(0, "adc=%d\r\n", v);

타깃은 메모리에 쓰기만 하고 끝난다. UART 처럼 비트를 밀어내는 시간이 없어 수백 ns 면 된다. 디버거가 백그라운드로 그 버퍼를 긁어 간다.

UART printf   40바이트 → 3.5ms    (115200bps)
RTT           40바이트 → 약 1µs    (메모리 복사만)

3000배 차이라 실시간 루프 안에서도 쓸 수 있다. 다만 디버거가 붙어 있어야 하고 별도 라이브러리가 필요하다.

ITM/SWO — 표준 트레이스 경로

// ITM 채널 0 으로 문자를 보낸다 (printf 를 여기로 연결)
int _write(int fd, char *buf, int len) {
    for (int i = 0; i < len; i++) ITM_SendChar(buf[i]);
    return len;
}

SWO 핀 하나로 나간다. SWD 의 두 선에 한 선만 더하면 되고, ARM 표준이라 벤더 종속이 없다.

// 데이터 워치포인트로 변수 변화를 자동 추적 — 코드 수정 없이
DWT->COMP0 = (uint32_t)&g_state;
DWT->MASK0 = 0;
DWT->FUNCTION0 = (0b10 << 0)          // 쓰기 감시
               | DWT_FUNCTION_EMITRANGE_Msk;
// → g_state 가 바뀔 때마다 SWO 로 값이 나간다

코드를 안 고치고 변수 변화를 기록할 수 있다는 것이 강력하다. 로그 문장을 넣으면 타이밍이 바뀌는데, 이 방식은 하드웨어가 하므로 영향이 거의 없다.

SWO 대역폭이 한계다 — 클럭에 비례하고, 넘치면 데이터가 조용히 버려진다
→ 채널을 줄이거나 필터를 건다

통계적 프로파일링 — 어디가 느린가

// 타이머 인터럽트에서 PC 를 표본 추출한다
#define BUCKETS 64
static uint32_t hist[BUCKETS];

void PROFILE_TIMER_IRQHandler(void) {
    clear_flag();
    // 예외 스택 프레임의 PC (offset +24)
    uint32_t *sp = (uint32_t *)__get_MSP();
    uint32_t pc = sp[6];

    if (pc >= FLASH_BASE && pc < FLASH_END) {
        hist[(pc - FLASH_BASE) / BUCKET_SIZE]++;
    }
}

"어느 주소에서 시간을 보내나" 를 확률로 알아낸다. 코드를 전혀 고치지 않고, 표본 주기만큼만 오버헤드가 든다.

# 히스토그램을 덤프해 addr2line 으로 함수 이름을 붙인다
for addr in $(cat hist.txt); do
  arm-none-eabi-addr2line -e firmware.elf -f -C $addr
done | sort | uniq -c | sort -rn | head
#  412 filter_iir  (dsp.c:88)     ← 여기에 41% 를 쓴다
#  201 memcpy

PC 표본이 계측보다 나은 점은 사전 지식이 필요 없다는 것이다. 어느 함수를 재야 할지 몰라도 결과가 알려 준다.

인터럽트 지연을 실제로 재기

// 외부 신호가 들어온 뒤 ISR 이 시작되기까지
void EXTI0_IRQHandler(void) {
    PROBE_HI();                              // 오실로스코프의 두 번째 채널
    EXTI->PR = (1 << 0); (void)EXTI->PR;
    ...
    PROBE_LO();
}

채널1 (입력 신호)  ___|‾‾‾‾‾‾‾‾‾‾
채널2 (프로브)     ______|‾‾‾‾‾‾‾
                      |<->|
                       이 간격이 인터럽트 지연

이론값(12사이클)과 실측이 다르면 그 사이에 더 높은 우선순위 ISR 이 돌았거나, 임계 구역에서 인터럽트를 막고 있었다는 뜻이다.

// 임계 구역이 얼마나 긴지도 재 본다 — 이것이 곧 최악 지연의 하한이다
uint32_t s = enter_critical();
uint32_t t0 = DWT->CYCCNT;
shared_update();
uint32_t c = DWT->CYCCNT - t0;
exit_critical(s);
if (c > worst_critical) worst_critical = c;

임계 구역의 최악 길이가 시스템의 최악 인터럽트 지연을 지배한다. 이 값을 모르면 실시간성을 증명할 수 없다.

이벤트 기록 — 시간 순서를 남긴다

typedef struct { uint32_t cyc; uint8_t id; uint16_t val; } Ev;
static Ev log[256];
static volatile uint8_t widx;

#define TRACE(id, v)  do { \
    uint8_t i = widx++; \
    log[i].cyc = DWT->CYCCNT; log[i].id = (id); log[i].val = (v); \
} while (0)

TRACE(EV_ISR_IN, 0);
TRACE(EV_QUEUE_PUSH, len);
TRACE(EV_TASK_SWITCH, task_id);

한 항목 기록에 10 사이클 정도라 실시간 경로에도 넣을 수 있다. 순환 버퍼라 최근 256개가 항상 남는다.

// 폴트나 이상 상황에서 덤프한다 — 그 직전에 무슨 일이 있었나
void dump_trace(void) {
    for (int i = 0; i < 256; i++) {
        Ev *e = &log[(widx + i) & 255];
        printf("%10lu %2u %5u\r\n", e->cyc, e->id, e->val);
    }
}

"터지기 직전 100 마이크로초에 무슨 일이 있었나" 에 답하는 유일한 방법이 이것이다. 브레이크포인트로는 그 순간을 잡을 수 없다.

무엇을 먼저 재나

① 전체 CPU 여유          IDLE 시간 비율 — 여유가 없으면 다른 것을 봐도 소용없다
② 각 작업의 최악 실행 시간  주기 대비 부하율
③ 인터럽트 지연           임계 구역 최악 길이
④ 함수 단위 프로파일       ①~③에서 병목이 좁혀진 뒤에

// ① 을 재는 가장 쉬운 방법 — 유휴 루프에서 카운터를 올린다
volatile uint32_t idle_count;
while (1) { scheduler_run(); idle_count++; }

// 1초마다 비교: 아무 일도 없을 때의 값 대비 지금 값
// idle_count 가 절반이면 CPU 를 절반 쓰고 있다

순서를 지키는 것이 중요하다. 함수 하나를 최적화했는데 시스템이 안 빨라지는 경우가 흔한데, 대개 병목이 다른 곳(인터럽트 지연·대기)이기 때문이다.

제품에 남기는 관측

// 개발용 로그는 빼되, 지표는 남긴다
typedef struct {
    uint32_t boot_count;
    uint32_t fault_count;
    uint32_t isr_worst_us[N_ISR];
    uint32_t queue_overflow;
    uint32_t comm_error;
} Metrics;

현장에서 문제가 나면 이 숫자가 유일한 단서다. 로그를 다 빼 버리면 "가끔 이상하다" 는 신고에 아무 대응도 할 수 없다.

// 진단 명령으로 꺼내 볼 수 있게 한다
case CMD_GET_METRICS: send(&metrics, sizeof metrics); break;

한눈에 정리

printf 는 수 ms, GPIO 토글·DWT 는 몇 클럭 — 관측이 타이밍을 바꾸면 관측이 아니다
DWT 사이클 카운터가 가장 정확한 자다. 최악값을 추적하는 것이 실시간 설계의 근거
GPIO 토글 + 오실로스코프로 실행 시간·주기·선점 관계를 눈으로 본다
RTT 는 UART 보다 3000배 빠르다 — 메모리에 쓰고 디버거가 긁어 간다
ITM/SWO 는 ARM 표준이고, DWT 워치포인트로 코드 수정 없이 변수 변화를 추적할 수 있다
**PC 표본 프로파일링**은 어느 함수를 재야 할지 몰라도 병목을 찾아 준다
임계 구역의 최악 길이가 최악 인터럽트 지연을 지배한다 — 이 값을 재야 실시간성을 증명한다
순환 이벤트 로그가 "터지기 직전에 무슨 일이 있었나" 에 답하는 유일한 수단
재는 순서 — CPU 여유 → 작업별 최악 → 인터럽트 지연 → 함수 프로파일
제품에는 로그 대신 지표를 남긴다 — 현장 신고에 대응할 유일한 단서

꼬리질문 대비

"실행 시간을 재는 가장 정확한 수단은?" → DWT 사이클 카운터. 읽기 오버헤드가 몇 클럭이라 측정 대상을 거의 안 흔든다

"printf 로 시간을 재면 왜 안 되나?" → 115200bps 에서 한 줄이 수 ms — 측정 대상보다 커서 결과 자체를 왜곡한다

"인터럽트 지연을 실제로 어떻게 재나?" → 인터럽트 발생 핀과 ISR 진입 시 토글하는 핀을 오실로스코프로 동시에 본다

출처 — Arm, Cortex-M4 Technical Reference Manual(DDI0439) — DWT·ITM · Arm, CoreSight Architecture Specification — 트레이스 경로 · Arm, Cortex-M4 Devices Generic User Guide(DUI 0553) §5 디버그 · SEGGER RTT 문서