printf와 시스템 성능 그리고 UART baud rate

CPU 사용율이 높지 않음에도 불구하고 이유없이 프로그램 수행 속도가 극도로 느려지는 문제가 발생. 예상되는 원인은 과다한 로그 출력. 임베디드 환경에서는 로그 출력이 UART를 통하여 이루어 지는 경우가 많은데, 이 때 UART의 baud rate이 프로그램 동작의 병목으로 작용하는 것이다. 비록 버퍼가 있다고 하지만, 로그양이 버퍼양을 넘어서면 printf등의 함수도 바로 리턴하지 못하고, 대기할 수 밖에 없을 것이다.  하지만 로그가 많다고 무턱대도 이를 줄이는 것도 쉽지 않은 일이다. 각각의 로그는 각 개발자들이 문제 발생을 확인하고 해결하기 위하여 최적화하여 넣어놓은 것으로 이를 제거하면 나중에 디버깅이 어려워지거나 불가능해 지기 때문이다.

가설 검증을 위해 로그 출력에 사용되는 stderr/stdout용 serial(UART)장치 즉 /dev/ser1의 baud rate을 올려보았다. 문제 해결!!!  수정된 이미지를 배포하지만 얼마 지나지 않아서 생산기술에서 연락이 온다. Baud rate 변경으로 인해 생산 테스트 장비를 모두 바꿔야하고, Baud rate 상승으로 인한 통신 에러 증가가 예상되어 절대로 Baud rate를 변경하면 안된단다.   다시 원점.

Baud rate이 115200 bps라면 대충 계산해도 115,200/8=14,400 character 이상의 로그는 (1초에)출력이 불가능하다. 실제로는 UART 전송 시 설정에 따라  Start/Stop bit 및 1 char당 bit수 그리고 char간 delay 등을 고려해야하고 이 경우 실제 전송 가능한 char수는 14,400보다 훨씬 적어지게 된다.

따라서 Baud rate을 올리는 방법으로 문제 개선이 가능하지만, 예상치 못한 문제로 인하여 Baud rate는 올리지 못하는 것으로 결론.

어림 계산으로 1초에 10,000 글자가 전송 가능하다고 하고, 라인당 100글자를 넘지 않는다고 하면, 1초에 100줄 정도의 로그가 출력 가능. 로그가  1초에 100줄이 넘지 않는다는 가정하에 로그 출력을 담당하는 전담 thread를 만든다면 다른 thread는 baud rate과 상관 없이 동작 가능할 것 이다.

로그를 출력하는 매크로를 사용하여 printf 대신 매크로를 사용하여 메모리에 로그를 기록하고, 메모리는 mutex로 보호한다.  로그 출력 thread에서는 계속해서 메모리에서 로그를 읽어와 puts로 출력하도록 하여 문제 해결. (단 1초에 100줄 이상의 로그가 지속적으로 발생한다면, 로그용 메모리 버퍼가 full나면서 mutex block이 걸리는 시간이 늘어나 다시 시스템 성능이 느려질 수 있다. )