Go to Qiita Advent Calendar 2024 Top
LoginSignup
8
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 3 years have passed since last update.

KotlinAdvent Calendar 2019

Day 19
@maruhachi

Kotlinでもトラブル解析がしたい！ (HeapDump, ThreadDump)

Last updated at Posted at 2019-12-18

先日、Ubieの長澤さんが仙台に来てくださり、そこでハンズオンを受けることができました。
名前がかわいいというだけで始めたぺーぺーなため御手柔らかにお願いします。。

やりたいこと

KotlinもJVM言語ですので、Javaと同じ障害時の解析手順が使えるか気になったため、
まずはヒープダンプ・スレッドダンプを出力、解析してみました。

難ありSpringBootアプリを作り、2つの問題を起こしそれぞれのダンプを解析します。

結論

Java知識で対応できる

OutOfMemoryを起こしたAPのヒープダンプ解析

cat /dev/urandom | head -c 20m > test.txt して作った20MBのテキストをアクセスするたびに読み込み、じゃんじゃかMapに突っ込んでいきます(下記AP)。

@Controller
class LoopController(
        var mm: LinkedHashMap<String, String>
) {
    @GetMapping("/hell")
    fun hell(): String {
        val inputStream = File("test.txt").inputStream()
        val reader = inputStream.bufferedReader()
        val res = reader.readText()
        mm.put(LocalDateTime.now().toString(), res)
        return "ok?"
    }

手順

難ありBootアプリを./gradlew build し、起動します。

$ java -Xmx500m -XX:+HeapDumpOnOutOfMemoryError -jar build/libs/infinite-loooooop-0.0.1-SNAPSHOT.jar

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.2.2.RELEASE)

2019-12-18 11:53:00.078  INFO 7200 --- [           main] c.e.i.InfiniteLoooooopApplicationKt      : Starting InfiniteLoooooopApplicationKt on PC with PID 7200 (\infinite-loooooop-0.0.1-SNAPSHOT.jar started by PC in path)
2019-12-18 11:53:07.246  INFO 7200 --- [           main] c.e.i.InfiniteLoooooopApplicationKt      : Started InfiniteLoooooopApplicationKt in 8.075 seconds (JVM running for 9.133)

起動しました。VMオプションはOOM時にHeapdumpを出力、死にやすいようヒープ上限500MB制限です。

localhost:8080/hell へ何度か繰り返しリロードしてアクセスしてみるとError画面が返ってきました。
コンソールにもOutOfMemoryが発生し、ヒープダンプが出力されたことを示すログが出ています。

2019-12-18 22:57:51.907  INFO 27795 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 13 ms
java.lang.OutOfMemoryError: Java heap space
Dumping heap to /Users/ykonno/Src/qiita-article/java_pid27795.hprof ...
Heap dump file created [464222278 bytes in 2.474 secs]
2019-12-18 22:58:26.771 ERROR 27795 --- [nio-8080-exec-7] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: Java heap space] with root cause

java.lang.OutOfMemoryError: Java heap space
	at java.util.Arrays.copyOfRange(Arrays.java:3664) ~[na:1.8.0_192]
	at java.lang.StringBuffer.toString(StringBuffer.java:669) ~[na:1.8.0_192]
	at java.io.StringWriter.toString(StringWriter.java:210) ~[na:1.8.0_192]
	at kotlin.io.TextStreamsKt.readText(ReadWrite.kt:108) ~[kotlin-stdlib-1.3.61.jar!/:1.3.61-release-180 (1.3.61)]
	at com.example.infiniteloooooop.LoopController.hell(LoopController.kt:32) ~[classes!/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_192]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_192]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_192]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_192]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) ~[spring-web-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]

at com.example.infiniteloooooop.LoopController.hell(LoopController.kt:32) ~[classes!/:na]
上記の部分でしっかり.ktファイルのどの部分でエラーが起きたか出してくれています。
val res = reader.readText() の部分ですね。

それではヒープダンプをEclipse Memory Analyzerで見てみます。
mat_leakSuspects-1.png
今回はControllerのフィールドにMapを作り、そこに突っ込んでいるため納得のグラフです。
mat_dominatorTree-1.png
dominatorTreeで見るとLoopControllerがLinkedHashMapを抱えており、そこで90%メモリを消費しているとあります。
フィールドはkotlin.collections.LinkedHashMapというkotlin-stdlib内にあるもので用意していますが、中身はJavaの方のLinkedHashMapとなるようです。
と思ってF3で飛んでみたらtypealiasとなっていました。これによるものですかね。

デッドロック状態なAPのスレッドダンプ解析

教科書的なsynchronizedブロックによるデッドロック用メソッドを用意します(下記AP)。

@RestController
class LoopController() {
    companion object {
        @JvmStatic var lockerA: IntArray = intArrayOf(1, 2, 3)
        @JvmStatic var lockerB: IntArray = intArrayOf(3, 2, 1)
    }

   @GetMapping("paJ")
    fun paJ(): String {
        // ジャバジャバしたデッドロック
        val t1: Thread1 = Thread1()
        val t2: Thread2 = Thread2()
        t1.start()
        t2.start()
        return "ジャバジャバ"
    }

class Thread1 : Thread() {
    override fun run() {
        while (true) {
            synchronized(LoopController.lockerA) {
                synchronized(LoopController.lockerB) {
                    for (i in 0..2) {
                        LoopController.lockerA[i] += LoopController.lockerB[i]
                        LoopController.lockerB[i] += LoopController.lockerA[i]
                    }
                }
                try {
                    sleep(6)
                } catch (ex: InterruptedException) {
                    // no-op
                }
            }
        }
    }
}

class Thread2 : Thread() {
    override fun run() {
        while (true) {
            synchronized(LoopController.lockerB) {
                synchronized(LoopController.lockerA) {
                    for (i in 0..2) {
                        LoopController.lockerA[i] += LoopController.lockerB[i]
                        LoopController.lockerB[i] += LoopController.lockerA[i]
                    }
                }
                try {
                    sleep(5)
                } catch (ex: InterruptedException) {
                    // no-op
                }
            }
        }
    }
}

上記APを起動後、jvisualvmコマンドで状態を確認しながらへリクエストを飛ばしてみます。
すると即デッドロックする様子がコンソールから見て取れます。

2019-12-18 23:52:17.897  INFO 28979 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-12-18 23:52:17.908  INFO 28979 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 11 ms
スレッド1:ロックA取得
スレッド2:ロックB取得
# => 以降沈黙...

jvisualvmの画面で確認してみます。
jvisualvm_threadMonitor.png

初めて使いましたがめっちゃ分かりやすく見せてくれますね! 現在は同梱されていないのが残念です。

スレッドダンプ(抜粋)
2019-12-18 23:52:27
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.192-b12 mixed mode):

"Thread-5" #37 daemon prio=5 os_prio=31 tid=0x00007fccb3a2c800 nid=0x6703 waiting for monitor entry [0x000070000f39f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.example.infiniteloooooop.Thread2.run(LoopController.kt:125)
        - waiting to lock <0x00000007a10ec088> (a [I)
        - locked <0x00000007a10ec068> (a [I)

   Locked ownable synchronizers:
        - None

"Thread-4" #36 daemon prio=5 os_prio=31 tid=0x00007fccb3cc8000 nid=0x6603 waiting for monitor entry [0x000070000f29c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.example.infiniteloooooop.Thread1.run(LoopController.kt:103)
        - waiting to lock <0x00000007a10ec068> (a [I)
        - locked <0x00000007a10ec088> (a [I)

   Locked ownable synchronizers:
        - None

Found one Java-level deadlock:
=============================
"Thread-5":
  waiting to lock monitor 0x00007fccb17f78a8 (object 0x00000007a10ec088, a [I),
  which is held by "Thread-4"
"Thread-4":
  waiting to lock monitor 0x00007fccb49df008 (object 0x00000007a10ec068, a [I),
  which is held by "Thread-5"

Java stack information for the threads listed above:
===================================================
"Thread-5":
        at com.example.infiniteloooooop.Thread2.run(LoopController.kt:125)
        - waiting to lock <0x00000007a10ec088> (a [I)
        - locked <0x00000007a10ec068> (a [I)
"Thread-4":
        at com.example.infiniteloooooop.Thread1.run(LoopController.kt:103)
        - waiting to lock <0x00000007a10ec068> (a [I)
        - locked <0x00000007a10ec088> (a [I)

Found 1 deadlock.

スレッドダンプでもOOMError時と同じくat com.example.infiniteloooooop.Thread2.run(LoopController.kt:125) と問題が発生した箇所を示してくれています。ここを手がかりに原因を探すことができそうです。

ホントはKotlinらしい非同期処理であるCoroutineで並列処理させ、その中のデッドロックの状態を見てみたかったのですが、自分のkotlin力が足りず、再現コードの用意まで至りませんでした。。今後の宿題です。

以上です。

あとがき

以前AltJavaScriptな言語に手を出してみたところ、トランスパイル?されるためかSourceMapやらなにやら用意できないとまともにデバッグできない という状況に見舞われました。

AltJVMなKotlinはどうなんだろう と思い、気軽にできる障害対応を2つ試してみました。
結果、バッチリ.ktファイルの行数で示してくれるため問題なく解析できそうで安心しました。
デバッグ実行はIntelliJでやっている限りは全く気にせず済む上、こうした周辺技術もそのまま使えるのはジャバラーな自分には嬉しいです。

8
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
8
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?