JVM 기반 애플리케이션 운영시 스레드 덤프를 통한 이슈 해결

JVM기반 애플리케이션을 개발하다가 이슈가 생겼을때 다양한 방식으로 이슈를 확인하고 처리할 수 있습니다. 그중 한가지인 스레드 덤프를 사용하여 이슈를 해결한 사례를 공유하겠습니다.

제가 운영하고 있는 애플리케이션은 Scala로 이루어져 있고 JDK 1.8에서 돌아가는 Multithread application입니다. 카프카 컨슈머를 스레드로 작게는 10개 많게는 100개이상 띄워서 운영하고 있습니다. 이 애플리케이션은 안전하게 중지하기 위해 Shutdown hook을 받도록 개발했습니다만, 언제부턴가 Shutdownhook을 통해 중지요청을 하더라도 애플리케이션이 중지하는 절차를 진행하지 않는 현상이 발생했습니다. 또다시 shutdown hook을 kill -term 명령어와 함께 명령내렸으나 응답이 없고 로그도 남지 않았습니다. 대부분 shutdown hook을 통해 안전하게 종료했지만 가끔 응답이 없었습니다.

결국 배포를 위해 강제 중지하는 방법은 kill -9를 통해 강제 종료하는 수 밖에 없었는데요. 자원을 완전히 종료하지 못하고 강제 종료했기 때문에 문제가 있었습니다. 각종 로그를 작성하고 로그를 확인했으나 결과적으로 확인할 수 있는건 없었는데요.

멈춰있는 상태에서 스레드덤프를 떠보자고 결정하였고 스레드 덤프를 통해 확인할 수 있었습니다. 스레드 덤프를 통해 현재 애플리케이션의 스레드 상태를 확인할 수 있고 스레드가 어디서 멈춰있는지, 실행되는지 등을 알 수 있습니다. 

어느날 shutdown hook(kill -term XXXX)을 날렸는데 종료되지 못하고 응답이 없는 상태로 기다리는 것을 확인하였습니다. 바로 아래 명령어를 통해 thread dump를 파일로 생성하였습니다.

$ jps
4123 MyApplication
$ jstack 4123 > dump.txt

jps를 통해 현재 JVM에 올라가 있는 프로세스의 번호를 확인할 수 있습니다. jstack은 JDK에서 제공하는 스레드 덤프 획득 명령어 입니다. jps를 통해 알아낸 프로세스 번호로 jstack명령어를 조합, 스레드 덤프를 출력할 수 있습니다. 스레드 덤프를 통해 아래와 같은 데이터를 얻었습니다.

2020-07-29 20:20:19
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode):

"Attach Listener" #28692 daemon prio=9 os_prio=0 tid=0x00007f4078008000 nid=0xeb36 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   

"ForkJoinPool-1-worker-31" #28685 daemon prio=5 os_prio=0 tid=0x00007f3eac014000 nid=0xde72 waiting on condition [0x00007f3d40f3d000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00007f50b6887718> (a scala.concurrent.forkjoin.ForkJoinPool)
	at scala.concurrent.forkjoin.ForkJoinPool.scan(ForkJoinPool.java:2075)
	at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
	at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
    
....

"my-computing-thread-12" #1005 prio=5 os_prio=0 tid=0x00007f3fc44fd000 nid=0xc912 runnable [0x00007f3f904c2000]
   java.lang.Thread.State: RUNNABLE
	at scala.collection.mutable.HashTable$class.resize(HashTable.scala:262)
	at scala.collection.mutable.HashTable$class.scala$collection$mutable$HashTable$$addEntry0(HashTable.scala:154)
	at scala.collection.mutable.HashTable$class.findOrAddEntry(HashTable.scala:166)
	at scala.collection.mutable.HashMap.findOrAddEntry(HashMap.scala:40)
	at scala.collection.mutable.HashMap.$plus$eq(HashMap.scala:90)
	at scala.collection.mutable.HashMap.$plus$eq(HashMap.scala:40)
	at myproject.kafka.KafkaConsumerRunner$$anonfun$1.apply$mcV$sp(KafkaConsumerRunner.scala:133)
	at myproject.kafka.KafkaConsumerRunner$$anonfun$1.apply(KafkaConsumerRunner.scala:46)
	at myproject.kafka.KafkaConsumerRunner$$anonfun$1.apply(KafkaConsumerRunner.scala:46)
	at scala.util.Try$.apply(Try.scala:192)
    
 ...

my-computing-thread-12는 제가 실행한 스레드이고 이 스레드가 종료되어야 하는데도 불구하고 RUNNABLE로 실행되고 있는 모습을 볼 수 있습니다. 자세히 살펴보니 KafkaConsumerRunner의 133번째 line에서 HashMap을 실행하고 있는 모습을 볼 수 있습니다. 추가로 jstack을 통해 일정시간이 지난 후에 스레드 덤프를 출력해도 동일한 위치에서 머물고 있는 모습을 확인했습니다.

왜 HashMap에서 머물고 있을까? 라고 의문을 가진 저는 혹시 하는 마음에 구글링을 하였고 답을 찾았습니다.

HashMap은 멀티스레드 환경에서 접근시 내부에서 무한 루프(infinity loop)를 발생할 수 있다는 것이였습니다. 운영환경에서 너무 크리티컬한 이슈 였습니다. 결국 해당 이슈를 확인하고 해당 hashMap을 ConcurrentHashMap로 변경하여 배포하여 해결할 수 있었습니다. 이렇게 Java에서 제공하는 내부 클래스에서 이슈가 발생할 경우에는 쉽게 찾아낼 수 없습니다. 사실상 이번과 같이 스레드 덤프를 생성하지 않고서는 확인할 수  없던 문제인 것입니다. 이슈가 발생하였고 문제가 생겼다고 판단될때는 주저하지 않고 스레드 덤프를 생성하여 분석해보시는것을 추천합니다.