jvisualvmでKubernetesのScalaアプリケーションのチューニング

GKEで走るScalaアプリのチューニングをjvisualvmでやったので手法をあとで振り返れるようにメモしておく。

要件としては、所与のマシンスペック・台数の範囲内で、スループットを最大化したいというもの。さらに、RTBなので、安定した高速なレスポンス速度が求められる。具体的には1レスポンス20msecくらい。そのレスポンス速度自体はすでに達成できているので、それを崩さずに、スループットを上げる必要があった。

チューニングは、locust で負荷をかけながら行った。はじめはローカル環境からlocustを起動していたが、ある程度以上の負荷をかけようと思うと、ローカルからだとネットワークやCPUがボトルネックになってかけられない。そこでGCEでインスタンスを作って、そこからlocustを起動した。

locustは簡単にマスター・スレーブ構成のクラスタを作ることができる。もちろん、複数のインスタンスでクラスタを組んでもいいが、マルチコアのインスタンスを1つ起動して、その中で複数のスレーブを起動する形でもいい。

マスター側

locust --host=[負荷をかけるURL] --master

スレーブ側

locust --host=[負荷をかけるURL] --slave --master-host=127.0.0.1 &

この状態で、負荷をかけたまま、コンテナに kubectl exec -it でログインして、

ss -taでコネクションをみる
topでCPUの使用率やロードアベレージをみる

をみて概況を掴んだ。

その後、 kubectl port-foward してコンテナのJMXをローカルにポートフォーワードして、jvisualvmを起動した。

jvisualvmは高機能なツールで、これ1つで稼働中のアプリのjvmに関する多くの情報が得られる。今回使ったのは、

スレッドダンプをとる

スレッドダンプはボタン1つでとれる。各スレッドのスタックトレースをみていき、各スレッドがどのように使われているか、ロックしているスレッドがないかを調べる。例えば

"pool-11-thread-231" - Thread t@1001
   java.lang.Thread.State: WAITING
        at sun.misc.Unsafe.park(Native Method)
        - waiting to lock <2ffa4815> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) owned by "pool-11-thread-215" t@984
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:197)
        at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231)
        at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)

これはlogbackのログ出力だが実行がロックされていて、その先の pool-11-thread-215 をみると、ファイルIOを待っていることがわかる。今回の場合は不要なログ出力だったので、それをしなくするようにした。