태그 보관물: threaddump

프로세스 스냅샷을 이용한 Java 어플리케이션 분석


사이트에 장애가 발생되면 처음 하는 일이  로그 분석입니다.

로그 분석 후 원인을 못 찾게 되면 다음 하는 일은 Thread Dump 입니다.

포스팅 내용은 ThreadDump 를 이용하여 무한 루프에 빠진 스레드 정보를 찾는 내용입니다.

하단 이미지는 제가 우분투 환경에서 가상으로 무한 루프를 돌리고 테스트를 한 내용입니다. (top command 이용)

coozplz@localhost:~$ top



전체 CPU 사용량은 노란색 테두리 부분을 합산한 내용으로 보시면 됩니다.(38+28)

붉게 표시된 부분의 CPU% 는 (CPU 사용량 / CPU Core 수) 를 하시면 됩니다. 저는 테스트 환경이 쿼드 코어에서 200%가 사용중이므로 즉 50%가 사용중입니다. (무한루프를 두번 만들었습니다.)

Thread 덤프를 통해 분석을 해야 하는데 Thread Dump에는 무한 루프에 빠졌다는 정보는 없습니다.


coozplz@localhost:~$ ps -mo pid,lwp,pcpu -C java

출력결과

20058     –  192

 

   – 20097  0.0

   – 20098  0.0

   – 20099  0.0

   – 20100  0.0

   – 20298  0.0

   – 20301  0.0

   – 20302  0.0

   – 20303  0.0

   – 20304  0.0

   – 20305  0.0

   – 20306  0.0

   – 20307  0.0

   – 20308  0.0

   – 20309  0.0

   – 20310  0.0

   – 20311  0.0

   – 20312  0.0

   – 20313  0.0

   – 20314  0.0

   – 20315  0.0

   – 20318 99.9

   – 20381 99.8

위의 내용중 20318’ 스레드와 ‘20381’ 스레드가 CPU 를 각각 99% 사용하고 있다는 정보가 확인 되었습니다.

‘20318’ HexString 값으로 변경하면 4f5e 라는 값이 나옵니다.

0x4f5e” 값으로 ThreadDump에서 분석을 해보면 어떤 스레드에서 무한 루프가 돌고 있는지 확인할 수 있습니다.


ThreadDump 명령어(Eclipse Console 또는 catalina.out 에 출력됨)

coozplz@localhost:~$ kill -3 20058


“Thread-118” daemon prio=10 tid=0x0000000001563000 nid=0x4f5e runnable [0x00007f0610f23000]

  java.lang.Thread.State: RUNNABLE

   at sun.nio.ch.FileDispatcherImpl.read0(Native Method)

   at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

   at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)

   at sun.nio.ch.IOUtil.read(IOUtil.java:197)

   at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379)

   – locked <0x00000007db9e04f0> (a java.lang.Object)

   at coozplz.test.presense.NetworkSocket.read(NetworkSocket.java:153)

   at coozplz.test.presense.NetworkSocket.recvMessage(NetworkSocket.java:216)

   at coozplz.test.presense.NetworkSocket.recvMessageHead(NetworkSocket.java:355)

   at coozplz.test.presense.NetworkSocket.recvMessage(NetworkSocket.java:372)

   at coozplz.test.presense.ServerThread.run(ServerThread.java:33)


Dump내용중이 coozplz.test.presense.ServerThread 소스를 분석해보면 무한 루프를 찾을 수 있을 겁니다.


TDA(ThreadDump analiyzer) 를 이용한 스레드덤프 분석

순서

  1. 쓰레드 덤프를 5~7초 간격으로 3~5회 정도 추출한다.
    jstack 또는 kill -3 명령을 이용

  2. TDA(ThreadDump analyzer)를 실행한다.

  3. 파일 – 열기 선택 후 스레드 덤프 파일을 선택한다.

  4. 분석 시작


주의사항

쓰레드 덤프를 간격을 두고 여러번 추출하는 이유는 여러번 추출하는 동안 같은 부분에 BLOCK이 되어 있다면 로직 처리 시간이 15초가 넘어가는 경우기 때문에 병목 현상을 예상할 수 있습니다.


위의 이미지를 보면 덤프가 출력된 시간을 볼 수 있습니다. 약 7초간격으로 반복적으로 쓰레드 덤프를 출력 했습니다.

위의 상황을 Oracle JDBC에서 대기 상태로 남는 문제가 발생되는 것을 확인할 수 있습니다. 링크된 부분을 클릭하면 LOCK 된 객체때문에 대기중인 스레드 정보도 확인할 수 있습니다.