I am메모리에요~ 🤗

백수가 주말에 장애대응을 할 수 있다?

여느 날과 같이 구직에 쫓기며 폭풍 개발을 하던 와중에 홈랩 서버가 갑자기 이륙을 하기 시작했다. 무슨 상황인지 싶어 모니터링 도구를 보니 메모리가 매우 화나있었다.

일단 평소 1Gb RAM으로 충분히 동작하고 있어서, 단순히 "팀원이 빌드 실행하셨나 보다.." 정도로 생각하고 신경을 안 쓰다가 시간이 지나도 계속된 엔진 소음으로 문제를 확인하니 이상한 점이 있었다.

첫 번째로 갑자기 높아진 메모리 사용량이다. 처음엔 단순히 빌드 작업 중이시구나 생각했지만, 빌드를 하는거면 메모리보단 CPU가 더 높아야 하는데 CPU는 굉장히 잔잔했다.

왼쪽이 문제 상황에서 CPU 상황이고, 오른쪽은 문제를 해결한 후 테스트로 빌드를 실행할 때 CPU 상황이다.

메모리 사용량이 갑자기 치고 올라오면 램이 날뛰기 시작하고, 당연하게도 HTTP 요청을 처리할 스레드를 할당할 메모리조차 할당할 수 없는 상황이니 Jenkins에는 접속조차 불가능한 상황이었다. 일단 메모리가 문제인 것은 명확하니 당장 할 수 있는 조치는 메모리를 4Gb에서 8Gb로 늘렸다.

다행히 RAM문제는 명확해서 홈랩 서버가 이륙하려고 하는 것은 멈췄지만 여전히 메모리 사용량은 변화가 없었다.

원래 예상했던 시나리오는 메모리 부족으로 밀린 작업들이 처리가 완료되면서 GC가 메모리를 정리해주지 않을까? 였지만, 한 번 할당된 메모리는 반환되고 있지 않았다.

36.5℃에서도 끓는 개발자의 피

문제를 명확하게 하기 위해서 리눅스에 접속해 어떤 프로세스가 귀여운 돼지 녀석🐽인지 확인했다.

ps -eo user,pid,ppid,rss,size,vsize,pmem,pcpu,time,cmd --sort -rss | head -n 4

당연하게도 Jenkins가 압도적으로 많은 메모리를 점유하고 있는 상태였다.

root@jenkins ~# ps -eo user,pid,ppid,rss,size,vsize,pmem,pcpu,time,cmd --sort -rss | head -n 4 
USER         PID    PPID   RSS  SIZE    VSZ %MEM %CPU     TIME CMD
jenkins    24853       1 9130364 10140264 19688136 55.7 0.1 00:10:46 /usr/bin/java -Djava.awt.headless=true -jar /usr/share/java/jenkins.war --webroot=/var/cache/jenkins/war --httpPort=8080

더 자세히 알아보기 위해서 jmap을 이용해 어떤 모듈이 메모리를 많이 점유하고 있는지 확인이 필요했다.

root@jenkins ~# jmap -histo 24853
 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:       2267030     1588968600  [B (java.base@17.0.7)
   2:       1157551      437729336  [C (java.base@17.0.7)
   3:        591833      104471984  [I (java.base@17.0.7)
   4:          5811       51789704  [F (java.base@17.0.7)

가장 많은 메모리를 점유한 인스턴스와 그다음 인스턴스가 거의 3배 가까이 점유하고 있는 상태다. 이제 더 자세한 분석을 위해 jmap을 이용해 덤프 파일을 생성해ㅂ....

root@jenkins ~# jhsdb jmap --binaryheap --dumpfile dump.hprof --pid 24853
Attaching to process ID 24853, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 17.0.7+7-Debian-1deb11u1
java.lang.IndexOutOfBoundsException: bad SID 0
        at jdk.hotspot.agent/sun.jvm.hotspot.runtime.vmSymbols.symbolAt(vmSymbols.java:61)
        at jdk.hotspot.agent/sun.jvm.hotspot.oops.InstanceKlass.getFieldName(InstanceKlass.java:307)
        at jdk.hotspot.agent/sun.jvm.hotspot.oops.InstanceKlass.<init>(InstanceKlass.java:157)
        at jdk.internal.reflect.GeneratedConstructorAccessor2.newInstance(Unknown Source)

...

원인 자체는 덤프 과정에서 식별할 수 없는 타입의 인스턴스가 발견된 것 같다.

  public static Symbol symbolAt(int id) {
    if (id < FIRST_SID || id >= SID_LIMIT) throw new IndexOutOfBoundsException("bad SID " + id);
    return Symbol.create(symbolsAddress.getAddressAt(id * VM.getVM().getAddressSize()));
  }

아쉽게도 나와 같은 이슈가 제보되었지만, 완료되지 않은 상태로 닫힌 것 같다.. 어쩔 수 없이 pmap을 이용해 현재 프로세스 메모리 맵을 확인 해보자.

root@jenkins ~# pmap -x 24853 | sort -k 3 -n -r | more
total kB         19688140 9135216 9115904
000000041a000000 9314304 8612620 8612620 rw---   [ anon ]
00007f8abc26f000  146564  145544  145544 rw---   [ anon ]
00007f8ae1400000   38336   38320   38320 rwx--   [ anon ]

다음으로 갓이크로소프트(Microsoft)가 제공하는 procdump를 이용해 현재 Jenkins의 메모리 덤프를 떠봤다.

root@jenkins ~# procdump -pgid 24853

덤프 된 파일은 ELF 형식으로, JVM 자체를 지지고 볶을 예정은 아니니, 단순히 프로세스 구조만 확인해 보자. ELF 구조를 확인해 가장 많은 메모리를 할당한 메모리 영역이 어떤 섹션인지 확인해보자.

root@jenkins ~# readelf -S java_time_2023-10-30_15\:50\:48.24853 
There are 553 section headers, starting at offset 0x4b1aea5a0:

Section Headers:
  [Nr] Name              Type             Address           Offset
       Size              EntSize          Flags  Link  Info  Align
  ...중략...
  [ 2] load              PROGBITS         000000041a000000  000078c8
       0000000238800000  0000000000000000  WA       0     0     1

착한 분이 메모리 덤프를 쉽게 뜨기 위한 스크립트를 작성해 주셔서 그대로 이용했다.

#!/bin/bash

grep rw-p /proc/$1/maps \
| sed -n 's/^\([0-9a-f]*\)-\([0-9a-f]*\) .*$/\1 \2/p' \
| while read start stop; do \
    gdb --batch --pid $1 -ex \
        "dump memory $1-$start-$stop.dump 0x$start 0x$stop"; \
done

그런데 아쉽게 위 스크립트가 아니라, gdb에서 직접 프로세스 메모리 덤프 뜨려다 프로세스가 죽어버려 문제의 메모리 누수된 상황에서 원래 상태로 돌아왔다.. 😭