2009년 6월 7일 일요일

디버깅은 근성이다!!!

개발을 하다보면 문제의 원인을 찾지 못해 문제를 바로 해결하지 못하고 짧게는 며칠에서 길게는 몇 달 씩 고생하는 경우가 생기곤 한다. 최근 1년동안에는 두 번 정도 이런 문제에 발목을 잡혀 여러날을 맘고생하며 보내야 했다. 먼저 부딪친 문제는 플래시 메모리용 파일 시스템이 망가지는 문제였고, 이 문제가 해결되고 몇 달이 지나지 않아 메인 어플리케이션이 SIGSEV로 terminated 되는 문제가 발생하였는데, 프로그램이 죽는 위치가 직접 작성한 코드가 아니라 Rose RT가 제공하는 코드고, 직접 재현이 불가능하고 바다건너 미국에서만 발생한다고 하여 도무지 디버깅을 하기 쉽지 않은 문제였다. 두 문제 모두 몇 달에 걸친 디버깅 과정끝에 다행이 원인을 찾을 수 있었지만, 문제를 찾은 후 좀 더 빨리 문제해결하지 못한것에 대한 아쉬움이 남는다.

문제를 해결하기위한 첫번째 과정은 문제를 재현하는 것이다. 문제 재현, 이것이 문제 해결에 가장 중요한 항목이지만, 실제 개발중에는 여러가지 이유로 문제 재현이 용이하지 않는 경우가 발생하곤 한다. 따라서 재현이 잘 되지 않는 문제가 발생하면, 해결하는데 오랜 시간이 걸리는 골치거리로 자라날 가능성이 크다. 따라서 문제 재현이 어려울 경우에는 문제를 재현하는 방법을 찾는 것이 문제를 해결하는 것이 된다.

앞에서 언급한 두 문제 모두, 역시 해결의 열쇠는 "문제 재현"이었다. 첫번째 문제는 수만대의 제품이 시장에 팔려나간 상태에서 한달에 한번꼴로 문제 발생이 보고 되었지만 개발실에서는 좀처럼 문제를 재현시킬 수 없었고, 두번째 문제는 테스트 벤치에서는 발생하지 않고, 멀리 미국에 서만 재현되는 문제였다. 결국 두 문제 모두 결국 문제를 재현할 수 있는 환경이 갖추어진 후에야 해결되었는데, 이 과정에서 적잖은 근성을 소모해야 했다.

운동 선수만 근성이 필요한게 아니다. 개발자들에게도 직장인에게도 근성이 필요하며, 적절한 실력을 인정받기 위해서 꼭 필요한 요소중의 하나로 감히 근성이 한자리를 차지할 것 같다. 사람들이 어려운 문제에 이르렀을때 이를 해결해 나가는 저마다의 노하우가 있지만, 때론 자신의 지식으로 바로 해결할 수 없는 문제에 부딪치게 된다. 이때 문제를 해결하는 열쇠는 다름아닌 "근성"이다. 근성이 없는 사람은 여러가지 핑게를 대며 문제를 회피하거나 외면하는 수순에 들어가게 되는데, 이때 그들은 나약함과 비굴함을 얼핏 밖으로 비치기도 한다.

사람을 평가할 때 사용하는 중요한 지표로 attitude, 즉 태도를 사용하는데, 근성이 여기에 포함될 것이다. 즉 실력있는 사람으로 인정받기 위해서는 근성이 중요하다는 말이다. 박지성이 높이 평가받는 이유도 "근성"이 아닐까? 물론 근성만있고 문제 해결을 못한다면 문제가 있지만, 근성이 있는 사람이 문제 해결을 위한 지식을 쌓아왔을 가능성이 더 높지 않을까 ?

앞에서 말한 골치거리 문제들을 해결할 때도 "근성"이 나의 친구가 되어 주었다. 아래에 나와 나의 친구 "근성"이 어떻게 문제를 해결했는지 정리하고자 한다.

첫번째 문제는 수만대의 제품이 풀린 시장에서 한달에 한번정도만 보고되는 재현 빈도가 낮은 문제였다. 하지만 문제가 꾸준히 발생하고 있었고, file system이 corrupt되면 그 이 후 정상적으로 시스템을 사용할 수 없었기 때문에 꽤나 치명적인 문제였다.

우리는 당연히 file system이 깨지는 것은 flash device driver나 file system library에 문제가 있는 것이라고 생각했지만, OS업체는 해당 driver와 library가 여러 업체에서 사용하지만 문제가 거의 보고된 적이 없기 때문에 s/w문제 보다는 flash device의 불량일 것이라고 추정하며 책임을 회피하고 있었다.

당연한 수순으로, 문제 재현을 위해 우리 프로그램의 파일 접근 과정을 시뮬레이션하는 작은 테스트 프로그램을 만들어 며칠씩 반복해서 돌려보았지만 문제를 재현시킬 수 없었다.

결국 문제를 해결하기 위해서 캐나다에 있는 OS개발 업체로 우리측 개발자 3명이 파견되었고, OS개발 업체 개발자 2명 및 여러명의 테스터가 할당되었다. 우리 개발자들이 우리쪽 s/w의 file access 하는 디자인을 OS쪽 개발자들에게 설명하여 주고, 반대로 OS쪽 개발자들도 flash device driver와 file system 구현 코드를 우리에게 설명하여 주었다. 재미나게도 우리는 서로 상대방의 프로그램에서 문제를 찾아내는데 집중하였다. (자신이 더 잘 알고 있는 자신의 코드에서 문제를 찾아내는게 더 쉬울것임에도 불구하고...)

상호 프로그램에 대한 디자인 리뷰를 통해서 서로의 시스템을 대강 이해하게 되었다. 하지만 그 정도로 복잡한 s/w내에 잠자고 있는 문제를 찾을 수는 없었다. 이러면서 몇달이 흘러갔고 결국은 디버깅용 출력 코드를 삽입한 바이너리를 여러개의 제품에 넣어 expose 테스트를 하며 문제가 재현되기를 기다리기로 하였다. 그러나 문제가 몇 대의 테스트 제품에서 재현되기에는 너무 발생 빈도가 낮았고, 문제가 재현되어도 디버깅용 출력 코드가 충분한 정보를 제공한다는 보장은 어디에도 없었다.

해결의 실마리는 의외로 엉뚱한 곳에서 나왔다. 해당 제품을 함께 개발한 다른 개발자들과 파일 접근 관련 경험을 문답하던 중 마지막 데이터 몇바이트를 유실하는 경험을 한 프로그래머가 있었는데, 마침 유실되는데이터가 꼭 필요한 데이터가 아니었기에, 아예 그 데이터를 저장하지 않는 방법으로 문제를 피해갔다는 것이었다. 그리고나서 나중에 자신이 알아낸 것은 fclose()를 하지 않고 프로그램을 종료시키면 문제가 발생하는 것 같다는 정보도 함께 주었다.

확인 결과 fclose()를 호출하지 않으면 프로그램 종료시 마지막에 저장한 몇바이트 정도가 유실 되었고 이는fclose를 호출하지 않으면 flash write cache의 내용이 file system에 commit되지 않는 것으로 추정되었다. 하지만 이 경우 유저 데이터만 유실될 뿐 file system에는 문제가 없었다.

하지만, 뭔가 이런 오동작과 이번 문제가 관련이 있을 것만 같아 이전에 작성한 시뮬레이션용 프로그램을 fclose를 하지 않도록 수정하여 프로그램을 돌렸고, 채 1분이 지나지 않아서 거짓말 처럼 해당 문제가 재현되었다.

문제를 재현하는 테스트 프로그램을 OS업체에 보내자 OS업체는 하루만에 문제를 해결한 flash filesystem driver를 보내왔다. 문제는다소 복잡한 조건하에서만 발생하였는데, fclose()를 빼먹는 것이 필수 조건이었다. OS는 프로그램 종료시 어플리케이션이 사용한 모든 자원을 안전하게 반납하여야 하기 때문에 fclose() 하지 않아도 이를 안전하게 처리해 주어야 하지만, flash file system의 버그로 문제가 발생한 것이었다.

해당 문제는 거의 몇개월이나 걸려서 해결이 되었고, 문제 해결에 대한 성취감도 대단하였다. 문제를 해결하기 위해서 여러가지 과거의 경험이 총 동원되었지만, 모두가 문제 해결에 지쳐가고 회의적으로 생각하는 시점에서 계속 문제 재현을 시도했던것은 나의 친구 "근성"이었던 것 같다.

더 빨리 문제를 해결하지 못한것에 대한 아쉬움이 어쩔수 없이 내 뒤에 붙어있다. 하지만 아이러니한 것은, 문제가 오래끈 만큼 해결에 대한 주위의 인정이 커졌다는 것이다. 문제를 손쉽게 해결하였다면 누가 알아주었을까?


두번째 문제는 미국의 테스트 환경에서만 발생하는 문제였다. 재현도 최소 30분~ 2시간 정도가 필요한 것으로 보고가 되었고, 한국에서는 재현이 전혀 되지 않았기 때문에, 몇 달동안 별다른 분석을 할 수 없었다.

매주 고객은 업데이트된 보고서를 요청하는데, 미국에서 테스트한 결과 자료만 가지고는 도무지 원인을 찾을 수 없었다. SIGSEGV로 terminated될 때 출력되는 IP주소를 map파일에서 추적하여 문제 발생 함수명을 찾았지만, 해당함수는 Rose RT쪽 코드로 상용으로 널리 사용되는 부분이라 문제가 발생할 가능성이 아주 적은 곳이었다. 미국에 상주하는 테스트 팀에 요청하여 문제 발생시 core file을 dump하여 문제 발생 위치를 뒤진 결과 스택에 있는 포인터 변수에 이상한 주소 값이 들어가 있어, 해당 포인터 변수에 접근시 SIGSEGV가 발생하는 것이 확인 되었다. 하지만 core file에서 memory를 dump해 보아도 stack overflow의 흔적은 찾을 수 없었고, 해당 변수에 이상한 값이 들어가 있었다. 프로그램의 어디에선가 포인터를 잘못 사용한 것으로 추정되었지만, 수십만 라인의 코드에서 해당 위치를 찾기란 불가능에 가까웠다.

결국은 문제가 재현되는 미국으로 출장을 갈수 밖에 없었고, 출장을 와서도 특별히 뾰족한 수가 있는 상황이 아니었다. 최후로 선택한 방법은 divide and conquer로 프로그램내의 어플리케이션 모듈을 하나씩 실행되지 않도록 수정하여 재 컴파일 하고 이를 실행하여 문제 발생 여부를 테스트 하였다.

오랜 시각의 재현 테스트(한번에 40분정도 걸리는...) 끝에 18번째 재현 테스트만에 GPS관련 application을 disable하였을 때 문제가 발생되지 않음이 확인되었고, 해당 모듈을 디자인 리뷰한 결과 해당 프로그램 코드에서 구조체의 항목중 배열로된 어떤 항목을 사용하면서 배열의 index를 무한히 증가시킴을 확인하였다. 따라서 구초체 크기만큼씩 건너뛰면서 메모리에 값이 덮어써졌고, 이 과정이 20분정도 반복되면 그때가 되서야 시스템이 SIGSEGV로 죽었던 것이다.

이 문제를 발견하기 위해서 한국에서 내가 알고 있는 모든 급 디버깅 기법을 사용하여 문제를 분석하였지만, 전혀 문제의 핵심에 접근하지 못하였다. 메모리 오류를 잡아주는 각종 디버깅용 라이브러리를 사용하여 미국에 테스트를 요청하여도 전혀 문제는 검출되지 않았고, 결국 문제 해결은 문제가 재현되는 환경에서 "노가다"에 가까운 반복 재현 테스트로 문제 발생 원인을 좁혀가는 과정을 통하여 이루어졌다. 다행이도(?) 문제가 한시간 안에 한번은 재현이 되었기 때문에 이러한 방법이 가능하기는 했지만, 그래도 여전히 지난한 과정이었고 "근성"으로 이를 진행할 수 밖에 없었다.

(개발 환경이 리눅스등의 환경이었으면 좀 더 강력한 메모리 오류 검출 툴들을 사용해 볼 수 있었겠지만, 애석하게도 이런 툴이 돌아가지 못하는 환경이었다. )

아마도 문제 재현이 더 어려원다면, 문제를 더 자주 재현시키는 다른 방법을 찾아야 했을 것이고, 이는 더욱 지난한 과정이 되었을 것이다. 이런 경우가 발생하지 않은 걸 신에게 감사할 수밖에...