서버 다운타임 분석 프로세스 1회 기록(1) - 문제 해결

다운타임 발견 & 코어dump 시작

최근 판서에 판본을 심사하는 데 쓰이는 서버는 며칠마다 다운되는데, 상황은 비교적 유사하다. 모두 로비복의 진행이 직접적으로 떨어지지 않았다.서버 로그를 보았지만 아무런 단서도 발견되지 않았습니다.서버 프로세스가 붕괴된 것으로 의심되어 서버의coredump를 열고 다음 다운타임이 gdb를 통해 문제가 어디에 있는지 확인하기를 기다립니다.

coredump가 잘못되었습니다.

며칠이 지나자 서버가 다시 다운되어coredump 폴더를 보았는데dump 파일이 생성되지 않았습니다.곰곰이 생각해 보니,dump 파일은 프로그램이 붕괴될 때만 생성됩니다. 그러면 프로그램이 붕괴되지 않았을 수도 있고, 다른 방식으로 종료되었을 수도 있습니다.

메모리 문제 의심

이때 메모리 문제가 생각되어 서버를 다시 시작한 후 서버 메모리를 보았는데 과연 서버 프로세스에서 어떤 서비스(서비스가 독립된 루아 가상 컴퓨터에서 실행됨)의 메모리 사용이 이상하다는 것을 발견했다.문제를 검증하기 위해 10여 줄의 코드를 쓴 C 프로그램은 끊임없이 메모리를 신청하고 방출하지 않는다.역시 프로그램은 시스템 메모리를 다 먹은 후에 깜박거렸고,coredump 파일이 생성되지 않았습니다.인쇄 메시지 남기기: Memor가 죽었습니다.

OOM 킬러 끌어내기

구글은 이 인쇄 정보를 살펴보니 linux에 OOM-killer (Out Of Memory killer) 라는 메커니즘이 있습니다.
OOMkiller는 시스템 메모리가 다 소모된 상황에서 터치하여 일부 프로세스를 선택적으로 제거하여 메모리를 방출합니다.OOM killer는 /proc//oom_score 이 값을 통해 어떤 프로세스가 삭제되었는지 결정합니다.이 값은 시스템 종합 프로세스의 메모리 소모량, CPU 시간(utime + stime, 생존 시간(uptime - start time과 oom_adj을 계산한 것으로 메모리 소모량이 많을수록 높고 생존 시간이 길수록 낮다.한 마디로 하면 전체적인 전략은 손실이 가장 적은 작업, 가장 큰 메모리를 방출하는 동시에 무고하게 큰 메모리를 사용한 프로세스를 손상시키지 않고 죽이는 프로세스 수가 최대한 적다는 것이다.
시스템 로그 파일 (/var/log/messages) 을 찾아 다음과 같은 정보를 확인하십시오.

Jul 27 14:54:11 iZbp1gq49eb2h8qr5ktv1gZ kernel: Out of memory: Kill process 1119 (test) score 865 or sacrifice child
Jul 27 14:54:11 iZbp1gq49eb2h8qr5ktv1gZ kernel: Killed process 1119 (test) total-vm:962016kB, anon-rss:903972kB, file-rss:80kB

역시 OOM-killer가 내 예시 프로그램을 죽였어. 그러면 로그에 서버 프로세스가 죽은 흔적이 있는 거 아니야? 로그를 계속 뒤져보면 또 몇 가지 의심스러운 정보를 발견할 수 있어.

Jul 23 20:48:33 iZ23n1006xeZ kernel: [17045726.198604] mongod invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
...

이 시간(Jul 23 20:48:33)에 인쇄된 정보는 매우 길다. 아마도 몬god가 OOM-killer를 촉발했다는 뜻이다.log에는 게임 서버 프로세스와 관련된 정보가 없습니다. 서버 프로세스도 Jul 23 시간 근처에서 끊겼습니다. 몬god가 OOM-killer를 터치하고 OOM-killer가 서버 프로세스를 죽인 것 같습니다.서버가 끊은 시간점과 로그 정보가 발생하는 시간점의 키스를 확인하기 위해crontab를 통해 시간 셸 스크립트를 만들어 서버 프로세스의 실행 상황을 모니터링했습니다.다음 다운타임을 계속 기다립니다.

메모리 유출 추적

이때 메모리 문제로 서버 프로세스가 죽었다는 것이 대충 확인되었다.그래서 메모리 유출 문제를 추적하기 시작했다.
먼저 이 문제가 있는 서비스의 코드 특징을 살펴보자. 이 서비스의 주요 업무는 끊임없이 센터 서버에 최신 차트 데이터를 요청하고 로컬의 낡은 차트 데이터를 교체하는 것이다. 즉, 전체 프로그램의 실행 과정에서 대량의 임시 메모리가 끊임없이 발생한다는 것이다.
그리고 이 서비스의 메모리 상승 특징을 관찰한 결과 메모리가 주기적으로 상승하고 있다는 것을 발견했다(메모리 상승 주기 = 요청 데이터의 주기).루아GC가 실효된 건가요?나는 debug console에 GC 명령을 입력하여 GC를 강제 집행했다. (뒤의 연구에서 그것이 실제적으로 완전한 GCcycle를 강제 집행했다는 것을 알았다.) 메모리가 바로 떨어졌다는 것을 발견했다. 이것은 메모리가 회수할 수 있다는 것을 설명한다.GC가 자동으로 촉발되지 않는 건가요?

Lua GC

그래서 Lua의 GC 메커니즘을 연구했다.루아 공식 문서(www.lua.org/manual/5.3/manual.html#2.5)에 따르면 루아의 GC는 incrementalmark-and-sweepcollector 메모리 회수 메커니즘(wiki.luajit.org/New-Garbage-Collector)을 실현했다.대략 세 가지 상태를 바탕으로 단계적으로 실행할 수 있는 GC 메커니즘으로 각 GCcycle은 여러 개의 GCstep로 나누어 완성할 수 있다.GC 알고리즘은 두 개의 핵심 매개 변수인garbage-collectorpause,garbage-collectorstepmultiplier를 설정할 수 있다.공식 문서에서 제시한 두 가지 매개 변수에 대한 대략적인 해석(구체적인 설명은 공식 문서를 볼 수 있다)은 다음과 같다.
pause: 얼마나 자주 새로운 GCcycle을 시작하는지 제어합니다. 기본값은 200이고 메모리가 2200/100배일 때 새로운 GCcycle를 시작합니다.step multiplier: GC 속도는 메모리 분배 속도의 배수에 비해 기본적으로 200, 즉 2배(200/100입니다.
위의 설명만 보면 이 두 파라미터를 이해하기 어렵다. 운풍이 LuaGC에 대한 분석 문서(blog.codingnow.com/2011/03/lua_gc_3.html)를 참조한다.두 매개변수에 대한 추가 이해는 다음과 같습니다.
pause: 현재 메모리가 실제 사용 메모리pause/100의 배로 추산될 때 GCcycle를 촉발합니다.예를 들어 실제 사용된 메모리는 100KB로 추산되고 메모리가 200KB에 도달하면 GCcycle를 촉발한다.step multiplier: 전체 GCcycle은 여러 개의 GCstep로 나누어 완성된 것입니다. step multiplier는 각 GCstep에서 몇 개의 GCsingle-step를 실행할지 조절합니다.
두 가지의 직관적인 의미는 다음과 같다.
pause: 작을수록 회수가 적극적이다(aggressive).클수록 회수가 적극적이지 않습니다 (lessaggressive).기본값: 200.step multiplier: 작을수록 회수가 적극적이지 않습니다(lessaggressive).큰 회수일수록 적극적이다.기본값: 200.
이어서 나는 주기적으로 실행하고 대량의 임시 메모리를 생성하는 Lua 프로그램을 썼다. 이 두 파라미터를 설정하여 이 두 파라미터가 LuaGC에 미치는 실제 영향(X축은 실행 횟수, Y축은 프로그램 메모리 KB을 살펴보았다.
pause 매개 변수 대비
pause 파라미터가 확대됨에 따라 GCcycle 트리거 주기가 길어지고 더 많은 쓰레기 메모리가 방출되지 않습니다.그러나 비교가 그렇게 안정적이지 않은 것은 LuaGC의 일부 핵심 변수와 추산의 관계가 있다.
step multiplier 매개 변수 비교
step multiplier 파라미터가 증가함에 따라 한 번의 GCcycle 실행 시간이 짧아지고 트리거 주기도 짧아지며 쓰레기 메모리는 더욱 빨리 회수됩니다.step multiplier 파라미터를 낮춘 후 LuaGC는 매우 민감하여 첫 번째 GCcycle의 집행이 오랫동안 이루어지지 않았다.
문제가 발생한 서비스의 메모리 상승 상태는 (step multiplier=190) 곡선과 유사하여 계속 상승 상태에 있다. 이것은 아마도 step multiplier가 부족하여 첫 번째 GCcycle를 완성할 수 없기 때문이다.마지막으로 변경된 방안은 그 서비스의 stepmultiplier=300,ps:좀 높아진 것 같습니다.메모리는 더 이상 지속적으로 상승하지 않는다.
이 다운타임으로 구덩이를 파는 과정에서 몇 가지 생각할 점이 있다.

왜 서버 프로세스가 며칠 동안 첫 번째 GCcycle을 완료하지 못합니까?생각해 보니 몇 가지 이유가 있을 수 있다. (1) 첫 번째 GC에서 처리해야 할 쓰레기 메모리가 워낙 크다.(2) Lua 프로그램은 대부분의 시간을 휴면하고 있기 때문에 GCcycle은 실행 기회가 매우 적다.이상 두 가지로 인해 오랫동안 첫 번째 GCcycle을 완성하지 못했다.

LuaGC의 기본 매개 변수는 대부분 문제가 없지만 GC 소모 시간과 메모리 사용량을 균형 있게 조절해야 하는 Lua 프로그램은 스스로 GC 매개 변수를 조정해야 한다.그러나 파라미터를 어떻게 조정하는 것이 좋은지는 충분한 실험 검증을 거쳐야 한다.