프로그래머의 일상: IRQ 충돌

오늘 퇴근이 한 시간 가까이 늦어진 건 몇 주전의 일도 제대로 기억 못하는 내 기억력 탓 Orz.

퇴근시간 즈음해서 오늘 받은 머신의 MAC 주소가 등록되었나 확인하고 설정 시작.

  • BIOS에서 네트워크 부팅을 활성화하고
  • 어째서인지 secondary LAN card인 intel GBE도 네트워크 부팅하려 시도하길래 끄고
  • OS 설치한 후
  • 네트워크 설정 확인하고 필요한 팩키지들 설치 시작
  • ?!
  • Secondary LAN card로 통신 불가
  • tshark 으로 덤프 떠 봐도 뭐 보이는 거 없음
  • 재 부팅하고 재시도 (…)
  • 스위치에서 포트 바꾸고 재시도 (…)
  • (결국) syslog/dmesg 보기 시작
  • 수상쩍은 irq 충돌 메시지

흑흑, 대략 2주? 전에 있었던 비슷한 머신 설치 때 당한 게 떠오름. 그 때와 똑같은 방식으로 해결한 얘기를 하자면:

원인

nvidia graphic card (GTS240?) 와 intel gigabit ethernet card (pci interface) 가 IRQ 충돌 중. grub의 부팅 옵션에 irqpoll 주고 띄우니 잘 돈다. tshark 붙인 순간 떨어지는 cisco router의 이런저런 메시지들을 잔뜩 보고 퇴근했다 ㅠㅠ.

해결책 + 교훈

위에서 말한 것처럼 boot loader 옵션에 irqpoll을 주는 것.

근데 이거 약간의(?) performance penalty가 있…을 듯 하다. IRQ를 IRQ답게 처리 하는 게 아니니 Orz. 게다가 이거 gigabit ethernet에 물려서 특정 프로세스의 네트워크 성능 테스트하려고 한 건데 아무래도 망한 듯; 아니면 기왕 이렇게 된 거 서버에서 그래픽 카드들 다 떼버릴까. 내장 그래픽 카드가 있는지 확인하고 해봐야 ㅠㅠ.

dput (sftp) + inotify = FAIL

내부적으로 사용하는 apt 저장소에서는 dput이 incoming으로 올린 데이터를 crontab 을 이용해서 실제 배포용 디렉터리에 복사하고 / .db 업데이트하고 / … 등을 처리하게 했다.

crontab을 써서 사실 상 polling하는 구조가 맘에 안들어서, linux의 inotify를 이용해서 이걸 우회하려고 지난 주 후반부에 뭔가 진행해봤다.
대략 chroot jail에 sftp만 허용한 계정을 만들고 여기에 대해서 upload를 감지하자는거였는데 대략 다음과 같이 진행했다.

  1. scp로 업로드한 파일을 inotify가 인지하고 이에 대해서 처리하는 코드 테스트 (정상 작동)
  2. sftp 로 업로드한 파일에 대해선 inotify가 인지못하고(…) crontab이 처리
  3. ?!?!?!

…3의 대혼란.

 

intoify를 래핑한 inoticoming 를 사용했는데, 코드를 까보니 주석처리된 디버깅 코드가 있더라; 이걸 주석해제하고 돌려보니 아뿔사 -_-

scp와 sftp를 순차적으로 썼을 때 inoticoming이 호출한 inotify에 걸린 이벤트는 아래와 같다.[1]

rein@rein:~/inoticoming-0.2.2/build$ ./inoticoming --foreground /tmp/test --suffix .changes echo {} \;
File ready: python-stdeb_0.6.0+git-1_all.deb
File ready: stdeb_0.6.0+git-1_amd64.changes
Will call action echo for: stdeb_0.6.0+git-1_amd64.changes
stdeb_0.6.0+git-1_amd64.changes
File ready: python-stdeb_0.6.0+git-1_all.deb.tmp.1338036938.225992918.7760.688775960
File ready: stdeb_0.6.0+git-1_amd64.changes.tmp.1338036944.455483913.7760.1022155507

dput이 sftp를 통해 업로드할 때 대략 다음과 같은 일을 한다:[2]

  1. 위에서 나온 임시 파일 형식으로 파일 업로드; bzrlib/transport/sftp.py:SFTPTransport._put
  2. 업로드가 끝나면 임시 파일을 실제 이름으로 link + 임시 파일 unlink; bzrlib/osutils.py:fancy_rename

…그래서 inotify는 이걸 인지할 방법이 없다.

대략 chroot jail에서 scp만 허용하는 쪽으로 바꿔야 할 것 같다. 아니면 dput 말고 딴 걸 쓰거나; 근데 내가 왜 sftp만 허용하는 걸 생각했는지 기억이 나질 않는다 Orz.

  1. python-stdeb는 임의로 가져온 python package다. setup.py가지고 .deb을 빌드할 수 있게 해준다 []
  2. 정확히는 dput이 사용하는 bzrlib/transport/sftp.py 가 하는 일이 그렇다 []

NDC 참관기: 덤프 파일을 통한 사후 디버깅 실용 테크닉

슬라이드는 “NDC2012 덤프 파일을 통한 사후 디버깅 실용 테크닉“에서 볼 수 있음.

넥슨 김이선 님의 발표.

내용 요약:

돈을 벌기 전에는 배포 전 디버깅이 중요하다.
라이브 상황에서는 배포 후 디버깅이 더 중요해진다.

덤프 파일

특정 상황 — 특히 안좋은 상황 — 에서 프로세스 상태를 디버깅 용으로 남기는 것.
풀 메모리 덤프를 남기면 좋지만 커서(…) 미니 덤프를 남긴다.
상용 서비스까지 갔다면 미니덤프를 남기고 이를 수집해서 디버깅하는 시스템은 필수.

하지만 미니 덤프 디버깅의 현실은…

  • 덤프 파일을 열었는데 심볼이 없다고 어셈블리 코드가 보이는 경우
  • 여기서 죽으면 안되는데 왜 죽었나 싶은 경우?
  • 콜스택이 깨졌다거나
  • 풀 메모리 덤프를 남겼는데 내가 보려는 객체는 어디에?

덤프 파일과 pdb 파일 연결하기

  • 미니덤프 헤더는 RSDS 헤더, GUID, age, pdb-path 등이 들어감
  • pdb, exe, minidump는 이 GUID로 연결된다
  • 심볼서버는 당연히 써야
  • 보안 솔루션 (더미다 류) 을 사용하면 덤프 파일의 GUID가 바뀐다
  • 하지만 COFF file format의 링크 시간을 기록한 타임 스탬프는 유지
  • 클라이언트 덤프 수집단계에 미니덤프와 해당하는 PDB를 맺어주는 단계를 넣자(클라이언트 버전 정보; 타임 스탬프를 이용해서)

여러 개의 덤프 파일을 분석할 때

일어나지 않을 것 같은 일도 덤프 파일이 많으면 분석할 수 있음[1]

  • 분류 기준으로 EIP, callstack, 게임에 따른 정보(맵, 장비, …)
  • 외부 모듈이나 말이 안되는 곳이면 어떻게하지? 클라는 환경을 통제할 수 없으니 외부 변수를 추적한다
  • EIP와 다른 변인 (OS, CPU, GPU) 등을 보면 예상되는 것과 다른 분포인 경우가 있다 (=환경 편재)
  • OS라면 드라이버 버그, CPU의 문제 (보통은 mainboard), GPU 문제, 외부 모듈 (보안 프로그램이나 해킹 툴)

사례 분석

 

  1. DF의 코드 베이스를 VS 2003에서 VS 2008로 이전함.
  2. 특정 유저 (소수) 에서 채널 선택하는 순간 HeapAlloc/HeapFree 중에 크래시 하는 버그 발견
  3. Heap-corruption이라,
    • 게임 시작에서 채널 선택하는 부분까지의 코드를 리뷰
    • 이 영역에 많은 수의 trap code와 HeapValidate 코드 삽입
    • 하지만 문제는 발견되지 않음
  4. 모듈 목록에 환경 편재가 있음: BFCO0GAF.dll 등의 알파벳/숫자가 섞인 특정 패턴의 모듈 발견
  5. 해당 dll이 악성 프로그램이 삽입한 것; 2003과 2008의 heap 구현이 달라서 생긴 일

콜 스택이 깨지는 경우

  • EBP, ESP 중 하나만 깨져도 콜 스택을 복원할 수 없다
  • 이를 다음 휴리스틱으로 극복
    1. 스택 메모리에서 주소를 추려낸다 (모듈 정보의 주소 영역을 이용해서)
    2. 스택 메모리에서 스택 주소를 추려낸다
    3. 1 + 2를 해서 콜 스택을 추정
  • 프로그래머의 해석이 필수

힙 메모리 문제

  • 메모리 덤프가 있으면 디버깅에 큰 도움이 된다
  • 하지만 모든 메모리 객체에 접근하는 건 쉽지 않음
  • 메모리를 exhaustive하게 검색
  • vfptr 값 이용
  • typeid(T)의 구현 형태를 이용해서 타입 이름을 이용해서 검색

이걸 포함한 오픈소스 툴을 공개

 

 

감상:

이번에 네 개 세션 밖에 못들었는데, 그 중 제일 괜찮은 강연이었다. 다음 세션을 회사 돌아갈 시간이라 못 들은게 아쉬움.

내가 예전에 했던 유사한 시도는 통계적으로 분류하고 / 적당한걸 찾을 수 있게 도와준다 정도였는데 (VS 안띄우게 하는게 목표였으니..) 이렇게 실제 사례를 바탕으로 한 내용을 알고 있었다면 훨씬 좋게 할 수 있었을 듯.
그리고 바이너리가 수정된 경우의 처리는 제대로 못했는데 — ipkn 패치해서 돌아가게 수정 — 이 부분에 대한 정보도 얻게 되어서 좋았다.

게다가 강연자 분이 “이런거 되는걸 모아서 새로 짜서 공유했습니다”라고 말한건 대박(…).
아마 `지식 공유’란 점에서 모델이 될만한 수준.

summerlight 님이 녹화한 영상도 토런트 시딩되고 있을테니 (촬영 가능한 세션이었음) 관심 생기신 분들은 한 번씩 보는걸 추천합니다.

  1. 이건 이전 회사에 있을 때 내가 포스트모텀 디버깅, 그것도 최대한 많은 수를 수집해야 한다고 주장한 이유와 같음 []

디스크 공간이 부족하다

작년 가을에, Google BreakPad를 써서 크래시 덤프를 보낼 수 있겠다고 썼다. 여하튼 이걸 위해 간단한 웹 서비스를 만들었었다. 팀 내에서 이걸 쓰다가 좀 확장해서 (…) 같은 스튜디오 내의 다른 팀에도 약간 적용했음. 대략

  • 매일 매일 얼마나 많은 덤프가 나오는지,
  • 가장 많이 발생한 원인 (WinDbg의 버킷 비슷한 것) 은 뭔지,
  • 같은 원인으로 죽은 덤프는 어떤지,
  • 각각의 덤프 별 콜 스택 플랫폼 정보 (OS 버전, 각 모듈 별 버전) 는 어떤지

가 나오는 페이지를 만들었다.[1] 아니 근데 생각지도 못했던 문제를 만났다;

여름에 서버를 설치한 후, 총 3개 팀이 사용하게 했고, 이에 따라 차근차근 크래시 덤프가 쌓여간다. 최근 덤프가 좀 무섭게 쌓여서 (…) 디스크 사용량을 추적해봤더니 대략 이런 결과가; (8월 중순 쯤 서버를 리셋했고, 그 이후의 디스크 사용량)

cr3

팀 + 1개 팀 상태에서는 참 완만하게 올라갔는데 (…), 좀 덩치 큰 다른 팀까지 적용했더니 순식간에 하드디스크가 차고 있다; 게다가 기울기가 더 올라가서, 현재 Doomsday는 다음 달 중순까지 당겨진 상태 Orz. 개발 중인 프로그램에 적용한 것이고, 개발 팀만 접근 가능한 위치라 전체 메모리 덤프를 받게 했더니 정말 저장 공간을 왕창 잡아 먹더라; 이건 내 예상 실패라고 밖엔;

HDD 가격 올랐다고 구매 신청해도 안 사줄 기세던데 이를 어찌 해결하는가; 일단 같은 콜 스택 + 같은 모듈 (이름; 버전; 체크 섬) 인 것들 지워서 지난 주 후반에 40 GiB 쯤 확보했는데, 그럼에도 불구하고 (…) 이미 216 GiB 쯤 쓴 상태. 사진은 2주 전 상태임.

 

저 서버를 설정할 때만 해도, 연말까지 300 GiB 정도는 넉넉하리라 생각했다[2] 하다못해 HDD 하나 추가하는 건 별 큰 일 아니라고 생각했다. 하지만 태국 홍수 덕에 구매 팀에서 HDD 가격 비싸다고 장비도 안 사주는 마당이니, 망한 상황인 듯. 아마 1월부턴 90일 정도만 남기고 – 어차피 개발 중인 프로그램들 용으로 덤프 받는 서버라 버전 정보가 휙휙 올라가는지라; – 다 지워버리던가 해야.

사실 내가 궁금한 건 이거다; 과거의 덤프가 남아있다면 뭐가 좋을까? 그냥 간단한 텍스트 정보 – 크래시 한 상황에 대한 OS 정보, 콜 스택 정도가 있다면 충분할까? 아니면 전체 메모리 덤프가 다 있다면 오~래 가는 버그를 좀 더 쉽게 잡을 수 있을까?

원래 목적이던 “자주 발생하는 버그를 빨리 잡자”는 어느 정도 되어가는 것 같은데 – 일주일쯤 피크 치는 버그는 대충 잘 잡히는 듯? – 오래된 버그를 잡는데 도움이 되려면 어느 정도 범위를 가지고 있어야 할지;;;

PS. iPhone 4 렌즈 수차 정말 망이네; 화면 위 아래 수평선의 기울기를 비교해보면 Orz (…).

  1. 실제 페이지 구현은 회사에서 만든 부분이라 여기서 공개하는 건 무리 []
  2. 즉, 한 달에 50 GiB 이상은 안 나오겠지 정도로… []

VS 2010 소스 서버 설정과 홈 디렉터리 문제

최근에 받은 머신에서 크래시 덤프 디버깅 하다 겪은 일.

VisualStudio 2010에서 포스트모텀 디버깅[1] 할 때 심볼 서버, 소스 서버를 이용해서 디버깅하는데, 얘가 소스 서버에서 파일을 안 가져온다. 그래서 내가 추적한 순서 (…)

svn.exe 가 있는가 – 없으면 svn.exe cat … 이 실행 안될테니

심볼 서버 접근이 잘 되는가 – 안 그러면 .pdb 에서 소스 리스팅을 못할테니

.pdb에 소스 정보가 없는가 – …없으면 못 찾아올테니

…여기까지 했으니 전부 아니었음. .pdb도 잘 가져오고, 거기에 소스 인덱싱된 것도 있고, 거의 똑같은 설정의 다른 머신에선 디버깅 잘 되더라고 Orz

 

관리자 모드로 VS 2010을 재실행하고 나니 원인이 보이더라. 유저 홈 디렉터리를 d:\Users로 옮겼는데, 소스 서버 데이터를 c:\Users\rein\AppData\… 에 저장하는 것. 이전에는 일반 유저 권한이라 c:\Users 밑에 뭔가 못 만들어서 svn.exe cat이 실패한 모양. 이유는 모르겠지만, VS2010은 저 설정이 거의 하드 코딩되어 있거나, 홈 디렉터리 위치를 c:\에서 d:\로 바꾸려고 레지스트리에서 바꾼게 불충분한 모양.

좀 더 이유를 아시는 분은 설명 좀 (굽신굽신)

  1. 혹은 사후 디버깅. 크래시 덤프를 가지고 진행하는 디버깅 []

프로그래머의 일상: race-condition, 글쓰기, …

Race condition

5월 말에 예비군 훈련을 다녀오고나니 (…), 내가 작성한 C++/Win32 기반의 서버 런타임에 문제가 발생했더라. 정확한 요인은 모르겠지만, 메모리 사용량이 팍 뛰었고, 32bit 프로세스의 한계로 사망 -_-

다행히 ipkn이 작성한 부하 테스트 툴로 원인을 좁힐 수 있었다. 해당 프로세스에 미리 할당하는 소켓 수 이상으로,

  1. 연결을 계속해서 맺고
  2. 과다한 트래픽을 흘려보내고,
  3. 다시 끊고

…을 수 시간 반복하면 서버가 크래시하더라.

이미 수 개월 동안의 라이브 서비스 동안 별 문제 없어서 안정화 끝났다라고 생각했는데 그게 아니었던 모양.

처음 찾은 버그는 이런 거였다. 대략 소켓 래퍼 객체의 참조 카운트를 가지고 최종적으로 할당된 자원을 재활용하는데, 단 하나의 시나리오에서 이 패킷 버퍼와 소켓의 참조 카운트 해제하는 순서가 반대(…)로 되어있더라. 그래서 대략 k 시간의 코드 리뷰 후에 잡았음. 그나마 패킷 버퍼 쪽에서 문제가 되는 코어 덤프가 있었으니 Orz.

…그리고 이 상태로 다시 부하 테스트 시작. 또 죽는다? 다행히도 디버그 빌드에서도 재현이 된다. 문제는 heap corruption이라는 것? -_-;; 정확히 1 bytes가 0로 셋팅되더라.[1] 그래서 서버 런타임 전체에서 1바이트 세팅하는 코드를 전부 뒤졌다.
그 결과, 일부 per-thread 타이머 객체가,

  • 해당 스레드에서 타이머 객체가 종료되어 자원 해제
  • 다른 스레드에서 해당 타이머 객체 invalidate

하는 경우가 있을 수 있더라. 역시나 참조 카운터 문제 -_-; 선형화처리 코드는 들어가 있지만, 해당 객체가 살아있다는 보장이 없는 상황이라, 대부분 잘 돌지만(…) 이렇게 레이스가 일어나면 얼마든지 맛이 갈 수 있더라;

이 두 가지 문제 해결하고나니 대략 (눈에 보이는) 버그는 잡은 거 같지만…
일단 부하 테스트는 잘 버티고 있다.

…근데 애초에 문제가 되었던, 갑자기 메모리 사용량 1G 점프하던건 뭐였을까? 십중팔구는 처리가 늦어지고, 그에 따라 센드 큐가 늘어나고, 그에 따라 처리가 더 늦어지고(…) 하는 악순환의 결과였던 거 같지만 -_-;

만약 크래시 덤프도 없고, 디버그 모드에서 재현 못했으면 어쨌을지를 생각하니 좀 끔찍하긴 하구나 -_-;

글쓰기

역시 공대생을 위한 글쓰기 수업을 들었어야 했나 -_-;
내가 얘기하고자 하는 부분이 아닌 걸 계속 써야하나?

예전에 책 번역 할 때도, 영어보다 한국어 실력이 더 문제란 느낌이었으니 에휴.

  1. Win32 DEBUG heap이 마킹해주는 덕에 이건 파악할 수 있었다. 정말 다행임 []

WinDbg의 !analyze 가 강력한 이유

당연한 얘기지만, 그 만큼의 수고와 끊임 없는 개선이 따랐기 때문. 이미 10년이 넘은 이 툴은…

WER 팀의 작년 논문(작년 10월의 SOSP09, http://www.sigops.org/sosp/sosp09/papers/glerum-sosp09.pdf)에 따르면,

!analyze is roughly 100,000 lines of code implementing some 500 bucketing heuristics, with roughly one heuristic added per week.

!analyze 명령 (WinDbg)는 대략 십만 줄의 코드로 만들어져 있고, 이는 500 개의 버킷팅 휴리스틱을 구현한다. 그리고 개략적으로 매주 1개의 휴리스틱이 추가된다.

라 한다.[1]

프로그래머가 직접 실행하기도 하는 부분이지만(windbg !analyze), 이 부분은 WER 서비스의 백엔드 서버들도 수행하는 부분이다. 그리고 이 부분에서 계속적으로 사용되고, 결과를 측정하고(!), 이를 반영해서 새로운 휴리스틱을 적용하는 등의 개선이 있었기에 굉장히 훌륭한 디버깅 툴이 된 것.

 

PS. 저 논문 굉장히 재밌다. 세부 내용 말고도 WER 서비스의 개략적인 역사와 통계, 측정치만 봐도 개발자들은 매우 재밌게 볼 수 있음.

  1. 해당 논문 3.2절의 첫 문단 일부 발췌 []

추리소설에서 디버깅의 향기를 느끼기

추리소설 내지는 추리가 내재된 소설, 극, 드라마, 영화등을 볼 때 아주 높은 확률로 (프로그램) 디버깅의 향기를 느끼게 된다.

decadence in the rye의 “핀치의 부리”를 통해 간만에 읽은 셜록 홈즈의 구절들.

“Eliminate all other factors, and the one which remains must be the truth.” (4개의 서명, 1장)[1]

“How often have I said to you that when you have eliminated the impossible, whatever remains, however improbable, must be the truth?” (4개의 서명, 6장)[2]

“Data! Data! Data!” he cried impatiently. “I can’t make bricks without clay.” (너도밤나무 집의 모험)[3]

“It is impossible as I state it, and therefore I must in some respect have stated it wrong.” (프라이어리 학교의 모험)[4]

뭔가 오역과 비문이 난무하는 번역이 있지만 참아주실듯(…).

디버깅의 많은 경우,

  • 불가능한 경우를 제거하고 — 물론 그에 대한 증명/데이터가 있어야하고
  • 가능한 경우의 수를 모두 제거하고 — delta debugging?
  • 재현 가능한 증거(=데이터)가 있어야하고 — 반복적인 재현이 되야 뭘 하던가(…)
  • 가정을 의심할 줄 알아야

한다. 그런 면에서 “추리”와 참 닮아 있다.

ps. 비슷하게 의학(오락) 드라마 닥터 하우스도 비슷한 느낌을 잔뜩 준다. 다만 프로그램에나 가할 법한 실험을 인간에게 한다는게 좀 무섭지만[…]

  1. 모든 나머지 요소를 제외하고 나면, 남은 하나가 진실이다. []
  2. 모든 불가능한 것을 제외하고 나면, 남은 하나가 아무리 일어날법 하지 않아도 그게 진실이라고 내가 몇 번이나 말했었지? []
  3. 데이터! 데이터! 데이터! 그가 참을성없이 외쳤다. 진흙도 없이 벽돌을 만들 순 없다고! []
  4. 내가 말한대로 이건 불가능해. 그러니 내가 뭔가 잘못 “말한” 것임에 틀림없어 []