사이트에 장애가 발생되면 처음 하는 일이 로그 분석입니다.
로그 분석 후 원인을 못 찾게 되면 다음 하는 일은 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 소스를 분석해보면 무한 루프를 찾을 수 있을 겁니다.
Coozplz Blog 