Logstash Memory 사용량 증가 파악기

Latency 측정을 위해 Logstash 를 이용해 Nginx 의 access.log 를 분석하여 수집하고있다.
logstash:2.4.1 -> logstash:7.16.2 로 버전을 올리면서 OOM 이 발생하여 원인을 파악하기 시작하였다.

서버  환경

Logstash 가 배포되는 서버는 Kubernetes 환경의 WorkerNode 에 배포되고 있으며 컨테이너의 리소스.

• requested_memory: 1G
• requested_cpu: 500m

증상

logstash 의 Base Image 를 logstash:2.4.1 -> logstash:7.16.2 로 변경하면 아래와 같이 logstash 가 시작되자마자 OOM Killed

  Last Termination State:
    Exit Code: 137
    Reason: OOMKilled
    Started At: 2021-12-31 01:32:39 +0000 UTC​

 

원인 분석

OOM 발생 원인

 Exit Code: 137 이므로 컨테이너가 종료 신호를 받았고 종료 신호를 받은 이유는 OOMKilled 임을 로그에서 확인할 수 있다.

자세한 원인 분석을 시작하기전에 컨테이너를 정상적으로 띄워놓고 확인하기 위하여 requested_memory: 2G 로 수정 배포하였다.

 

배포한 후에 컨테이너에 접속하여 jps -v 명령어를 사용하여 JVM arguement 를 확인해보았다.

 

logstash:2.4.1

1 Main -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Djava.awt.headless=true -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError -Xmx1g -Xss2048k -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Djava.awt.headless=true -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError -Djruby.script=jruby -Djruby.shell=/bin/sh

logstash:7.16.2

1 Logstash -Xms1g -Xmx1g -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -Djava.awt.headless=true -Dfile.encoding=UTF-8 -Djruby.compile.invokedynamic=true -Djruby.jit.threshold=0 -Djruby.regexp.interruptible=true -XX:+HeapDumpOnOutOfMemoryError -Djava.security.egd=file:/dev/urandom -Dlog4j2.isThreadContextMapInheritable=true

주목할 부분은 logstash:2.4.1 버전에는 -Xms (최소 힙크기 옵션) 이 지정되어있지 않고 logstash:7.16.2 버전에는 -Xms1g 로 지정되어있다는 것이다. 

• logstash:2.4.1 => jdk 1.8.0_292
• logstash:7.16.2 => jdk 11.0.13

logstash:2.4.1 은 jdk 8 버전을 사용하고 있으므로 -Xms 옵션 값을 주지 않았을 경우 사용 가능한 메모리의 절반을 -Xms 로 지정한다.따라서 requested_memory: 1G 환경에서 약 500MB 정도를 최소 Heap size 로 지정하여 사용하고 있었을 것이다.

 

하지만 logsatsh:7.16.2 버전으로 변경되면서 -Xms1g 로 변경되었음에도 Kubernetes 의 requested_memory:1G 로 유지하여 JVM 이 필요한 메모리보다 적은 메모리가 사용 가능하여 OOM 이 발생하였을 것이다.

때문에 requested_memory 를 1G -> 2G 로 변경하니 OOM 발생 없이 정상적으로 실행된 것이다.

 

메모리 사용량 증가 원인

 메모리가 증가한 이후에는 컨테이너가 OOMKilled 없이 정삭적으로 실행되었으나 logstash container 가 사용중인 메모리가 꾸준히 증가하는 메트릭이 보였다. 더하여 메트릭에 잡히는 메모리 사용량이 logstash:2.4.1 사용때보다 대폭 증가하였다.

 

메모리 릭이 의심되어 logstash 컨테이너를 실행할때 LS_JAVA_OPTS 환경변수에 JMX 관련 값들을 전달하여 Heap Memory 를 모니터링하였다.

LS_JAVA_OPTS: '-Dcom.sun.management.jmxremote=true -Dcom.sun.management.jmxremote.port=11618 -Dcom.sun.management.jmxremote.rmi.port=11618 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.rmi.server.hostname='$(IP)' -Xlog:gc*:file=/logs/logstash/gc/gc.log:time:filecount=5,filesize=2M',

초록색 선이 요청량이 있는 서버의 Logstash Heap 사용률을 나타내는 것이다.

꾸준한 우상향 그래프이고 Minor GC 가 발생하여도 확보되는 공간이 매우 적어 Memory Leak 이라 생각하여 Heap Dump 를 떠서 확인해보았다.

 

 

Heap dump 에는 대부분의 공간을 차지하고 있는 객체는 Unreachable Objects 이고 RubyFloat 클래스의 객체들이였다.

한가지 이상한 점은 Minor GC 는 계속 발생하고 있음에도 Unreachable Object 가 계속 쌓여가는 것이다.

 

Minor GC 가 발생하여도 Unreacahble Object 가 쌓인다는것은 Old Generation 에 객체들이 쌓이고 있는 것이다. logstash:7.14.2 버전은 CMS Garbage Collector 를 사용하고 있는데 CMS GC 는 특별한 옵션을 주지 않는다면 -XX:NewRatio=1 로 설정된다.

 

-XX:NewRatio=N 
Heap 의 young generation 크기와 old generation 크기의 비율을 의미한다. N=1 인 경우 young:old=1:9 의 비율을 가져 예를 들어 heap 전체 크기가 1g 라면 young=1g, old=9g 크기를 갖게 된다.

 

따라서 logstash:7.14.2 버전에서 -XX:NewRatio 옵션을 주지 않았다면 -Xms1g 인 상황에서 young generation 은 1g old generation은 9g 를 사용하게 된다.

 

logstash container 에 접속하여 jmap -heap {pid} 명령어로 힙의 각 영역 사이즈를 확인해보면 더 명확하게 알 수 있다

NewSize                  = 87228416 (83.1875MB)   
OldSize                  = 986513408 (940.8125MB)

 

때문에 Minor GC 가 발생하더라도 전체 Heap 영역의 10%만 공간이 확보가 되고 Reference 가 남아있는 객체들이 90% 크기를 갖는 Old Generation 으로 넘어가면서 이러한 우상향 그래프가 그려지게 되는 것이다.

 

이는 Minor GC 가 발생하여도 Unreachable Object 들이 쌓여있는 것 또한 설명이 된다.

항상 G1GC 만 사용하여 Young Generation 의 비율이 최대 60%까지 잡히는 시스템의 Heap 사용률의 그래프만 보다가 CMS GC 그래프를 보니 memory leak 으로 의심하였다.

 

 

번외1) Logstash GC 변경하기

 logstash:7.14.2 버전에서는 CMS GC 를 사용하도록 JVM Argument 를 세팅하고 있으므로 LS_JAVA_OPTS 로 사용하고자 하는 GC 를 전달한다고 하더라도 아래와 같은 에러가 발생한다.

Using LS_JAVA_HOME defined java: /usr/lib/jvm/java-11-openjdk-amd64.
WARNING: Using LS_JAVA_HOME while Logstash distribution comes with a bundled JDK.
OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
Error occurred during initialization of VM
Multiple garbage collectors selected​

여러개의 Garbage Collector 가 선택되어 에러가 발생했다.

이런 경우 /logstash/config 에 있는 jvm.options 파일을 수정해주면 된다.

## GC configuration
#8-13:-XX:+UseConcMarkSweepGC
#8-13:-XX:CMSInitiatingOccupancyFraction=75
#8-13:-XX:+UseCMSInitiatingOccupancyOnly
-XX:+UseG1GC
-XX:MaxGCPauseMillis=200
-XX:G1HeapRegionSize=8m

만약 Docker 를 사용하고 있다면 이미지를 새로 빌드할때 logstash 를 실행하기 전에 jvm.options 파일을 새로 정의한것으로 교체하면 된다.

 

번외2) docker 파일로 logstash 실행할때 stdin 을 input 으로 사용하기

 로컬에서 logstash 를 테스트하고자 할때 매번 logstash 를 파싱하는 파일에 로그를 쓰고 저장하는것은 번거롭다

logstash 의 input{} 을 stdin 으로 바꿔주면 logstash 를 실행한 화면에서 편하게 log 를 입력할 수 있다.

input {
  stdin {}
}

하지만 이 logstash 를 docker image 로 빌드해서 docker-compose up 명령어를 사용해서 실행할 경우에는 logstash 가 특별한 에러 없이 즉시 종료되어 버린다.

logstash 가 stdin 으로 받을 데이터가 더 이상 없다고 판단하여 즉시 종료된 것인데 docker-compose 를 이용하여 컨테이너들을 실행할때는 여러개의 container 가 한번에 실행되므로 어떤 container 의 stdin 을 input 으로 전달할지 정할 수 없다.

 

따라서 docker-compose 파일에 logstash 컨테이너 옵션에 stdin_open: true 를 추가해준다. 그 후에 docker attach {containerId} 를 이용하면 해당 container 의 stdin 으로 붙어서 테스트가 가능하다.