KamonとDatadogを使ってAkka actorのパフォーマンスを可視化する |

Blog

2015.9.24

KamonとDatadogを使ってAkka actorのパフォーマンスを可視化する

こんにちは、CA ProFit-X の塚本です。

先日ご紹介いたしました、同チームの松村の記事はいかがでしたでしょうか。

上記の記事では応答時間など特定の値を収集するためにKamonというJVMのモニタリングを行うライブラリを用いています。（KamonはAkka actorをモニタリングすることもできます。）また、その収集した値を保存し可視化するために、モニタリングサービスであるDatadogというクラウドサービスを用いています。

この記事では主にKamonとDatadogをメインに、私たちCA ProFit-Xが行っているモニタリングの方法についてご紹介して行きます。

Datadogとは

Datadogとはクラウドのモニタリングサービスです。詳しくは以下のリンクをご覧ください。無料で簡単に利用できますので、試してみると良いかと思います。

モニタリングサービス Datadogの解説！

Datadogの本当の魅力とは

Datadog公式サイト

Datadog日本語blog

Kamonとは

KamonとはJVMのモニタリングを行うライブラリで、Akka actorを監視することもできます。

Kamon

Kamon (GitHub)

Mailboxにどの程度メッセージが溜まっているかや、Actorのエラーの数などをモニタリングできます。

複数の統合機能が用意されているため、Actorだけでなく、SprayやPlayなどのWebアプリケーションフレームワークなどの監視も行うことができます。また、独自に数値をカウントすることもできます。

例えばkamon-sprayというSprayの統合機能を使うと、sprayに来たHTTPリクエストがどの程度の時間で処理できたかを可視化できます。

使い方は簡単で、以下のGet startedが参考になると思います。（これとは別に後でサンプルを載せます）

http://kamon.io/introduction/get-started/

ProFit-Xチームでは0.3の頃から使っていて、2度ほどメモリリークのバグを踏むという悲しみを味わいましたが、最近は0.5も出てそれらも修正されました。開発はかなり活発な方で、良いOSSだと思います。

Akka actorとは

Akka actorは並列処理を行うためのフレームワークです。詳しくは弊社の以下の記事をご覧ください。

【Akka入門の入門】Part.1 メッセージを送る

【Akka入門の入門】Part.2 アクター子アクター孫アクター

Akka actorのパフォーマンスをKamonを使って収集し、値をDatadogに送信する

ここまでで使っている技術について説明しました。ここからは簡単なSpray(spray-routing)アプリケーションを作成し、Kamonを使って値を取得してみます。

順を追って１つずつ説明して行きます。初めから全てのコードが見たい、動かしたいという方は以下に実行可能なサンプルを置いていますので、ご覧下さい。sbt runで動かすことができます。

https://github.com/tsukaby/kamon-spray-example

これだけでは分からない場合や、Spray以外のケースも見ておきたい方は公式のexampleをご覧下さい。

https://github.com/kamon-io/Kamon/tree/master/kamon-examples

Sprayアプリ

まずはspray-routingとActorを使って簡単なHTTPサーバアプリケーションを作成します。

https://github.com/tsukaby/kamon-spray-example/commit/8c3acc6ed73a07fbeb25e3d9c3fc3c293f85dd56

上記のコミットのようにlibraryDependenciesを追加してからMainのコードを記述します。

import java.util.UUID

import UUIDService.Protocol.Generate
import akka.actor.{Actor, ActorSystem, Props}
import akka.pattern._
import akka.util.Timeout
import spray.routing.SimpleRoutingApp

import scala.concurrent.duration._
import scala.language.postfixOps

object Main extends App with SimpleRoutingApp {
  implicit val system = ActorSystem("my-system")
  implicit val timeout = Timeout(5 seconds)

  import system.dispatcher

  val personService = system.actorOf(Props(classOf[UUIDService]), "uuid_service")

  startServer(interface = "localhost", port = 8080) {
    path("uuid") {
      get {
        complete(
          personService.ask(UUIDService.Protocol.Generate()).mapTo[UUID].map(_.toString)
        )
      }
    }
  }
}

class UUIDService extends Actor {
  override def receive: Receive = {
    case Generate() => sender() ! UUID.randomUUID()
  }
}

object UUIDService {

  object Protocol {

    sealed case class Generate()

  }

}

import java.util.UUID

import UUIDService.Protocol.Generate

import akka.actor.{Actor, ActorSystem, Props}

import akka.pattern._

import akka.util.Timeout

import spray.routing.SimpleRoutingApp

import scala.concurrent.duration._

import scala.language.postfixOps

object Main extends App with SimpleRoutingApp {

implicit val system = ActorSystem("my-system")

implicit val timeout = Timeout(5 seconds)

import system.dispatcher

val personService = system.actorOf(Props(classOf[UUIDService]), "uuid_service")

startServer(interface = "localhost", port = 8080) {

path("uuid") {

get {

complete(

personService.ask(UUIDService.Protocol.Generate()).mapTo[UUID].map(_.toString)

)

}

class UUIDService extends Actor {

override def receive: Receive = {

case Generate() => sender() ! UUID.randomUUID()

}

object UUIDService {

object Protocol {

sealed case class Generate()

}

Sprayアプリの動作確認

sbt runで実行できます。http://localhost:8080/uuidにGETでアクセスするとランダムなUUIDが返るというアプリケーションができました。

[shuya@PC kamon-spray-example]% curl http://localhost:8080/uuid
6aa73413-6f2b-4a57-ac5e-4d7bba82b6b9

1 2	[shuya@PC kamon-spray-example]% curl http://localhost:8080/uuid 6aa73413-6f2b-4a57-ac5e-4d7bba82b6b9

Kamonを入れる

次にKamonを導入します。

https://github.com/tsukaby/kamon-spray-example/commit/c928d8bfa2c953acf1198bfb933e805a1af19298

このコミットを参考にlibraryDependenciesとconfファイル作成、コードの変更を行います。

Main.scalaはこのように変わりました。

object Main extends App with SimpleRoutingApp with KamonTraceDirectives {
  Kamon.start()

  ...

  startServer(interface = "localhost", port = 8080) {
    path("uuid") {
      traceName("get:uuid") {

  ...

object Main extends App with SimpleRoutingApp with KamonTraceDirectives {

Kamon.start()

...

startServer(interface = "localhost", port = 8080) {

path("uuid") {

traceName("get:uuid") {

...

Kamon.start()はActorSystemを動かす前に呼び出しておいてください。traceNameはメモリリークの問題を回避するために付けておいてください(spray-routingだけの対応)

これをsbt runで動かすとsbt pluginによりAspectJのライブラリが自動的にDLされます。Kamonは特定のモジュールでAspectJを利用しています。詳細は以下のURLをご覧下さい。

http://kamon.io/introduction/overview/

今回利用しているkamon-akka、kamon-sprayなどのモジュールはrequires aspectjとなっているのでAspectJを入れています。

AspectJを利用する方法は以下のURLに記載してある方法を用いると良いと思います。

http://kamon.io/introduction/get-started/

sbt runの場合はsbt pluginが利用できますので、sbt-aspectj pluginを利用しています。javaコマンドでExecutable jar(Runnable jar, Fat jar)を実行する場合はManuallyの方法を用いると良いと思います。

Kamonの動作を確認する

ここまででサンプルアプリにKamonを入れました。Kamonはあくまでデータの収集がメインなので、データを見るには別の何かを利用する必要があります。2015年8月現在、公式には以下の手段が用意されています。

今回はDatadogを用いてデータを可視化しますが、まずは正しく動いているか確認してみます。そのためにはLogReporterを用いるのが最も簡単です。LogReporterはlibraryDependenciesに依存性を追加するだけで自動的に動くようになっています。上記のコミットでも追加しています。

ですので、sbt runコマンドを叩いて、少し負荷をかけてみます。10秒間隔でlogが表示されます。以下はその一部です。

# コンソールA
[shuya@PC kamon-spray-example]% sbt run

# コンソールB
[shuya@PC kamon-spray-example]% wrk -c 24 -t 4 -d 10m http://localhost:8080/uuid
Running 10m test @ http://localhost:8080/uuid
  4 threads and 24 connections

# コンソールA
# LogReporterが以下のような結果を出力する（本当はもっと大量に色々出ます）
[info] +--------------------------------------------------------------------------------------------------+
[info] [INFO] [08/31/2015 11:30:28.652] [kamon-akka.actor.default-dispatcher-11] [akka://kamon/user/kamon-log-reporter]
[info] +--------------------------------------------------------------------------------------------------+
[info] |                                                                                                  |
[info] |    Actor: my-system/user/uuid_service                                                            |
[info] |                                                                                                  |
[info] |   Processing Time (nanoseconds)      Time in Mailbox (nanoseconds)         Mailbox Size          |
[info] |    Msg Count: 359175                     Msg Count: 359174                   Min: 0              |
[info] |          Min: 3552                             Min: 226                     Avg.: 8.0            |
[info] |    50th Perc: 13312                      50th Perc: 90112                    Max: 25             |
[info] |    90th Perc: 22784                      90th Perc: 236544                                       |
[info] |    95th Perc: 27520                      95th Perc: 284672                                       |
[info] |    99th Perc: 67584                      99th Perc: 391168                 Error Count: 0        |
[info] |  99.9th Perc: 159744                   99.9th Perc: 1392640                                      |
[info] |          Max: 50593792                         Max: 50593792                                     |
[info] |                                                                                                  |
[info] +--------------------------------------------------------------------------------------------------+

# コンソールA

[shuya@PC kamon-spray-example]% sbt run

# コンソールB

[shuya@PC kamon-spray-example]% wrk -c 24 -t 4 -d 10m http://localhost:8080/uuid

Running 10m test @ http://localhost:8080/uuid

4 threads and 24 connections

# コンソールA

# LogReporterが以下のような結果を出力する（本当はもっと大量に色々出ます）

[info] +--------------------------------------------------------------------------------------------------+

[info] [INFO] [08/31/2015 11:30:28.652] [kamon-akka.actor.default-dispatcher-11] [akka://kamon/user/kamon-log-reporter]

[info] +--------------------------------------------------------------------------------------------------+

[info] | |

[info] | Actor: my-system/user/uuid_service |

[info] | |

[info] | Processing Time (nanoseconds) Time in Mailbox (nanoseconds) Mailbox Size |

[info] | Msg Count: 359175 Msg Count: 359174 Min: 0 |

[info] | Min: 3552 Min: 226 Avg.: 8.0 |

[info] | 50th Perc: 13312 50th Perc: 90112 Max: 25 |

[info] | 90th Perc: 22784 90th Perc: 236544 |

[info] | 95th Perc: 27520 95th Perc: 284672 |

[info] | 99th Perc: 67584 99th Perc: 391168 Error Count: 0 |

[info] | 99.9th Perc: 159744 99.9th Perc: 1392640 |

[info] | Max: 50593792 Max: 50593792 |

[info] | |

[info] +--------------------------------------------------------------------------------------------------+

これはuuid_serviceというActorのモニタリング結果です。例えば処理時間は中央値0.013 ms、メールボックスには平均8メッセージ蓄積、というようなことが分かります。

Kamonの独自集計の仕組み（メトリクス、トレーサー）を利用する

上記のモニタリング結果はkamon-akkaモジュールが自動的に収集した結果です。自動でやってくれるのは勿論良いのですが、時には手動で適切な場所に集計処理を埋め込みたいときがあります。Kamonでは独自に集計を行うための機能があるので、それを利用します。

https://github.com/tsukaby/kamon-spray-example/commit/0750de16f0102b37182924659b2e2ae5383e27e4

このコミットを参考にUUIDServiceを変えてゆきます。

class UUIDService extends Actor {
  val counter = Kamon.metrics.counter("uuid-count")
  val minMaxCounter = Kamon.metrics.minMaxCounter("uuid-min-max")
  val histogram = Kamon.metrics.histogram("uuid-histogram")
  val gauge = Kamon.metrics.gauge("uuid-gauge")(0L)

  override def receive: Receive = {
    case Generate() =>
      val currentMillis = System.currentTimeMillis()

      counter.increment()
      if(currentMillis % 2 == 0) minMaxCounter.increment() else minMaxCounter.decrement()
      histogram.record(currentMillis % 1000)
      gauge.record(currentMillis % 1000)

      val uuid = Tracer.withNewContext("uuid-generate", autoFinish = true) {
        UUID.randomUUID()
      }
      sender() ! uuid
  }
}

class UUIDService extends Actor {

val counter = Kamon.metrics.counter("uuid-count")

val minMaxCounter = Kamon.metrics.minMaxCounter("uuid-min-max")

val histogram = Kamon.metrics.histogram("uuid-histogram")

val gauge = Kamon.metrics.gauge("uuid-gauge")(0L)

override def receive: Receive = {

case Generate() =>

val currentMillis = System.currentTimeMillis()

counter.increment()

if(currentMillis % 2 == 0) minMaxCounter.increment() else minMaxCounter.decrement()

histogram.record(currentMillis % 1000)

gauge.record(currentMillis % 1000)

val uuid = Tracer.withNewContext("uuid-generate", autoFinish = true) {

UUID.randomUUID()

}

sender() ! uuid

}

counterやhistogramなどを追加していますが、これがメトリクスです。

Counterはincrement()あるいはincrement(Long)だけ行うことが出来ます。例えばアプリケーション内で発行したSQLの成功回数、失敗回数をそれぞれカウントする、というような使い方があるかと思います。

MinMaxCounterはdecrementも可能なCounterです。

Histogramはそのときの値を収集するためのメトリクスです。例えば現在のCPU利用率・現在のメモリ使用量、などを収集するという使い方があるかと思います。（ちなみにCPUとメモリはkamon-system-metricsで自動的に収集できます）

Gaugeは良くわかっていません。（すみません）

ProFit-XチームではCounterのみ利用しています。Histogramは今後利用するシーンが出てくるかもしれません。この辺りはアプリケーションの特性によって変わりそうですね。

Tracer.withNewContextがトレーサーです。その後のブロックで囲った処理の実行時間を収集してくれます。

この状態で動作させると、LogReporterが以下のような結果を出力します。

[info] +--------------------------------------------------------------------------------------------------+
[info] [INFO] [08/31/2015 11:56:35.774] [kamon-akka.actor.default-dispatcher-7] [akka://kamon/user/kamon-log-reporter]
[info] +--------------------------------------------------------------------------------------------------+
[info] |                                                                                                  |
[info] |                                         Counters                                                 |
[info] |                                       -------------                                              |
[info] |                                 uuid-count  =>  401415                                           |
[info] |                                                                                                  |
[info] |                                                                                                  |
[info] |                                        Histograms                                                |
[info] |                                      --------------                                              |
[info] |  uuid-histogram                                                                                  |
[info] |    Min: 0            50th Perc: 486            90th Perc: 892            95th Perc: 952          |
[info] |                      99th Perc: 988          99.9th Perc: 996                  Max: 996          |
[info] |                                                                                                  |
[info] |                                                                                                  |
[info] |                                      MinMaxCounters                                              |
[info] |                                    -----------------                                             |
[info] |  uuid-min-max                                                                                    |
[info] |          Min: 0                      Average: 188.0                       Max: 568               |
[info] |                                                                                                  |
[info] |                                                                                                  |
[info] |                                          Gauges                                                  |
[info] |                                        ----------                                                |
[info] |  uuid-gauge                                                                                      |
[info] |          Min: 0                      Average: 492.0                       Max: 996               |
[info] |                                                                                                  |
[info] |                                                                                                  |
[info] +--------------------------------------------------------------------------------------------------+

[info] +--------------------------------------------------------------------------------------------------+

[info] [INFO] [08/31/2015 11:56:35.774] [kamon-akka.actor.default-dispatcher-7] [akka://kamon/user/kamon-log-reporter]

[info] +--------------------------------------------------------------------------------------------------+

[info] | |

[info] | Counters |

[info] | ------------- |

[info] | uuid-count => 401415 |

[info] | |

[info] | Histograms |

[info] | -------------- |

[info] | uuid-histogram |

[info] | Min: 0 50th Perc: 486 90th Perc: 892 95th Perc: 952 |

[info] | 99th Perc: 988 99.9th Perc: 996 Max: 996 |

[info] | |

[info] | MinMaxCounters |

[info] | ----------------- |

[info] | uuid-min-max |

[info] | Min: 0 Average: 188.0 Max: 568 |

[info] | |

[info] | Gauges |

[info] | ---------- |

[info] | uuid-gauge |

[info] | Min: 0 Average: 492.0 Max: 996 |

[info] | |

[info] +--------------------------------------------------------------------------------------------------+

（Counter以外は特に意味のない値ですが、）正しく値が取れていることを確認できました。

トレーサーの結果はまた別に出ているのですが、ここでは一旦省略します。（後で出てきます）

Datadogへデータを送る

ここまでで、Spray + Kamonのアプリケーションを作成して来ました。Kamonの確認にLogReporterを用いましたが、これは公式にもデバッグ用で本番環境には向いていないと言われています。（実際に見辛いですし）

そのため、ここではDatadogというクラウドサービスを用いてデータを可視化して行きます。

Datadogについては手前味噌ですが、以前自分のblogに記事を書いていますので、そちらをご覧下さい。Datadogのエージェントをご自身のPCにインストールしておく必要があるのですが、その方法も書いていますのでご覧下さい。

モニタリングサービス Datadogの解説！

もちろん、上記で作成したアプリケーションを動作させる環境がご自身のPCではなく、別のLinux上などであれば、そちらの環境上にDatadog Agentをインストールしてください。

実はDatadogのアカウントを作成して、Agentをインストール（起動）して、sbt runでここまで作成してきたアプリを実行すればDatadogとの連携は終わりです。

libraryDependenciesに追加したkamon-datadogのデフォルトの設定は以下のようになっています。

https://github.com/kamon-io/Kamon/blob/master/kamon-datadog/src/main/resources/reference.conf#L9-L10

kamon {
  datadog {
    # Hostname and port in which your Datadog is running. Remember that Datadog packets are sent using UDP and
    # setting unreachable hosts and/or not open ports wont be warned by the Kamon, your data wont go anywhere.
    hostname = "127.0.0.1"
    port = 8125

    ...

kamon {

datadog {

# Hostname and port in which your Datadog is running. Remember that Datadog packets are sent using UDP and

# setting unreachable hosts and/or not open ports wont be warned by the Kamon, your data wont go anywhere.

hostname = "127.0.0.1"

port = 8125

...

デフォルトで自身の8125にデータを送信するようになっており、Datadog agentもまたデフォルト8125で待ち受けているので後は勝手に連携してくれるという感じになっています。

Datadogのグラフを作成し、可視化する

いよいよ可視化の段階まで来ました。予め上記のアプリを起動してwrkやabコマンドなどで適度に負荷をかけておき、Datadogに数値を送っておいてください。

Datadogの画面へ行き、Dashboardを作成します。

まずはtraceのグラフを作ります。kamon-sprayによって自動的にトレースしたuuidエンドポイントの処理時間と、独自にTraceを埋め込んだUUIDのランダム生成の処理時間、２つのグラフを作成します。

トレースは単位がnano secondsで少々分かり辛いため、 / 1000000して、milli secondsに変換しておきます。

次にActorの様子を見るためのグラフも追加します。

長くなるので省略しますが、このような感じで各種グラフを作成して行きます。最終的にこのようなダッシュボードが完成しました。

無事Kamonの値を可視化できました・・・！

このダッシュボードのおかげで大体以下のような状況であることが確認できます。

uuidのエンドポイントは大体3ms程度で処理を完了している。ときどき遅くて10ms程度になる。
uuidエンドポイントの中のuuid生成処理は0.5ms程度で完了している。
uuidのActorには常にメッセージが10個程度溜まっているので、少し溜まっているかもしれない（グラフは上昇していないので消化はできている）
一番メールが溜まっているのはio-tcp/selectors
etc

Kamon + Datadogの可視化は本当に使えるのか？

上記のようなダッシュボードを作成しましたが、本当に使えるのか若干疑問があるかと思います。そこでもうすこしだけグラフに付き合ってみます。

Datadogには様々なインテグレーションやアラートなどの機能があるのですが、それは別途設定するなどしてください。ここでは主にKamonについて触れて行きます。

例えばもしプログラムに良くない変更が加わったとします。ここでは簡略化のためにUUIDを生成するActorの処理の部分にThread.sleep(50)を入れてみます。少し重たい処理を入れてしまった、という想定です。

      val uuid = Tracer.withNewContext("uuid-generate", autoFinish = true) {
        Thread.sleep(50)
        UUID.randomUUID()
      }

val uuid = Tracer.withNewContext("uuid-generate", autoFinish = true) {

Thread.sleep(50)

UUID.randomUUID()

}

この状態で再度sbt runを行い、負荷をかけてみます。

Traceが大きく跳ね上がっています。uuid-generateがsleep 50msを仕込んだせいで50ms程度遅くなっていることが分かります。get:uuidは1sec近く遅くなっていることが分かります。なぜかは調べないと分かりませんが、これは良くない状況であることが分かります。

Traceが跳ね上がった反面、cpu_userは大きく下がっています。Thread.sleepによって明らかにCPUがさぼっていることが分かります。mailboxのカウント数が上がっていませんが、これはActorSystemが使えるスレッドが全てSleepしてしまったためだと思います。使えるスレッドが無いため、mailboxのカウントは上がりませんが、その代わりにuuid_serviceのmailboxにmailを渡す前段階であるmy-system/system/io-tcp/selectorsのmailbox sizeが52.72と、上昇していることが分かります。

Kamon + DatadogによってActorの挙動やSprayの挙動を監視しておけば良くないリリースや、障害などをいち早く検知し、対策できる状況になると思います。個人的な感想ですが、Kamon + Datadogの可視化はかなり有益だと思っています。

まとめ

Datadog、Kamon、Sprayなどについて簡単に説明を行いました
サンプルアプリを作りながらKamonについて解説しました
Datadogを用いてKamonのデータの可視化を行いました
プログラムに問題があったときにDatadogのグラフがどのように変化するのか例を示しました

いかがでしたでしょうか。KamonとDatadogを利用してAkka actor（また、その他）のパフォーマンスを可視化することで、システムの様子を具体的に把握できるようになります。

運用をしながら開発を行う場合、障害を検知するコストや障害に対応するコスト、それらから来る精神的な負担は無視できません。今回ご紹介しましたKamon + Datadogという仕組みを用いて、みなさんも快適な開発ライフをお過ごし下さい！

塚本

Author

shuya