자바 응용프로그램의 장애는 크게 2가지로 분류됩니다. 첫번째는 과도한 힙 메모리 사용에 따른 잦은 GC 발생이고, 두번째는 I/O로 인한 블록 혹은 잠금으로 인한 스레드 대기 혹은 교착 문제입니다. 개발 환경에서는 디버거를 통해서 쉽게 WAS나 자바 애플리케이션의 내부 동작을 확인할 수 있지만, 운영 환경에서는 보안 문제로 터미널 접속조차 쉽지 않은 경우가 많습니다.
운영 환경에 JRE 대신 JDK를 설치한 경우라면, 잘 알려진대로 jstack 도구를 사용할 수 있습니다. 다음과 같이 현재 동작 중인 JVM 프로세스 PID를 매개변수로 넘겨서 실행합니다.
그러면 아래와 같은 형식으로 스레드 스택이 출력됩니다.
2017-02-01 23:01:35
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.51-b03 mixed mode):
"[iPOJO] pool-5-thread-1" #53 prio=5 os_prio=0 tid=0x000000000428a000 nid=0x7dcd waiting on condition [0x00007f3b2cf74000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000080c04348> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"FelixStartLevel" #36 daemon prio=5 os_prio=0 tid=0x000000000263d000 nid=0x7dbc in Object.wait() [0x00007f3b2d67b000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:283)
- locked <0x0000000080f65660> (a java.util.ArrayList)
at java.lang.Thread.run(Thread.java:745)
jstack 덤프는 스레드 이름, 스택, 동작 상태 뿐 아니라, 현재 각 스레드가 소유하고 있는 잠금 인스턴스, 대기하고 있는 인스턴스 정보까지 포함합니다. 이를 확인하면 현재 어떤 이유로 스레드가 대기하고 있는지 진단할 수 있습니다.
그러나 보안 문제로 운영 환경에서 jstack 도구를 실행하기 어렵거나, 진단 정보를 자동으로 수집하려는 경우에는 ThreadMXBean을 사용해서 애플리케이션 자체에 잠금 상태를 포함한 스택 덤프 기능을 내장할 수 있습니다.
ThreadMXBean bean = ManagementFactory.getThreadMXBean();
long[] tids = bean.getAllThreadIds();
writer.write("Thread dump (total=" + tids.length + ")" + LF);
writer.write("------------------------------------------" + LF);
for (ThreadInfo t : bean.getThreadInfo(tids, true, true)) {
if (t == null)
continue;
writer.write("\"" + t.getThreadName() + "\" tid=" + t.getThreadId() + ": (state = " + t.getThreadState() + ")" + LF);
writer.write(mergeStackTrace(t));
writer.write(LF);
}
그런데 스레드 풀을 활용하는 경우 보통 스레드 풀을 대표하는 이름만 부여되기 때문에 스택 덤프를 봐도 현재 실행 중인 작업의 맥락을 쉽게 식별하기 어려운 경우가 종종 있습니다. 많은 개발자들이 스레드 이름은 스레드를 생성할 때만 설정할 수 있다고 생각하지만 실제로는 실행 중에 스레드 이름을 임의로 변경할 수 있습니다.
따라서 Runnable 혹은 Callable을 구현할 때, 시작 부분에 현재 컨텍스트에 해당하는 문자열을 스레드 이름으로 설정하고, finally 블록으로 원래 스레드 이름을 복구하도록 코딩하면 현장에서 빠르게 장애를 진단하고 대응할 수 있습니다.
로그프레소는 system threads 쿼리를 통해서 스레드 실행 상태를 진단할 수 있는 기능을 제공하며, 외부 시스템이 흔히 연동되는 스트림 엔진에서는 실행 중인 스트림 쿼리 이름을 스레드 이름으로 설정함으로써 필드 엔지니어의 장애 진단을 지원합니다.
예를 들어 인덱스되지 않은 외부 데이터베이스의 테이블을 dblookup 커맨드로 참조하는 경우 낮은 SQL 조회 성능으로 인해 스트림이 JDBC 드라이버 스택에서 소켓 수신을 대기하고 있는 모습을 쉽게 확인할 수 있고, 해당 스트림 쿼리에 설정된 SQL 쿼리를 확인한 후 즉시 대응할 수 있습니다.
