Showing Posts From

Printf

밤 11시, 여전히 'printf' 디버깅 중이다

밤 11시, 여전히 'printf' 디버깅 중이다

밤 11시, 여전히 'printf' 디버깅 중이다 시작은 단순했다 오후 3시쯤이었다. UART 통신이 간헐적으로 끊긴다는 보고가 올라왔다. "간단한 거 아니야?" 싶었다. 보드레이트 확인하고, 패리티 비트 체크하면 될 줄 알았다. printf("UART Start\n"); 일단 찍어봤다. 잘 나온다. printf("TX: %d\n", tx_count); 이것도 나온다. "문제없는데?" 생각한 게 5시간 전이다.printf의 함정 문제는 printf를 많이 찍기 시작하면서 생겼다. 센서 데이터를 실시간으로 보고 싶어서 루프 안에 넣었다. while(1) { sensor_data = read_sensor(); printf("Data: %d\n", sensor_data); HAL_Delay(100); }그런데 이상했다. 센서 값이 튀기 시작했다. 아니, printf 넣기 전에는 정상이었는데? 로그를 더 자세히 봤다. 타이밍이 이상하다. 100ms마다 찍혀야 하는데 가끔 200ms, 300ms씩 벌어진다. "printf가 블로킹이라 그런가?" UART 전송이 끝날 때까지 CPU가 기다린다. 당연히 느리다. 그래서 인터럽트 타이밍이 밀린 거다. 밤 7시. 저녁 먹으러 가자는 팀장님 말씀에 "조금만요" 했다.로그 메시지가 만든 버그 printf를 줄여봤다. 루프에서 빼고, 중요한 곳에만 넣었다. 그랬더니 또 다른 문제가 보였다. printf("Timer Start\n"); start_timer(); printf("Timer Running\n");타이머 시작하고 바로 다음 printf 찍는데, 타이머 인터럽트가 안 들어온다. 아니, 들어오긴 하는데 타이밍이 늦다. printf 하나에 몇 ms씩 걸리니까, 타이머 정밀도가 다 깨진 거다. "이래서 printf 디버깅 하지 말라는 거구나." 알면서도 할 수밖에 없다. JTAG 디버거는 느리고, 오실로스코프는 채널이 부족하고. 결국 printf가 제일 편하다. 밤 9시. 사무실에 나랑 옆자리 김 대리만 남았다. "형, 먼저 가세요." "너도 일찍 가라. 내일 또 있어." 말은 그렇게 하고 둘 다 안 간다.DMA로 바꿔보자 printf가 블로킹이라면 DMA를 쓰면 되지 않을까? UART DMA 설정을 켰다. 코드를 수정했다. char log_buffer[256]; sprintf(log_buffer, "Data: %d\n", sensor_data); HAL_UART_Transmit_DMA(&huart2, (uint8_t*)log_buffer, strlen(log_buffer));돌려봤다. 좋아졌다. ...라고 생각한 게 10시였다. 30분 돌리니까 또 문제다. 로그가 중간에 깨진다. "DatDaData: 123" 버퍼가 덮어써진 거다. DMA 전송이 끝나기 전에 다음 sprintf가 들어간 거다. "플래그 체크를 해야 하나?" if(uart_dma_ready) { sprintf(log_buffer, ...); HAL_UART_Transmit_DMA(...); uart_dma_ready = 0; }이것도 완벽하지 않다. 로그가 누락된다. 링 버퍼를 만들어야 하나? 지금 11시인데? 또 다른 버그의 발견 DMA 설정하면서 메모리 맵을 보다가 이상한 걸 발견했다. .bss 영역이 생각보다 크다. 40KB. 전역 변수를 확인해봤다. uint8_t rx_buffer[32768];누가 이렇게 큰 버퍼를 전역으로 잡았지? 커밋 히스토리를 뒤졌다. 3개월 전, 나였다. "당시엔 급했으니까..." 근데 이게 문제다. 이 버퍼 때문에 SRAM이 부족해서 힙 할당이 실패하고 있었다. 그래서 가끔 센서 초기화가 안 됐던 거다. printf 찍다가 발견한 완전히 다른 버그. 이거 고쳐야 한다. 지금. 밤 11시 반. 커피를 내렸다. 네 번째. 스택 오버플로우 검색 "uart dma buffer overwrite" 검색했다. 스택 오버플로우에 똑같은 질문이 있다. 2016년. 답변: "Don't use sprintf with DMA. Use a queue." 큐를 만들라고? 지금? 다른 답변: "Just use ITM/SWO for debugging." SWO? 그게 뭐지? 검색했다. ST-Link로 디버그 메시지를 보내는 기능이래. printf처럼 쓸 수 있는데 UART를 안 쓴다. "진작 알았으면..." 설정 방법을 찾아봤다. CubeMX에서 SYS 설정을 바꾸고, 스크립트를 추가하고... 30분 걸렸다. 안 된다. "지금 SWO 배우고 있을 시간이 아니지." 그냥 printf로 돌아갔다. 최소화해서 쓰자. 로그 레벨 구현 정신을 차렸다. 제대로 해야 한다. 간단한 로그 시스템을 만들었다. typedef enum { LOG_ERROR, LOG_WARN, LOG_INFO, LOG_DEBUG } log_level_t;log_level_t current_log_level = LOG_WARN;void log_print(log_level_t level, const char* fmt, ...) { if(level > current_log_level) return; char buffer[128]; va_list args; va_start(args, fmt); vsnprintf(buffer, sizeof(buffer), fmt, args); va_end(args); printf("[%d] %s", HAL_GetTick(), buffer); }이제 LOG_DEBUG는 릴리스 빌드에서 안 찍힌다. 중요한 것만 LOG_ERROR로 남긴다. 30분 돌려봤다. 괜찮다. 1시간 돌렸다. 문제없다. "이제 됐나?" 새벽 1시. 긴 테스트를 돌려놓고 화장실 갔다 왔다. 로그를 봤다. [ERROR] Sensor timeout "...또야?" 타이밍 문제의 본질 로그를 자세히 봤다. 패턴이 있다. 센서 타임아웃이 발생하는 시점마다 UART 로그가 몰려 있다. 아, printf가 많이 찍힐 때 센서 폴링이 늦어진 거다. 근본적인 해결책은 하나다. RTOS 태스크 분리. 센서 읽기는 우선순위 높은 태스크. 로그는 우선순위 낮은 태스크. "지금 RTOS 도입할 거야?" 양산까지 2주 남았다. 일단은 printf를 더 줄이자. 센서 읽는 부분에선 아예 안 찍자. 에러만 간단히. if(sensor_error) { error_count++; // printf 안 찍음 }나중에 error_count 값만 주기적으로 찍는다. // 10초마다 한 번 if(HAL_GetTick() - last_log_time > 10000) { log_print(LOG_INFO, "Errors: %d\n", error_count); last_log_time = HAL_GetTick(); }돌려봤다. 타임아웃이 안 난다. 새벽 1시 반. 드디어 해결된 것 같다. 문서화 코드에 주석을 달았다. // WARNING: printf는 블로킹. 센서 루프에서 사용 금지 // 로그 필요시 log_print() 사용 // 긴급 디버깅 시에만 printf 직접 사용그리고 위키에 정리했다. 펌웨어 디버깅 가이드printf는 최소화할 것 타이밍 크리티컬한 코드에서 로그 금지 DMA 사용 시 버퍼 오버라이트 주의 긴 테스트는 로그 레벨 낮춰서내일 팀원들한테 공유해야지. 아니, 오늘이네. 벌써 새벽 2시. "집 가자." 보드 전원을 껐다. 가방을 챙겼다. 모니터를 끄려는데 슬랙 알림이 왔다. 김 대리: "형 아직 있어요?" 나: "지금 퇴근" 김 대리: "저도요 ㅋㅋ 수고하셨습니다" 계단을 내려갔다. 경비실 아저씨가 놀란 표정으로 보신다. "아직도 일해요?" "네, 마무리하고 가는 길이에요." "고생이 많네. 조심히 가요." 밖은 추웠다. 11월 새벽 공기. 원룸까지 걸어가면서 생각했다. printf 하나 제대로 못 쓰는 게 펌웨어 개발이다. 웹 개발자들은 console.log 마음껏 찍잖아. 브라우저 콘솔에 다 나오잖아. 우린 printf 하나에 타이밍이 깨지고, DMA 설정하고, 버퍼 관리하고. "그래도 재밌긴 해." 집에 도착했다. 2시 10분. 샤워하고 침대에 누웠다. 내일... 아니 오늘 출근은 10시에 해야지. 눈을 감았다. 머릿속에 printf 로그가 스쳐 지나간다. [INFO] Sleep mode enteredprintf 디버깅. 간단한 것 같지만 절대 간단하지 않다. 내일도 또 찍겠지.