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이 걸리는 시간이 늘어나 다시 시스템 성능이 느려질 수 있다. )

Linux Vs QNX Neutrino 파일 디스크립터 관련

리눅스에서는 한 프로세스에서 파일 디스크립터가 할당 될 때마다 그 값이 증가하게 된다. 예를 들어 어떤 프로세스가 처음으로 파일을 open할 경우 3이 할당되며, 이후 4,5,6 순으로 파일 디스크립터가 할당되어 나간다. (0,1,2는 각각 stdin, stdout, stderr에 할당되어 있다) 프로그램이 실행하여 나가면서 파일이 close되는 경우 해당 파일 디스크립터가 반환되게 되는데, 파일 디스크립터가 할당 될 때에는 값이 항상 증가만 하므로, 중간에 반환된 이러한 파일 디스크립터들은 바로 재사용되지 않게 된다. 계속된 할당으로 파일 디스크립터가 사용 가능한 최대 값에 이르면 비로서 다시 0 부터 시작하여 반환된 파일 디스크립터를 찾아서 할당에 사용하게 된다.

최근에 경험한 바에 의하면, QNX Neutrino OS에서는 파일 디스크립터가 반환되면, 바로 다음 open 요청에 재사용되게 된다. 아마도 파일 디스크립터 할당 시, 항상 가장 작은 사용 가능한 파일 디스크립터를 반환하는 식으로 구현이 되어 있는 것으로 추정된다.  이 경우 user application의 상당한 주의가 요구된다. 만일 어떤 파일 디스크립터를 close 한 후에 실수로 한번 더 close를 할 경우, 두번째 close하는 파일 디스크립터가 이미 다른 thread에서의 open에 재사용되는 경우가 발생할 수 있기 때문이다. 이 경우 영문을 모른채 file이 open되자마자 close되어 버리는 문제가 발생하고, 이는 꽤 원인을 파악하기 어려운 문제가 된다.

리눅스에서는 파일 디스크립터를 계속 증가시키는 방법으로 이러한 문제를 영리하게 피해간 것으로 보이는데, QNX Neutrino에서는 관련해서 수정 계획이 없다고 하니, 계속해서 주의가 필요할 것으로 보인다.