Skip to content
isdnetworks
Go back

붙이면 사라지는 버그

통신 모듈에서 간헐적으로 프레임이 깨졌다. 백 번에 한두 번쯤이다.

디버거를 붙였다. 중단점을 걸고 버퍼를 들여다볼 참이었다.

증상이 안 나왔다. 몇 시간을 돌려도 깨끗하고 디버거를 떼면 다시 나온다.

Table of contents

Open Table of contents

관측이 대상을 바꾼다

이유는 분명했는데 JTAG 로 디버거를 붙이면 타이밍이 바뀐다.

중단점에서 멈추면 그 사이 버퍼가 비워진다
단계 실행하면 인터럽트 처리 순서가 달라진다
디버그 빌드는 최적화가 꺼져 있어 실행 속도가 다르다

이 버그는 특정 타이밍에서만 나타나는데 그 조건 중 하나가 디버거가 안 붙어 있다는 것이었다.

관측하려는 행위가 관측 대상을 바꾸면 그 방법으로는 못 잡는다.

원인 — printf 디버깅의 비용

원래 쓰던 것이 printf 디버깅이었는데 그것이 이 버그를 못 잡은 이유가 있었다.

UART 출력은 느려서 115200bps면 한 글자에 87마이크로초가 들고 한 줄이 40자면 3.5밀리초다.

인터럽트 주기가 1밀리초인 시스템에서 로그 한 줄이 인터럽트 세 번보다 오래 걸린다.

UART 출력이 블로킹이면 그동안 다른 것이 멈추고 안 멈추게 버퍼링하면 기록 순서가 뒤바뀐다.

그래서 로그를 넣으면 증상이 사라지는데 JTAG 를 붙였을 때와 같은 일이다.

대상을 안 건드리는 관측으로 바꿨다

실행을 안 바꾸는 방법을 썼는데 로직 애널라이저를 핀에 물려 신호를 밖에서 보는 것이다.

코드는 아무것도 모르고 실행도 안 바뀐다. 파형을 잡으니 클럭과 데이터의 위상이 어긋나 있었다.

장비가 없는 자리를 대비해 코드 안에서 기록하되 출력을 안 하는 방식도 만들어 뒀다.

링 버퍼로 기록만 했다

ring 이라는 고정 크기 배열에 쓰고 idx 만 돌린다.

static struct { uint32_t ts; uint8_t ev; uint8_t val; } ring[256];
static volatile uint8_t idx;

#define TRACE(e, v) do { \
    ring[idx].ts = get_tick(); ring[idx].ev = (e); \
    ring[idx].val = (v); idx++; } while (0)

TRACE 한 번이 메모리 쓰기 몇 번이라 printf 와는 비용이 비교가 안 된다. 타이밍을 거의 안 건드린다.

idxuint8_t 라 256에서 저절로 돌아간다. 오래 돌려도 메모리가 안 넘치고 직전 256개 사건이 늘 남아 있다.

증상이 나면 그때 ring 을 통째로 덤프하는데 기록은 실시간이고 출력은 사건이 끝난 뒤 한 번이다.

검증 — 고친 뒤 재현 조건으로

파형과 링 버퍼를 나란히 놓으니 원인이 보였다. 인터럽트 중첩 상황에서 버퍼 인덱스가 두 곳에서 동시에 갱신되고 있었다.

고친 뒤에 다시 재현을 시도했다. JTAG 를 붙인 채로 확인하면 고쳤든 안 고쳤든 증상이 안 나온다.

증상이 안 나오는 것과 고쳐진 것은 다르다. 원래 증상을 재현하던 조건을 그대로 걸어서 안 나오는 것을 봐야 확인이 된다.

그리고 ring 은 안 뺐는데 다음에 또 필요하고 비용이 거의 없어서 배포 빌드에도 켜 뒀다.

판단 기준 — 이 부류를 알아보는 법

관측하면 사라진다는 것이 이 부류의 특징이다. 그러면 셋을 의심한다.

타이밍 의존       경쟁 조건, 인터럽트 중첩
최적화 의존       디버그 빌드에서만 사라지면 volatile 누락이나 미정의 동작
메모리 배치 의존  로그 변수 하나 추가로 사라지면 버퍼 오버런

셋째가 특히 고약하다. 코드를 고쳐서 사라진 것이 아니라 배치가 바뀌어서 사라진 것이라 나중에 다른 변경으로 다시 나타난다.

그래서 사라졌다로 끝내지 않고 왜 사라졌는지까지 봤다. 사라진 이유를 모르면 다음에 같은 것이 나와도 같은 자리를 다시 뒤진다.

정리


Share this post on:

Previous Post
코드에 적힌 값이 실제 값이 아니다
Next Post
타임아웃이 네 곳에 있다