본문 바로가기
OS

[리눅스]쓰레드 덤프, 힙 덤프, 코어 덤프 분석 삽질과정

by 코리늬 2020. 1. 31.

개발서버(톰캣)가 자주 죽었다. 그것도 아무 에러로그 없이.

그럼 원인을 어떻게 찾아야하지??

 

정확한 원인을 파악하기 위해서는 쓰레드 덤프, 힙 덤프를 떠보고 메모리 사용량 CPU 사용량 등등 여러 복합적인 요소들을 확인해야 한다고 한다.

어떻게??

 

우선 쓰레드 덤프를 확인하는 여러가지 방법 중 자바에서 제공해주는 JVisualvm 을 사용해서 확인을 하려한다.

remote에 add host로 확인하려는 서버를 추가했지만 아무 반응이 없었다.

외않되???

 

더 찾아보니 실행시키면 자동으로 jvm에 등록되어 모니터링을 할 수 있는게 아니고, 모니터링을 하기 위한 설정을 따로 해줘야 한다.

JMX라는걸 사용해야 모니터링이 가능하다.

JMT(존맛탱)는 아는데 JMX는 뭐지 ??

 

JMX

  • JDK 1.5부터 사용 가능
  • 실행 중인 어플리케이션의 상태를 모니터링하고, 설정을 변경할 수 있게 해주는 API

JMX 설정

JMX_OPTS=" -Dcom.sun.management.jmxremote \
                 -Dcom.sun.management.jmxremote.authenticate=false \
                 -Djava.rmi.server.hostname=서버 IP \
                 -Dcom.sun.management.jmxremote.ssl=false "
CATALINA_OPTS=" ${JMX_OPTS} ${CATALINA_OPTS}"
  • authenticate를 사용하고 싶다면
-Dcom.sun.management.jmxremote.authenticate=true \
-Dcom.sun.management.jmxremote.password.file=$CATALINA_BASE/conf/jmxremote.password  \
-Dcom.sun.management.jmxremote.access.file=$CATALINA_BASE/conf/jmxremote.access  \
  • server.xml에 Listener 추가 (jmx 포트 번호 설정)
<Listener className="org.apache.catalina.mbeans.JmxRemoteLifecycleListener"
        rmiRegistryPortPlatform="9840" rmiServerPortPlatform="9841"/>

스레드 상태값은 여러개가 존재하지만 나의 톰캣이 죽기전 가장 최근 찍힌 상태값의 경우 WAITING이 많았다.

 

WAIT 상태에 있는 경우

스레드가 계속 WAIT 상태를 유지하고 있는 경우이다.

LinkedBlockingQueue 객체에서 메시지를 획득하기 위해 계속 대기하고 있다. 만약 계속 LinkedBlockingQueue에 메시지가 들어오지 않는 다면 해당 스레드의 상태가 바뀌지 않게 된다.

 

스레드 덤프를 이용한 문제 해결 예제

상황1: CPU 사용률이 비정상적으로 높을 때

애플리케이션을 수행할 때 CPU 사용률이 비정상적으로 높다면 스레드 덤프를 이용하여 문제를 파악할 수 있다.

먼저 다음과 같이 CPU를 가장 많이 점유하는 스레드가 무엇인지 추출한다.

ps -mo pid,lwp,stime,time,cpu -C java

음 그런데 CPU 사용량이 높은 스레드가 없었다. 이 경우는 아닌가보다.

 

상황2: 수행 성능이 비정상적으로 느릴 때

애플리케이션의 수행 성능이 비정상적으로 느릴 때에는 BLOCKED 상태인 스레드가 원인인 경우가 많다. 이 때에는 스레드 덤프를 여러 번 얻은 다음 BLOCKED 상태인 스레드 목록을 찾고 BLOCKED 상태인 스레드가 획득하려는 락과 관계된 스레드를 추출해 본다.

아직까지는 BLOCKED 상태가 보이지 않는다..

또한 OOM 가능성을 확인하기 위해 Heap Dump도 같이 확인해봐야 한다고 하였다.

 

Heap Dump 분석

JVM 을 사용하고 있으므로, Heap Dump 생성 버튼으로 생성했다.

  • 리눅스 tomcat/temp 경로 아래 덤프 파일이 생성되었다.

Heap Dump를 분석하기 위해 분석 툴(Eclipse Memory Analyzer)이란 것을 알게되었다.

  • 실행
  • Open a Heap Dump 클릭 -> Dump 파일 Open
  • 해당 경로에 다량의 *.index가 생성됨 (분석이 끝난 후 삭제해도 무관)
  • 분석이 끝난 경우 Overview 탭의 Dominator Tree 클릭
  • Heap Dump를 뜰 당시 만들어진 Java 객체 확인 가능 -> 비정상적인 Percentage 객체 확인

음..근데 17퍼면 양호한거 아닌감..

내가 뜬 덤프는 서버가 죽고 난 뒤의 덤프

즉, 의미가 없었다.

톰캣이 죽는 시점에 덤프를 남기도록 톰캣 설정이 있다고 한다.

역시 뭔가 이상했어..

 

OOM 에러 발생 시 힙 덤프 생성

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=$CATALINA_BASE/logs

OOM 발생 이후 조치

-XX:OnOutOfMemoryError=$CATALINA_HOME/bin/stop.sh

또는

-XX:OnOutOfMemoryError=$CATALINA_HOME/bin/restart.sh

힙 덤프를 남긴 뒤, 관리 정책에 맞게 적합한 동작을 취할 수 있도록 한다.

 

GC 설정

WAS 기동 Shell에 verbose:gc 옵션을 준다

    + GC에 대해 자세히 시간을 찍도록 한다

    + 로그위치와 명칭을 지정한다

-verbose:gc 

-Xloggc:/applog/cmsmDomain/gclog/gc.log 

-XX:+PrintGCDetails 

-XX:+PrintGCTimeStamps 

-XX:+PrintHeapAtGC

 

나의 셋팅

#OOM Heap Dump Setting
JAVA_OPTS="$JAVA_OPTS -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=$CATALINA_HOME/temp"

#GC Setting
JAVA_OPS="$JAVA_OPTS -verbose:gc -Xloggc:$CATALINA_HOME/temp/gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC"

음 근데 JAVA_OPS, CATALINA_OPS 가 있는데 어느 옵션에 줘야해..??

 

JAVA_OPS VS CATALINA_OPS

JAVA_OPS 는 start , stop, run - 항상 적용하는 JVM 옵션

CATALINA_OPS 는 start , run 명령에 영향 - START에 만 적용할 JVM 옵션

메모리 누수

LinkedHashMap은 LinkedList로 구현한 HashMap이며 맵에 저장한 엔트리를 before와 after라는 이름의 레퍼런스를 사용해 순서대로 엮는다. 따라서 before와 after 레퍼런스에 연결된 객체는 LinkedHashMap의 엔트리여야 하므로 내부의 table 배열에 존재하거나 다른 엔트리의 next 레퍼런스에 연결돼야 한다(next 레퍼런스는 해시의 버킷 연결을 의미한다). 그러나 table[795]에 저장된 객체의 before 레퍼런스에 연결된 객체는 table 배열에 존재하지 않았고 다른 엔트리의 next 레퍼런스에 연결되지도 않았다. 이것은 이 객체가 HashMap의 엔트리가 아님을 의미한다.

HashMap의 엔트리가 아닌 객체는 HashMap에서 지워야 하는데 어떠한 이유로 before 레퍼런스를 정리하지 못해 아직 남아 있기 때문에 가비지 컬렉터(garbage collector)가 객체를 정리하지 못한 상황이라고 볼 수 있었다. 그럼 왜 before 레퍼런스를 정리할 수 없었을까? 이런 문제는 대부분 멀티 스레드(multi thread) 환경에서 스레드 세이프(thread-safe)를 고려하지 않은 코드를 사용했을 때 발생한다는 것을 경험으로 알고 있었다. before 레퍼런스가 변경되는 시점의 코드를 찾아서 어떤 실수가 있었는지 확인하는 작업을 진행했다.

음 그런데 우린 ConCurrentHashMap을 사용하였고 이건 Thread Safe 한걸로 알고있는데

 

TIP

OOM이 발생되어 힙 덤프가 생성되는 동안은 시스템이 기동되지 않는다.

이제 서버를 터트려서 생성되는 로그를 확인해야 한다.

어떻게 터트리지?

 

리눅스에 stress 툴 설치

#EPEL repo 활성화
yum -y install epel-release

#Stress 툴 설치
yum -y install stress

 

사용법

CPU 부하 주는 방법

# stress -c <코어 수>
grep -c processor /proc/cpuinfo 명령어를 통해 CPU 코어 전체 개수를 확인할 수 있습니다.
stress 툴에 코어 수를 지정하면 해당 코어는 100%를 사용하게 됩니다.

Memory 부하 주는 방법

# stress --vm <프로세스 수> –vm-bytes <사용할 크기>
예 : stress --vm 3 --vm-bytes 1024m
stress --vm 50 --vm-bytes 8192m

HDD 부하 주는 방법

# stress --hdd <hdd 수> --hdd-bytes <사용할 크기>
예 : stress --hdd 3 --hdd-bytes 1024m

 

코어 덤프란?

  • 특정 시점에 작업 중이던 메모리 상태를 기록한 것
  • 프로그램이 비정상적으로 종료했을 때 만들어진다.

코어 덤프 생성

ulimit -a 이 명령어를 사용했을 때 core file size가 0이면 core dump는 생성되지 않는다.

ulimit -c unlimited 명령어를 사용하여 core 덤프를 남기도록 설정한다.

Out of memory: Kill process 6860 (java) score 84 or sacrifice child
Jan 13 16:02:58 tas-dev20 kernel: Killed process 21403 (git) total-vm:116496kB, anon-rss:184kB, file-rss:100kB, shmem-rss:0kB



Out of memory: Kill process 21462 (java) score 84 or sacrifice child
Jan 13 16:03:17 tas-dev20 kernel: Killed process 21462 (java) total-vm:10325748kB, anon-rss:2031956kB, file-rss:244kB, shmem-rss:0kB

core dump를 확인하기 위한 ulimit 설정 수정

/etc/profile 경로에 #ulimit -SHn 65536 에서 ulimit -c unlimited > /dev/null 2>&1 로 수정

/etc/sysctl.conf 수정
아래와 같이 kernel.suid_dumpable = 1,
kernel.core_uses_pid = 1 을 추가한다.

경로 지정을 위해 위의 경로에

kernel.core_pattern = ./core/core-%e-%s-%t.%p 를 추가하고

수정된 내용을 적용시키기 위해서 sysctl -p 명령을 수행

이렇게 하면 core 파일은 톰캣의 실행경로인 bin 아래 생기게 된다.

file core.pid 명령어를 사용하면 어느 항목에 해당하는 core dump인지 알려준다.

 file core.16183
core.16183: ELF 64-bit LSB core file x86-64, version 1 (SYSV), SVR4-style, from '/app/java/jdk1.8.0_31/bin/java -Djava.util.logging.config.file=/app/tomcat_www/', real uid: 0, effective uid: 0, real gid: 0, effective gid: 0, execfn: '/app/java/jdk1.8.0_31/bin/java', platform: 'x86_64'

gdb 명령어와 from 뒤의 파일 이름으로 코어 덤프 파일을 분석한다.

gdb ./app/tomcat_www/ ./core.16183

gdb /app/tomcat_www/bin ./core.16183

success가 뜨면
gdb에 backtrace 명령어를 실행한다.

 

자바 크래시 로그

https://d2.naver.com/helloworld/1134732

코어 덤프 설정까지 하고나니 JVM 크래시 로그가 생성되었다.

 eden space 55808K, 97% used [0x00000000fab00000,0x00000000fe04d028,0x00000000fe180000)
  from space 15360K, 47% used [0x00000000fe180000,0x00000000fe88ea40,0x00000000ff080000)
  to   space 14848K, 0% used [0x00000000ff180000,0x00000000ff180000,0x0000000100000000)

힙 영역을 보니 eden이 97퍼, S0(from)와 S1(to) 중 하나의 영역은 반드시 비어 있어야 하는데 to가 0퍼 인걸보니 GC는 제대로 동작을 했다.

쓰레드 덤프 남기는 쉘 스크립트

jstack -l 28012 >> threaddump%e-%s-%t.log

/app/tomcat_www/temp/heap/heap_dump$(date '+%Y-%m-%d-%H-%M')

리눅스 쉘 파일을 크론탭 없이 백그라운드에서 실행시키고 싶을 때

./test.sh &
  • 뒤에 &를 붙여준다.
while true;
         do d=`date +%Y%m%d-%H%M%S`;
         `jstack 25565 > "threaddump-$d.tdump"`;
        sleep 15m;
done

######

while true;
        do d=`date +%Y%m%d-%H%M%S`;
        jmap -dump:live,format=b,file=/app/tomcat_www/temp/heap/heapdump-$d.hprof 10378;
        sleep 1m;
done

jmap -dump:live,format=b,file=/app/tomcat_www/temp/heap/heapdump$(date '+%Y-%m-%d-%H-%M').hprof 10378

근데 왜 코어 덤프는 설정을 해놨는데 저 때 이후로는 다시 안생겨???

$^&%^&@#$%@#$%%$#^&%^^&(^&(^&$%^))

 

스트레스 발생 시 사용량 변화

 

스트레스 주기 전 힙덤프

 

스트레스 주고 난 후 힙덤프

왜 차이가 없을까? 어느 부분을 잘못했을까?

어디가 문제였을까..

 

참고

https://d2.naver.com/helloworld/10963

https://stackoverflow.com/questions/11628595/unable-to-remotely-connect-to-jmx

https://bluexmas.tistory.com/751

https://jupiny.com/2019/07/15/java-heap-dump-analysis/

저작자표시 비영리

'OS' 카테고리의 다른 글

[Linux] 로그 모니터링을 통한 장애시 문자 알림 보내기  (1) 2019.08.02
[Linux] 리눅스에 톰캣 설치 & 서비스 등록  (0) 2019.07.05
OS - 메모리 관리  (0) 2019.06.18

관련글

댓글

티스토리툴바