[Java] Java Process Error/Pending Analyze - 실행 중인 java 프로세스 에러 분석하기.

개요

Java의 특성이자 장점인 Object에 대한 동적할당이 때로는 우리의 발목을 잡는다. 

일반적으로 대부분의 문제들은 log4J로 생성되는 로그들이나 GC로그를 통해 확인할 수 있다. 

Java 프로세스가 느려지거나 멈추는 현상은 대부분 메모리 부족으로 인한 gc/swap 으로 인한 것이기 때문에 

리소스가 충분하다면 손쉽게 문제를 해결 할 수 있다. 하지만 log에 특별한 exception이 발생하지 않고, 

log.level을 DEBUG로 변경하였는데도 특별한 에러가 발견되지 않는다면 우리는 조금 더 복잡한 방법으로 문제를 확인해야 한다. 

많은 접근 방식이 있겠지만 가장 쉽게 생각할 수 있고 많은 레퍼런스가 있는 

JVM thread dump 와 JVM heap dump 방식을 보려고 한다.

1. JVM Thread dump 

제약사항 

1. root 계정으로 jps -l 또는 ps -ef | grep <pid> 명령를 통해서 원하는 JVM 프로세스 확인
2. jstack -l <pid>  >  process.log 를 통해서 스레드 덤프를 확인
3. jstack은 JDK 1.5 이후 버전부터 사용가능함
4. JDK 1.6 jstack 을 통해 JDK 1.5 로 수행중인 프로세스의 스레드 덤프 가져오지 못함

기본 사용법

$ sudo -u <user> jstack <pid>

- user : thread dump를 얻고자 하는 java process를 수행하고 있는 user 

- pid : thread dump를 얻고자 하는 java process의 id 

JVM thread dump 를 10초에 1개씩 총 10개를 가져오는 것이 좋다.

일정 시간을 가지고 반복적으로 수행하면서 어떠한 thread에 문제가 있는지 확인해야 한다.

Jstack script (jstackSeries.sh)

#!/bin/bash

if [ $# -eq 0 ]; then

    echo >&2 "Usage: jstackSeries <pid> <run_user> [ <count> [ <delay> ] ]"

    echo >&2 "Defaults: count = 5, delay = 0.5 (seconds)"

    exit 1

fi

pid=$1          # required

user=$2         # required

count=${3:-5}  # defaults to 10 times

delay=${4:-0.5} # defaults to 0.5 seconds

subdir=jstacklog-$pid

if [ ! -d "$subdir" ]; then

    mkdir ./$subdir

fi

while [ $count -gt 0 ]

do

    sudo -u $user top -H -b -n1 -p $pid > $subdir/top.$pid.$(date +%H%M%S.%N) &

    sudo -u $user jstack -l $pid > $subdir/jstack.$pid.$(date +%H%M%S.%N)

    sleep $delay

    let count--

    echo -n "."

done

  

결과 예시 

"ambari-client-thread-31 Acceptor0 SelectChannelConnector@0.0.0.0:8080" prio=10 tid=0x00007fca2f46d800 nid=0x6a00 runnable [0x00007fc9e6a9a000]

   java.lang.Thread.State: RUNNABLE

        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)

        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241)

        - locked <0x000000079dc2b528> (a java.lang.Object)

        at org.eclipse.jetty.server.nio.SelectChannelConnector.accept(SelectChannelConnector.java:109)

        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:938)

        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)

        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)

        at java.lang.Thread.run(Thread.java:745)

"HashSessionScavenger-0" daemon prio=10 tid=0x00007fca2f11f000 nid=0x69fe in Object.wait() [0x00007fc9e6b9b000]

   java.lang.Thread.State: TIMED_WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

        at java.util.TimerThread.mainLoop(Timer.java:552)

        - locked <0x000000079d79e648> (a java.util.TaskQueue)

        at java.util.TimerThread.run(Timer.java:505)

"pool-3-thread-1" prio=10 tid=0x00007fca2fbee000 nid=0x69c4 waiting on condition [0x00007fc9e6c9c000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x0000000799690570> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)

        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

        at java.lang.Thread.run(Thread.java:745)

"ambari-hearbeat-monitor" prio=10 tid=0x00007fca2fbea000 nid=0x69c3 waiting on condition [0x00007fc9e6d9d000]

   java.lang.Thread.State: TIMED_WAITING (sleeping)

        at java.lang.Thread.sleep(Native Method)

        at org.apache.ambari.server.agent.HeartbeatMonitor.run(HeartbeatMonitor.java:125)

        at java.lang.Thread.run(Thread.java:745)

Thread 확인 방법 

1. ps 명령어를 사용 

$ ps -T -p 26984

--------------------------------------    

PID  SPID TTY          TIME CMD 

26984 26984 ?        00:00:00 java 

26984 26985 ?        00:00:42 java 

26984 26986 ?        00:15:45 java 

2. top 명령어 사용 

$ top -H -p 26894

3. htop 명령어 사용 (http://ask.xmodulo.com/view-threads-process-linux.html)

- F2 -> setup -> display options -> Tree View, Show custom thread names 'on'

JVM Heap dump

제약사항

1. kill 명령을 통해서 heap dump를 생성하기 위해서는 별도의 java option이 설정되어 있어야 한다. (https://support.hpe.com/hpsc/doc/public/display?docId=mmr_na-0307663)

2. Heap dump를 생성하고자 하는 process의 JDK 버전을 사용한다.

JDK 버전별로 option 이 다르며, java process들의 heap 구조는 각 JDK에 의존성을 갖는다.

ps -ef 로 나온 프로세스의 jdk bin 경로를 사용하는 것이 좋다.

명령어 및 옵션

1. java heap summary : 요약된 정보를 보여준다.

$ jamp -heap 20167 > summary.out

2. finalizerinfo : pending 상태의 오브젝트 정보를 출력한다. 

$ jmap -finalizerinfo 20167 > pending.out

3. dump : heap dump를 hprof binary 포맷으로 생성한다.

 $ jmap -dump:live,format=b,file=dump.hprof <pid> 

- live : 현재 활성된 object만 dump를 생성한다. 만약 명시되지 않는다면 모든 object에 대해 dump를 생성한다. 

- format=b : binary로 파일을 생성한다. 

- file : 출력 경로를 지정한다. 

4. F option : dump, histo 명령어 등과 함께 사용되며 프로세스가 응답하지 않는 경우에도 사용할 수 있다. 

Heap dump 분석 

1. 서버에서 바로 분석 하는 경우 

1) jhat 사용 (http://2min2code.com/articles/jhat_comamnd/overview)

2. hprof 파일을 client(local)로 옮겨서 분석하는 경우 

1) easyGC 사용 (http://gceasy.io/)

3. 기타 : lsof 등을 통해서 file I/O를 확인 하는 것도 유용함. 
(https://www.lesstif.com/pages/viewpage.action?pageId=20776078)