주기가 짧은 처리에서 문제가 났다. 어디서 시간이 새는지 알아야 했는데 printf 를 넣었더니 문제가 사라졌다. 로그 자체가 느려서 타이밍이 바뀐 것이다.
Table of contents
Open Table of contents
출력이 비싼 곳
UART 출력은 느리고 한 줄에 밀리초 단위가 든다. UART 로 나가는 한 줄이 얼마나 걸리는지는 계산이 된다.
한 바이트에 시작과 정지 비트까지 열 비트가 실리므로 여든 바이트짜리 한 줄이면 115200에서 7밀리초쯤이고 9600이면 80밀리초를 넘는다. 주기가 밀리초인 처리에서 이것은 처리보다 로그가 오래 걸리는 것이다.
fwrite 로 파일에 쓰는 것도 마찬가지다. 저장 매체 접근은 예측이 안 된다. 출력하지 않고 기록하는 방법이 필요했다.
메모리에 쌓았다
고정 크기 ring 배열에 기록하고 idx 만 돌렸다.
static struct { uint32_t t; uint8_t ev; uint16_t v; } ring[256];
static volatile uint8_t idx;
#define TRACE(e, val) do { \
ring[idx].t = tick(); ring[idx].ev = (e); \
ring[idx].v = (val); idx++; } while (0)TRACE 한 번에 몇 사이클이 들고 출력은 안 한다. 문제가 나면 그때 통째로 덤프하고 직전 256개 사건이 시간순으로 남아 있다.
idx 는 인터럽트 쪽에서도 건드리므로 volatile 을 붙여 컴파일러가 읽기를 걷어내지 않게 했다. 쌓을 때 snprintf 로 문자열을 만들지 않고 숫자를 그대로 담았는데 사람이 읽을 모양으로 바꾸는 일은 꺼낼 때 한 번만 하면 된다.
무엇을 남길지 골랐다
ring 이 256개라 금방 차고 아무거나 넣으면 정작 필요한 것이 밀려난다. 상태가 바뀌는 지점만 넣었다.
인터럽트 진입·이탈
상태 전이
버퍼 임계 도달
오류 조건정상 흐름의 중간 단계는 안 넣었다. 그것은 정상일 때 안 봐도 되고 이상할 때는 상태 전이만 봐도 알 수 있다. 무엇을 남길지를 고르는 것이 이 방식의 절반이었다.
시각을 어떻게 찍나
타임스탬프가 필요한데 시간 함수도 비싸다. 그래서 tick 이 하드웨어 카운터 레지스터를 그대로 읽게 했고 그것뿐이라 거의 공짜다.
절대 시각이 아니라 상대 시각이지만 사건 사이 간격을 보는 데는 충분하다. 카운터가 한 바퀴 도는 주기를 확인해 뒀고 그보다 긴 간격은 못 잰다.
더 정밀하게 봐야 할 때는 핀 출력을 썼다.
GPIO_SET(DEBUG_PIN);
critical_work();
GPIO_CLEAR(DEBUG_PIN);GPIO 핀 상태를 바꾸는 것은 명령 한두 개이고 밖에서 오실로스코프로 본다. 그 구간이 얼마나 걸리는지와 얼마나 자주 일어나는지와 다른 신호와 어떻게 겹치는지가 보인다.
소프트웨어 안에서는 못 보는 것이 보였는데 인터럽트가 겹치는 순간 같은 것이다.
GPIO 쪽은 시간을 정밀하게 보여주고 값은 못 보여주며 ring 쪽은 값을 보여주고 시간 해상도가 낮다. 둘을 같이 켜고 관측하면 핀에서 이상한 구간을 찾고 그 시각의 링 버퍼 내용을 봐서 무엇이 언제 일어났는지가 맞춰진다.
판단 기준 — 릴리스에 남길 것
이 계측을 개발용으로만 쓰고 뺄지 고민했는데 남겼다.
TRACE 는 비용이 거의 없고 현장에서 문제가 났을 때 유일한 단서가 된다. 재현 안 되는 문제는 이것이 없으면 추측만 하고 개발할 때만 켜 두면 정작 필요한 순간에 아무것도 없다.
UART 로 내보내지 않는 한 남는 것은 메모리 쓰기 몇 번뿐이다. 출력을 DMA 에 넘기면 보내는 동안 처리가 안 멈추기는 하지만 걸어 주는 비용 자체는 남는다.
다만 핀 토글은 뺐다. 그 핀을 다른 용도로 쓸 수도 있고 밖에서 볼 장비가 현장엔 없다. 남기는 것과 빼는 것을 나눴다.
정리
- 출력이 비싼 곳에서는 로그를 넣는 것만으로 타이밍이 바뀐다
UART한 줄에 드는 시간은 비트 수로 계산이 된다- 메모리에 기록하고 출력은 나중에 한다
- 고정 크기 링 버퍼로 돌려 쓰면 오래 돌려도 안 넘친다
- 인덱스에는
volatile을 붙인다 - 쌓을 때
snprintf로 형식을 맞추지 말고 숫자를 그대로 담는다 - 공간이 한정되니 상태가 바뀌는 지점만 남긴다
- 무엇을 남길지 고르는 것이 절반이다
- 시각은 하드웨어 카운터를 읽고 상대 간격으로 쓴다
- 더 정밀하면 핀을 토글하고 밖에서 본다
- 두 방법을 같이 켜면 시간과 값이 맞춰진다
- 비용이 낮은 계측은 릴리스에도 남기고 핀 토글은 뺀다