SlideShare a Scribd company logo

Jvm operation casual talks

•
•
Yusaku Watanabe
Yusaku Watanabe

This document summarizes steps taken to optimize CPU usage of a JVM running an Akka application using Spray. The application was not utilizing the CPU effectively, with throughput very low. Understanding Akka's asynchronous, actor-based architecture and obtaining thread dumps revealed the logging was blocking threads. The solution was to configure logging to occur asynchronously within actors to avoid blocking and better utilize the CPU.

1 of 19
Downloaded 11 times
Spray(Akka)でJVMをCPUスケー ルさせるために行った事
渡辺 雄作(35) / @waysaku ソフトウェアエンジニア 株式会社サイバーエージェント アドテク本部 (Webシステム)
Spray(Akka)でJVMをCPUスケー ルさせるために行った事
spray is an open-source toolkit for building REST/HTTP- based integration layers on top of Scala and Akka. Being asynchronous, actor-based, fast, lightweight, modular and testable it's a great way to connect your Scala applications to the world.
Scalaコードを読めない人(技術的、もしくはポリ シー的に)がAkkaアプリケーション運用を任されて しまった JVM上で動くノンブロッキング、非同期なアーキ テクチャを採用しているアプリケーション 対象システム 対象者
リリース数日前の負荷試験、、、 何が起きたか スループットが全然出ない！
• Akkaの仕組みを理解する 解決までの道のり • Linuxの基本的な情報を取得 • Thread Dump取得
Actor Dispacher Actor Actor Actor Thread ThreadThread Thread Actor Actor ひもづける • Akkaの仕組みを理解する
Dispacher ThreadThread Akkaの基本的な考え方 Thread Actor Actor Actor Actor Actor Thread Actor ！！
Cpu0 : 2.3%us, 0.7%sy, 0.0%ni, 97.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu1 : 0.3%us, 0.3%sy, 0.0%ni, 99.3%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu2 : 92.0%us, 6.0%sy, 0.0%ni, 2.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu3 : 5.4%us, 1.7%sy, 0.0%ni, 93.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st スループットが全然出ないと思ったら、 CPU一個しか使ってない！ そのくせロードアベレージが無駄に高い • Linuxの基本的な情報を取得
Thread Dumpを取得する "Attach Listener" daemon prio=5 tid=0x00007f8de5852000 nid=0x3b07 waiting on condition [0x0000000000000000] "DestroyJavaVM" prio=5 tid=0x00007f8de280b800 nid=0x1903 waiting on condition [0x0000000000000000] "default-akka.actor.default-dispatcher-4" prio=5 tid=0x00007f8de28d8000 nid=0x5f03 waiting on condition [0x000000011fb12000] "default-akka.actor.default-dispatcher-3" prio=5 tid=0x00007f8de28e2800 nid=0x5d03 waiting on condition [0x000000011fa0f000] "default-akka.actor.default-dispatcher-2" prio=5 tid=0x00007f8de3158000 nid=0x5b03 waiting on condition [0x000000011f90c000] "default-scheduler-1" prio=5 tid=0x00007f8de3854800 nid=0x5903 waiting on condition [0x000000011f809000] "Service Thread" daemon prio=5 tid=0x00007f8de5001000 nid=0x5303 runnable [0x0000000000000000] "C2 CompilerThread1" daemon prio=5 tid=0x00007f8de4805000 nid=0x5103 waiting on condition [0x0000000000000000] "C2 CompilerThread0" daemon prio=5 tid=0x00007f8de303c800 nid=0x4f03 waiting on condition [0x0000000000000000] "Signal Dispatcher" daemon prio=5 tid=0x00007f8de303b800 nid=0x4d03 runnable [0x0000000000000000] "Finalizer" daemon prio=5 tid=0x00007f8de3803800 nid=0x3903 in Object.wait() [0x000000011e8a2000] "Reference Handler" daemon prio=5 tid=0x00007f8de3034800 nid=0x3703 in Object.wait() [0x000000011e79f000] "VM Thread" prio=5 tid=0x00007f8de3033800 nid=0x3503 runnable "GC task thread#0 (ParallelGC)" prio=5 tid=0x00007f8de281a800 nid=0x2503 runnable "GC task thread#1 (ParallelGC)" prio=5 tid=0x00007f8de4800000 nid=0x2703 runnable "GC task thread#2 (ParallelGC)" prio=5 tid=0x00007f8de281b800 nid=0x2903 runnable "GC task thread#3 (ParallelGC)" prio=5 tid=0x00007f8de281c000 nid=0x2b03 runnable "GC task thread#4 (ParallelGC)" prio=5 tid=0x00007f8de281c800 nid=0x2d03 runnable "GC task thread#5 (ParallelGC)" prio=5 tid=0x00007f8de5000000 nid=0x2f03 runnable "GC task thread#6 (ParallelGC)" prio=5 tid=0x00007f8de4801000 nid=0x3103 runnable "GC task thread#7 (ParallelGC)" prio=5 tid=0x00007f8de5800000 nid=0x3303 runnable "VM Periodic Task Thread" prio=5 tid=0x00007f8de480d800 nid=0x5503 waiting on condition Dynamic Attach機能に利用される(jmap, jstackなどのJVM内部の情報取得や 挙動の操作など) VMをアンロードするためのリスナー(JVMアプリケーション以外 からJVMを利用している場合にVMをDestroyできるように) JIT(HotSpot)で使うネイティブコンパイルスレッド() GCを走らせるなどのVMのオペレーションを行うスレッド マイナーGC用のスレッド finalizeメソッドが定義されているオブジェクトの実行スレッド OSからのシグナルを受け付ける
"Attach Listener" daemon prio=5 tid=0x00007f8de5852000 nid=0x3b07 waiting on condition [0x0000000000000000] "DestroyJavaVM" prio=5 tid=0x00007f8de280b800 nid=0x1903 waiting on condition [0x0000000000000000] "default-akka.actor.default-dispatcher-4" prio=5 tid=0x00007f8de28d8000 nid=0x5f03 waiting on condition [0x000000011fb12000] "default-akka.actor.default-dispatcher-3" prio=5 tid=0x00007f8de28e2800 nid=0x5d03 waiting on condition [0x000000011fa0f000] "default-akka.actor.default-dispatcher-2" prio=5 tid=0x00007f8de3158000 nid=0x5b03 waiting on condition [0x000000011f90c000] "default-scheduler-1" prio=5 tid=0x00007f8de3854800 nid=0x5903 waiting on condition [0x000000011f809000] "Service Thread" daemon prio=5 tid=0x00007f8de5001000 nid=0x5303 runnable [0x0000000000000000] "C2 CompilerThread1" daemon prio=5 tid=0x00007f8de4805000 nid=0x5103 waiting on condition [0x0000000000000000] "C2 CompilerThread0" daemon prio=5 tid=0x00007f8de303c800 nid=0x4f03 waiting on condition [0x0000000000000000] "Signal Dispatcher" daemon prio=5 tid=0x00007f8de303b800 nid=0x4d03 runnable [0x0000000000000000] "Finalizer" daemon prio=5 tid=0x00007f8de3803800 nid=0x3903 in Object.wait() [0x000000011e8a2000] "Reference Handler" daemon prio=5 tid=0x00007f8de3034800 nid=0x3703 in Object.wait() [0x000000011e79f000] "VM Thread" prio=5 tid=0x00007f8de3033800 nid=0x3503 runnable "GC task thread#0 (ParallelGC)" prio=5 tid=0x00007f8de281a800 nid=0x2503 runnable "GC task thread#1 (ParallelGC)" prio=5 tid=0x00007f8de4800000 nid=0x2703 runnable "GC task thread#2 (ParallelGC)" prio=5 tid=0x00007f8de281b800 nid=0x2903 runnable "GC task thread#3 (ParallelGC)" prio=5 tid=0x00007f8de281c000 nid=0x2b03 runnable "GC task thread#4 (ParallelGC)" prio=5 tid=0x00007f8de281c800 nid=0x2d03 runnable "GC task thread#5 (ParallelGC)" prio=5 tid=0x00007f8de5000000 nid=0x2f03 runnable "GC task thread#6 (ParallelGC)" prio=5 tid=0x00007f8de4801000 nid=0x3103 runnable "GC task thread#7 (ParallelGC)" prio=5 tid=0x00007f8de5800000 nid=0x3303 runnable "VM Periodic Task Thread" prio=5 tid=0x00007f8de480d800 nid=0x5503 waiting on condition Akkaのスレッド
"default-akka.actor.default-dispatcher-24" prio=5 tid=0x00007fef1e054800 nid=0x9003 waiting for monitor entry [0x0000000114423000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211) - waiting to lock <0x0000000701d22d00> (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:175) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395) Blockしてる
"default-akka.actor.default-dispatcher-24" prio=5 tid=0x00007fef1e054800 nid=0x9003 waiting for monitor entry [0x0000000114423000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211) - waiting to lock <0x0000000701d22d00> (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:175) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395) Lockを取得しよう として待ってる "default-akka.actor.default-dispatcher-18" prio=5 tid=0x00007fef1a99f800 nid=0x7f03 waiting for monitor entry [0x0000000113e11000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211) - locked <0x0000000701d22d00> (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:175) Lockしてる
ch.qos.logback.core.OutputStreamAppender#subAppend(E event) synchronized (lock) { writeOut(event); } Block !
Jvm operation casual talks
• Do the blocking call within an actor (or a set of actors managed by a router [Java, Scala]), making sure to configure a thread pool which is either dedicated for this purpose or sufficiently sized. ! • Do the blocking call within a Future, ensuring an upper bound on the number of such calls at any point in time (submitting an unbounded number of tasks of this nature will exhaust your memory or thread limits). ! • Do the blocking call within a Future, providing a thread pool with an upper limit on the number of threads which is appropriate for the hardware on which the application runs. ! • Dedicate a single thread to manage a set of blocking resources (e.g. a NIO selector driving multiple channels) and dispatch events as they occur as actor messages. The non-exhaustive list of adequate solutions to the “blocking problem”
ノンブロッキングアーキテクチャは I/Oを伴う処理は非常にセンシティブ まとめ Akkaにはログを非同期で出力できるユーティリティが用意されているのでそれを使おう おかしいなと思ったらまずは Thread dump
おわり

More Related Content

Jvm operation casual talks

  • 2. 渡辺 雄作(35) / @waysaku ソフトウェアエンジニア 株式会社サイバーエージェント アドテク本部 (Webシステム)
  • 4. spray is an open-source toolkit for building REST/HTTP- based integration layers on top of Scala and Akka. Being asynchronous, actor-based, fast, lightweight, modular and testable it's a great way to connect your Scala applications to the world.
  • 10. Cpu0 : 2.3%us, 0.7%sy, 0.0%ni, 97.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu1 : 0.3%us, 0.3%sy, 0.0%ni, 99.3%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu2 : 92.0%us, 6.0%sy, 0.0%ni, 2.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu3 : 5.4%us, 1.7%sy, 0.0%ni, 93.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st スループットが全然出ないと思ったら、 CPU一個しか使ってない！ そのくせロードアベレージが無駄に高い • Linuxの基本的な情報を取得
  • 11. Thread Dumpを取得する "Attach Listener" daemon prio=5 tid=0x00007f8de5852000 nid=0x3b07 waiting on condition [0x0000000000000000] "DestroyJavaVM" prio=5 tid=0x00007f8de280b800 nid=0x1903 waiting on condition [0x0000000000000000] "default-akka.actor.default-dispatcher-4" prio=5 tid=0x00007f8de28d8000 nid=0x5f03 waiting on condition [0x000000011fb12000] "default-akka.actor.default-dispatcher-3" prio=5 tid=0x00007f8de28e2800 nid=0x5d03 waiting on condition [0x000000011fa0f000] "default-akka.actor.default-dispatcher-2" prio=5 tid=0x00007f8de3158000 nid=0x5b03 waiting on condition [0x000000011f90c000] "default-scheduler-1" prio=5 tid=0x00007f8de3854800 nid=0x5903 waiting on condition [0x000000011f809000] "Service Thread" daemon prio=5 tid=0x00007f8de5001000 nid=0x5303 runnable [0x0000000000000000] "C2 CompilerThread1" daemon prio=5 tid=0x00007f8de4805000 nid=0x5103 waiting on condition [0x0000000000000000] "C2 CompilerThread0" daemon prio=5 tid=0x00007f8de303c800 nid=0x4f03 waiting on condition [0x0000000000000000] "Signal Dispatcher" daemon prio=5 tid=0x00007f8de303b800 nid=0x4d03 runnable [0x0000000000000000] "Finalizer" daemon prio=5 tid=0x00007f8de3803800 nid=0x3903 in Object.wait() [0x000000011e8a2000] "Reference Handler" daemon prio=5 tid=0x00007f8de3034800 nid=0x3703 in Object.wait() [0x000000011e79f000] "VM Thread" prio=5 tid=0x00007f8de3033800 nid=0x3503 runnable "GC task thread#0 (ParallelGC)" prio=5 tid=0x00007f8de281a800 nid=0x2503 runnable "GC task thread#1 (ParallelGC)" prio=5 tid=0x00007f8de4800000 nid=0x2703 runnable "GC task thread#2 (ParallelGC)" prio=5 tid=0x00007f8de281b800 nid=0x2903 runnable "GC task thread#3 (ParallelGC)" prio=5 tid=0x00007f8de281c000 nid=0x2b03 runnable "GC task thread#4 (ParallelGC)" prio=5 tid=0x00007f8de281c800 nid=0x2d03 runnable "GC task thread#5 (ParallelGC)" prio=5 tid=0x00007f8de5000000 nid=0x2f03 runnable "GC task thread#6 (ParallelGC)" prio=5 tid=0x00007f8de4801000 nid=0x3103 runnable "GC task thread#7 (ParallelGC)" prio=5 tid=0x00007f8de5800000 nid=0x3303 runnable "VM Periodic Task Thread" prio=5 tid=0x00007f8de480d800 nid=0x5503 waiting on condition Dynamic Attach機能に利用される(jmap, jstackなどのJVM内部の情報取得や 挙動の操作など) VMをアンロードするためのリスナー(JVMアプリケーション以外 からJVMを利用している場合にVMをDestroyできるように) JIT(HotSpot)で使うネイティブコンパイルスレッド() GCを走らせるなどのVMのオペレーションを行うスレッド マイナーGC用のスレッド finalizeメソッドが定義されているオブジェクトの実行スレッド OSからのシグナルを受け付ける
  • 12. "Attach Listener" daemon prio=5 tid=0x00007f8de5852000 nid=0x3b07 waiting on condition [0x0000000000000000] "DestroyJavaVM" prio=5 tid=0x00007f8de280b800 nid=0x1903 waiting on condition [0x0000000000000000] "default-akka.actor.default-dispatcher-4" prio=5 tid=0x00007f8de28d8000 nid=0x5f03 waiting on condition [0x000000011fb12000] "default-akka.actor.default-dispatcher-3" prio=5 tid=0x00007f8de28e2800 nid=0x5d03 waiting on condition [0x000000011fa0f000] "default-akka.actor.default-dispatcher-2" prio=5 tid=0x00007f8de3158000 nid=0x5b03 waiting on condition [0x000000011f90c000] "default-scheduler-1" prio=5 tid=0x00007f8de3854800 nid=0x5903 waiting on condition [0x000000011f809000] "Service Thread" daemon prio=5 tid=0x00007f8de5001000 nid=0x5303 runnable [0x0000000000000000] "C2 CompilerThread1" daemon prio=5 tid=0x00007f8de4805000 nid=0x5103 waiting on condition [0x0000000000000000] "C2 CompilerThread0" daemon prio=5 tid=0x00007f8de303c800 nid=0x4f03 waiting on condition [0x0000000000000000] "Signal Dispatcher" daemon prio=5 tid=0x00007f8de303b800 nid=0x4d03 runnable [0x0000000000000000] "Finalizer" daemon prio=5 tid=0x00007f8de3803800 nid=0x3903 in Object.wait() [0x000000011e8a2000] "Reference Handler" daemon prio=5 tid=0x00007f8de3034800 nid=0x3703 in Object.wait() [0x000000011e79f000] "VM Thread" prio=5 tid=0x00007f8de3033800 nid=0x3503 runnable "GC task thread#0 (ParallelGC)" prio=5 tid=0x00007f8de281a800 nid=0x2503 runnable "GC task thread#1 (ParallelGC)" prio=5 tid=0x00007f8de4800000 nid=0x2703 runnable "GC task thread#2 (ParallelGC)" prio=5 tid=0x00007f8de281b800 nid=0x2903 runnable "GC task thread#3 (ParallelGC)" prio=5 tid=0x00007f8de281c000 nid=0x2b03 runnable "GC task thread#4 (ParallelGC)" prio=5 tid=0x00007f8de281c800 nid=0x2d03 runnable "GC task thread#5 (ParallelGC)" prio=5 tid=0x00007f8de5000000 nid=0x2f03 runnable "GC task thread#6 (ParallelGC)" prio=5 tid=0x00007f8de4801000 nid=0x3103 runnable "GC task thread#7 (ParallelGC)" prio=5 tid=0x00007f8de5800000 nid=0x3303 runnable "VM Periodic Task Thread" prio=5 tid=0x00007f8de480d800 nid=0x5503 waiting on condition Akkaのスレッド
  • 13. "default-akka.actor.default-dispatcher-24" prio=5 tid=0x00007fef1e054800 nid=0x9003 waiting for monitor entry [0x0000000114423000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211) - waiting to lock <0x0000000701d22d00> (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:175) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395) Blockしてる
  • 14. "default-akka.actor.default-dispatcher-24" prio=5 tid=0x00007fef1e054800 nid=0x9003 waiting for monitor entry [0x0000000114423000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211) - waiting to lock <0x0000000701d22d00> (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:175) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395) Lockを取得しよう として待ってる "default-akka.actor.default-dispatcher-18" prio=5 tid=0x00007fef1a99f800 nid=0x7f03 waiting for monitor entry [0x0000000113e11000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211) - locked <0x0000000701d22d00> (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:175) Lockしてる
  • 17. • Do the blocking call within an actor (or a set of actors managed by a router [Java, Scala]), making sure to configure a thread pool which is either dedicated for this purpose or sufficiently sized. ! • Do the blocking call within a Future, ensuring an upper bound on the number of such calls at any point in time (submitting an unbounded number of tasks of this nature will exhaust your memory or thread limits). ! • Do the blocking call within a Future, providing a thread pool with an upper limit on the number of threads which is appropriate for the hardware on which the application runs. ! • Dedicate a single thread to manage a set of blocking resources (e.g. a NIO selector driving multiple channels) and dispatch events as they occur as actor messages. The non-exhaustive list of adequate solutions to the “blocking problem”