디버깅 - 로그·어서션·오실로스코프 사고법

이 장에서 배우는 것

저전력 설계를 다룬 앞 장까지는 회로와 레지스터를 어떻게 다뤄야 전력을 아끼는지에 집중했다. 이 장은 방향을 바꿔, 그렇게 만든 펌웨어가 의도대로 동작하지 않을 때 원인을 어떻게 찾아내는지를 다룬다. 임베디드 환경에서는 printf 한 줄을 넣는 것도 공짜가 아니다. UART 전송은 CPU가 바이트를 하나씩 내보내길 기다리는 시간이고, 그 시간이 원래 버그의 타이밍을 바꿔버리는 경우가 흔하다. 이 장에서는 로그의 비용을 직접 숫자로 계산하고, 어서션(assertion)으로 불변조건을 코드에 고정하고, 로그 대신 핀 하나를 토글해 실행 시간을 재는 오실로스코프 사고법을 익힌다. 이 장을 마치면 스마트 화분 펌웨어를 처음부터 끝까지 조립하는 종합 실습으로 넘어간다.

• printf/UART 로그가 실행 타이밍에 미치는 비용을 직접 계산해본다
• assert로 불변조건을 코드에 고정하고, NDEBUG가 그 검사를 지우는 조건을 이해한다
• 핀 토글과 트레이스 버퍼로 로그 없이 코드 실행 구간을 측정한다
• 흔한 버그 증상별로 어떤 디버깅 도구를 먼저 꺼낼지 판단한다

문제 상황

스마트 화분의 펌프 제어 루프가 가끔 펌프를 너무 오래 켜둔다는 보고가 들어왔다고 하자. 토양 센서 값을 읽고 펌프 구동 시간을 계산하는 구간 어딘가가 예상보다 오래 걸리는 것 같은데, 매번 재현되지는 않는다. 가장 먼저 손이 가는 방법은 각 단계마다 printf를 찍어 시간을 확인하는 것이다. 그런데 로그를 넣는 순간 증상이 사라지거나, 반대로 더 심해지는 경우가 있다. 로그를 넣을 때마다 UART 전송 자체가 수백 마이크로초에서 수 밀리초를 잡아먹기 때문에, 관찰 행위가 관찰 대상을 바꿔버린 것이다. 이런 현상을 현장에서는 흔히 하이젠버그라고 부른다. 이 장은 이 문제를 세 가지 도구로 나눠서 접근한다. 로그의 비용을 숫자로 알아두는 것, 조건을 코드에 못박아 두는 것, 그리고 로그 없이 시간만 재는 방법이다.

printf 디버깅의 비용

UART로 문자열 하나를 내보내는 데 걸리는 시간은 보드레이트로 정해진다. 예를 들어 115200bps에서 시작 비트와 정지 비트를 포함해 한 바이트에 10비트가 걸린다고 보면, 한 글자를 보내는 데 약 87마이크로초가 걸린다. 짧은 디버그 메시지 한 줄이 20바이트 안팎이라고 해도, 반복문 안에서 매번 호출하면 전체 실행 시간에 수십 배의 오차가 생긴다. 더 나쁜 점은 대부분의 임베디드 UART 드라이버가 폴링 방식으로 동작해 전송이 끝날 때까지 CPU가 다른 일을 못 한다는 것이다. 즉 로그 한 줄이 늘어날수록 원래 코드의 실행 시간이 아니라 "로그를 포함한" 실행 시간을 재게 된다. 아래 완성 코드에서 이 차이를 직접 숫자로 확인한다.

어서션으로 불변조건을 고정하기

어서션은 "이 지점에서는 항상 참이어야 하는 조건"을 코드에 직접 적어두는 방법이다. C 표준 라이브러리의 assert 매크로는 조건이 거짓이면 메시지를 출력하고 abort를 호출해 즉시 멈춘다. 로그는 값을 눈으로 확인해야 이상을 알아채지만, 어서션은 조건이 깨지는 순간 그 자리에서 멈추므로 원인 위치를 좁히는 속도가 훨씬 빠르다. 다만 두 가지를 기억해야 한다. 첫째, NDEBUG를 정의하고 빌드하면 assert 안의 코드 전체가 사라진다. 조건식 안에 부수 효과가 있는 코드를 넣으면 릴리스 빌드에서 그 동작 자체가 빠져버린다. 둘째, 실제 보드에서는 abort가 표준 방식대로 동작하지 않는 경우가 많아, 자체적으로 UART에 메시지를 남기고 무한 루프나 워치독 리셋으로 넘기는 커스텀 어서션 매크로를 쓰는 경우가 흔하다. 매크로 자체의 정의는 cppreference의 assert 문서를 참고할 만하다.

핀 토글로 시간 재기: 오실로스코프 사고법

측정하려는 구간의 시작에서 GPIO 핀을 High로, 끝에서 Low로 바꾸면 그 핀의 펄스 폭이 곧 실행 시간이다. 레지스터 한 번 쓰는 비용은 UART로 문자열을 보내는 비용과 비교가 안 될 만큼 작아서, 측정 대상의 타이밍을 거의 건드리지 않는다. 실제 보드에서는 이 펄스를 로직 아날라이저나 오실로스코프로 직접 관찰하지만, 이 장의 시뮬레이션 환경(hal_sim)에서는 핀 변화를 타임스탬프와 함께 배열에 기록해 두고 나중에 한꺼번에 확인하는 방식으로 같은 효과를 낸다. "측정 도중에는 아무것도 출력하지 않고, 측정이 끝난 뒤에만 결과를 정리해서 보여준다"는 원칙이 핵심이다.

표가 말하는 것: PC 시뮬레이션과 실제 보드의 측정 비용 차이

항목	PC 시뮬레이션(hal_sim)	실제 보드(STM32·ESP32·아두이노)
GPIO 쓰기 비용	함수 호출 후 배열에 1us로 근사 기록	레지스터 직접 쓰기, 보통 수 ns~수십 ns
UART 전송 비용	문자열 길이 × 87us로 근사 계산	보드레이트·FIFO·DMA 사용 여부에 따라 실측값이 갈림
시간 측정 수단	타임스탬프 배열(트레이스 버퍼)	로직 아날라이저·오실로스코프로 파형 직접 관찰
어서션 실패 시 동작	stderr 출력 후 abort() 호출	보드마다 다름, 대개 UART 메시지 후 무한 루프·리셋

증상별로 어떤 도구를 먼저 꺼낼까

표가 말하는 것: 흔한 버그 증상과 적합한 확인 도구

증상	흔한 원인	확인할 도구
가끔만 재현되는 오동작	레이스 컨디션, 인터럽트 타이밍 겹침	핀 토글 + 오실로스코프
로그를 넣으면 버그가 사라짐	printf 자체가 타이밍을 바꿈(하이젠버그)	핀 토글, 최소한의 로그
특정 입력에서만 잘못된 값	경계값·오버플로 처리 누락	어서션으로 불변조건 검증
릴리스 빌드에서만 발생	NDEBUG로 assert 제거, 최적화로 타이밍 변화	릴리스 빌드 그대로 재현 후 핀 토글

완성 코드

hal_sim.h

#ifndef HAL_SIM_H
#define HAL_SIM_H

#include <stdint.h>
#include <stddef.h>

#define HAL_TRACE_MAX 64

typedef enum { PIN_LOW = 0, PIN_HIGH = 1 } pin_level_t;

typedef struct {
    uint32_t timestamp_us;
    unsigned pin;
    pin_level_t level;
} hal_edge_t;

void hal_sim_reset(void);
uint32_t hal_now_us(void);
void hal_delay_us(uint32_t us);
void hal_gpio_write(unsigned pin, pin_level_t level);
void hal_uart_write(const char *s);
size_t hal_trace_count(void);
const hal_edge_t *hal_trace_get(size_t index);

#endif

hal_sim.c

#include "hal_sim.h"
#include <string.h>

static uint32_t g_clock_us;
static hal_edge_t g_trace[HAL_TRACE_MAX];
static size_t g_trace_len;

void hal_sim_reset(void)
{
    g_clock_us = 0;
    g_trace_len = 0;
}

uint32_t hal_now_us(void)
{
    return g_clock_us;
}

void hal_delay_us(uint32_t us)
{
    g_clock_us += us;
}

void hal_gpio_write(unsigned pin, pin_level_t level)
{
    g_clock_us += 1;
    if (g_trace_len < HAL_TRACE_MAX) {
        g_trace[g_trace_len].timestamp_us = g_clock_us;
        g_trace[g_trace_len].pin = pin;
        g_trace[g_trace_len].level = level;
        g_trace_len++;
    }
}

void hal_uart_write(const char *s)
{
    size_t len = strlen(s);
    g_clock_us += (uint32_t)(len * 87);
}

size_t hal_trace_count(void)
{
    return g_trace_len;
}

const hal_edge_t *hal_trace_get(size_t index)
{
    if (index >= g_trace_len) {
        return NULL;
    }
    return &g_trace[index];
}

debug_demo.c

#include <assert.h>
#include <stdint.h>
#include <stdio.h>
#include "hal_sim.h"

#define ITER_COUNT 20
#define PIN_TRACE 4

static int pump_duty_from_adc(uint16_t adc_raw)
{
    int duty = 100 - (int)(adc_raw * 100 / 4095);
    assert(duty >= 0 && duty <= 100);
    return duty;
}

static uint32_t run_with_uart_logging(void)
{
    hal_sim_reset();
    uint32_t start = hal_now_us();
    for (int i = 0; i < ITER_COUNT; i++) {
        uint16_t adc = (uint16_t)(300 + (i * 137) % 4000);
        pump_duty_from_adc(adc);
        hal_uart_write("DEBUG: sensor tick\n");
    }
    return hal_now_us() - start;
}

static uint32_t run_with_pin_probe(void)
{
    hal_sim_reset();
    uint32_t start = hal_now_us();
    for (int i = 0; i < ITER_COUNT; i++) {
        hal_gpio_write(PIN_TRACE, PIN_HIGH);
        uint16_t adc = (uint16_t)(300 + (i * 137) % 4000);
        pump_duty_from_adc(adc);
        hal_gpio_write(PIN_TRACE, PIN_LOW);
    }
    return hal_now_us() - start;
}

int main(void)
{
    uint32_t t_uart = run_with_uart_logging();
    uint32_t t_probe = run_with_pin_probe();

    printf("UART 로그 포함 실행 시간: %u us\n", (unsigned)t_uart);
    printf("핀 토글만 사용한 실행 시간: %u us\n", (unsigned)t_probe);

    size_t edges = hal_trace_count();
    printf("캡처된 엣지 수: %zu\n", edges);

    if (edges >= 2) {
        const hal_edge_t *first = hal_trace_get(0);
        const hal_edge_t *last = hal_trace_get(edges - 1);
        printf("첫 엣지: %u us, 마지막 엣지: %u us\n",
               (unsigned)first->timestamp_us, (unsigned)last->timestamp_us);
    }

    return 0;
}

줄별 해설

g_clock_us는 실제 MCU의 자유 러닝 타이머 카운터를 흉내 낸 값이다. hal_gpio_write는 레지스터 한 번 쓰기에 해당하는 비용으로 1us만 더하고, 그 순간의 시각과 핀 상태를 g_trace 배열에 기록한다. 이 배열이 로직 아날라이저의 캡처 버퍼 역할을 한다. hal_uart_write는 문자열 길이에 87을 곱해 115200bps 폴링 전송의 블로킹 시간을 근사한다. pump_duty_from_adc는 토양 센서 원시값을 펌프 구동 비율(0~100)로 바꾸면서 assert로 결과 범위를 못박아 둔다. run_with_uart_logging과 run_with_pin_probe는 완전히 같은 계산을 반복하되, 전자는 매 반복마다 UART로 로그를 남기고 후자는 핀만 토글한다. 두 함수 모두 시작 부분에서 hal_sim_reset을 호출해 이전 측정의 흔적을 지우는데, 실제 보드에서 측정 전에 타이머 카운터를 0으로 초기화하는 것과 같은 이유다. main은 측정이 모두 끝난 뒤에야 결과를 출력한다. 측정 도중에는 어떤 로그도 남기지 않는다는 원칙을 코드로 지킨 것이다.

실행 결과

cc -std=c11 -Wall -Wextra -o debug_demo hal_sim.c debug_demo.c
./debug_demo

UART 로그 포함 실행 시간: 33060 us
핀 토글만 사용한 실행 시간: 40 us
캡처된 엣지 수: 40
첫 엣지: 1 us, 마지막 엣지: 40 us

실무에서 자주 틀리는 것

인터럽트 핸들러 안에서 printf 호출하기

인터럽트 서비스 루틴은 짧게 끝나야 하는데, 그 안에서 블로킹 UART 전송을 호출하면 다른 인터럽트 응답이 그만큼 늦어진다.

void ADC_IRQHandler(void) {
    uint16_t v = ADC1->DR;
    printf("adc=%u\n", v);
    process(v);
}

volatile uint16_t g_last_adc;
volatile int g_adc_ready;

void ADC_IRQHandler(void) {
    g_last_adc = ADC1->DR;
    g_adc_ready = 1;
}
/* 로그는 인터럽트 밖 메인 루프에서 g_adc_ready를 확인한 뒤 남긴다 */

assert 조건식에 부수 효과를 넣기

NDEBUG로 빌드하면 assert 문 전체가 사라지므로, 조건식 안의 대입이나 함수 호출도 함께 사라진다.

int i = 0;
assert(queue_push(&q, i++) == 0);

int ok = queue_push(&q, i);
assert(ok == 0);
i++;

측정용 핀을 다른 용도의 핀과 겹쳐 쓰기

측정 전용이 아닌 핀을 토글하면 그 핀에 물린 실제 신호(SPI 칩 셀렉트 등)를 건드려 오히려 새로운 오동작을 만든다.

#define PIN_TRACE 2 /* SPI_CS와 같은 번호 */
hal_gpio_write(PIN_TRACE, PIN_HIGH);

#define PIN_TRACE 9 /* 보드에서 비워둔 전용 핀 */
hal_gpio_write(PIN_TRACE, PIN_HIGH);

로그를 넣으면 사라지는 버그를 우연히 고쳤다고 착각하기

로그가 타이밍을 늦춰 레이스 컨디션이 드러나지 않게 된 것뿐인데, 문제가 해결됐다고 판단하고 로그를 지우면 버그가 그대로 남는다.

for (int i = 0; i < n; i++) {
    printf("i=%d state=%d\n", i, state);
    state = update(state);
}

for (int i = 0; i < n; i++) {
    hal_gpio_write(PIN_TRACE, PIN_HIGH);
    state = update(state);
    hal_gpio_write(PIN_TRACE, PIN_LOW);
}
/* 오실로스코프로 반복 간 간격을 로그 없이 그대로 관찰한다 */

한눈에 보기

표가 말하는 것: 세 가지 디버깅 도구의 비교

도구	무엇을 확인하나	비용·주의점
UART 로그	값, 상태, 분기 경로	바이트당 수십~수백us, 타이밍을 크게 바꿈
어서션	불변조건 위반 여부	NDEBUG에서 사라짐, 조건식에 부수 효과 금지
핀 토글	구간 실행 시간	레지스터 쓰기 수준으로 저렴, 전용 핀 필요

연습 문제

1. hal_uart_write의 바이트당 비용을 57600bps 기준인 174us로 바꾼다면, run_with_uart_logging의 총 실행 시간(us)은 얼마가 되는가.
2. ITER_COUNT를 40으로 늘리면 run_with_pin_probe가 시도하는 엣지 기록 횟수와 HAL_TRACE_MAX(64)의 관계를 설명하고, 그때 hal_trace_count()가 반환하는 값을 구하라.
3. pump_duty_from_adc에 범위를 벗어난 adc_raw 값 5000을 넘기면 어떤 일이 일어나는지, NDEBUG를 정의한 빌드와 정의하지 않은 빌드를 비교해 설명하라.
4. 반복문 안에서 매번 상세한 값을 남겨야 하는 상황이라면, 실행 시간을 크게 왜곡하지 않으면서 정보를 남기는 방법을 두 가지 제안하라.

정답과 해설

1. 메시지 문자열 "DEBUG: sensor tick\n"의 길이는 19바이트다. 174us × 19 = 3306us이고, 20회 반복이므로 3306 × 20 = 66120us가 된다. 보드레이트가 절반이 되면 로그 비용은 두 배로 늘어난다.

2. 40회 반복이면 매 반복마다 High·Low 두 번씩 총 80회 기록을 시도한다. 그런데 hal_gpio_write는 g_trace_len < HAL_TRACE_MAX일 때만 기록하므로 처음 64회만 저장되고 나머지 16회는 시각은 흘러가지만 배열에는 남지 않는다. 따라서 hal_trace_count()는 64를 반환한다.

3. duty = 100 - 5000×100/4095 = 100 - 122 = -22가 된다. NDEBUG를 정의하지 않은 디버그 빌드에서는 assert(duty >= 0 && duty <= 100)이 거짓이므로 메시지를 출력하고 프로그램이 즉시 종료된다. NDEBUG를 정의한 릴리스 빌드에서는 이 검사 자체가 컴파일 단계에서 사라져, 함수는 아무 경고 없이 -22를 반환하고 그 값이 펌프 제어 로직으로 그대로 흘러 들어간다.

4. 첫째, 매 반복마다 즉시 전송하지 않고 값만 순환 버퍼(링 버퍼)에 저장했다가 반복문이 끝난 뒤 한꺼번에 출력한다. 둘째, 상세한 문자열 대신 핀 토글이나 카운터 증가처럼 극히 저렴한 신호만 남기고, 문자열 로그는 오류가 실제로 발생했을 때만 남기도록 조건을 둔다.