+ logreporter: new log reporter for trace, actor and user metrics, closes #57

The new kamon-log-reporter module subscribes itselfs for trace, actor
and user metrics and prints the values using ActorLogging in a pretty
ascii table format.

4 files changed, 253 insertions, 4 deletions

diff --git a/kamon-log-reporter/src/main/scala/kamon/logreporter/LogReporter.scala b/kamon-log-reporter/src/main/scala/kamon/logreporter/LogReporter.scala
new file mode 100644
index 00000000..b0cc2551
--- /dev/null
+++ b/kamon-log-reporter/src/main/scala/kamon/logreporter/LogReporter.scala
@@ -0,0 +1,227 @@
+/*
+ * =========================================================================================
+ * Copyright © 2013-2014 the kamon project <http://kamon.io/>
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file
+ * except in compliance with the License. You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software distributed under the
+ * License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
+ * either express or implied. See the License for the specific language governing permissions
+ * and limitations under the License.
+ * =========================================================================================
+ */
+
+package kamon.logreporter
+
+import akka.actor._
+import kamon.Kamon
+import kamon.metric.ActorMetrics.ActorMetricSnapshot
+import kamon.metric.Subscriptions.TickMetricSnapshot
+import kamon.metric.TraceMetrics.TraceMetricsSnapshot
+import kamon.metric.UserMetrics.{ UserCounter, UserMetricsSnapshot }
+import kamon.metric.instrument.{ Counter, Histogram }
+import kamon.metric._
+
+object LogReporter extends ExtensionId[LogReporterExtension] with ExtensionIdProvider {
+  override def lookup(): ExtensionId[_ <: Extension] = LogReporter
+  override def createExtension(system: ExtendedActorSystem): LogReporterExtension = new LogReporterExtension(system)
+
+  trait MetricKeyGenerator {
+    def localhostName: String
+    def normalizedLocalhostName: String
+    def generateKey(groupIdentity: MetricGroupIdentity, metricIdentity: MetricIdentity): String
+  }
+}
+
+class LogReporterExtension(system: ExtendedActorSystem) extends Kamon.Extension {
+  val subscriber = system.actorOf(Props[LogReporterSubscriber], "kamon-log-reporter")
+  Kamon(Metrics)(system).subscribe(TraceMetrics, "*", subscriber, permanently = true)
+  Kamon(Metrics)(system).subscribe(ActorMetrics, "*", subscriber, permanently = true)
+  Kamon(Metrics)(system).subscribe(UserMetrics.category, "*", subscriber, permanently = true)
+
+}
+
+class LogReporterSubscriber extends Actor with ActorLogging {
+  import LogReporterSubscriber.RichHistogramSnapshot
+
+  def receive = {
+    case tick: TickMetricSnapshot ⇒ printMetricSnapshot(tick)
+  }
+
+  def printMetricSnapshot(tick: TickMetricSnapshot): Unit = tick.metrics foreach {
+    case (identity, ams: ActorMetricSnapshot)  ⇒ logActorMetrics(identity.name, ams)
+    case (identity, tms: TraceMetricsSnapshot) ⇒ logTraceMetrics(identity.name, tms)
+    case (_, ums: UserMetricsSnapshot)         ⇒ logUserMetrics(ums)
+  }
+
+  def logActorMetrics(name: String, ams: ActorMetricSnapshot): Unit = {
+    log.info(
+      """
+        |+--------------------------------------------------------------------------------------------------+
+        ||                                                                                                  |
+        ||    Actor: %-83s    |
+        ||                                                                                                  |
+        ||   Processing Time (nanoseconds)      Time in Mailbox (nanoseconds)         Mailbox Size          |
+        ||    Msg Count: %-12s               Msg Count: %-12s             Min: %-8s       |
+        ||          Min: %-12s                     Min: %-12s            Avg.: %-8s       |
+        ||    50th Perc: %-12s               50th Perc: %-12s             Max: %-8s       |
+        ||    90th Perc: %-12s               90th Perc: %-12s                                 |
+        ||    95th Perc: %-12s               95th Perc: %-12s                                 |
+        ||    99th Perc: %-12s               99th Perc: %-12s           Error Count: %-6s   |
+        ||  99.9th Perc: %-12s             99.9th Perc: %-12s                                 |
+        ||          Max: %-12s                     Max: %-12s                                 |
+        ||                                                                                                  |
+        |+--------------------------------------------------------------------------------------------------+"""
+        .stripMargin.format(
+          name,
+          ams.processingTime.numberOfMeasurements, ams.timeInMailbox.numberOfMeasurements, ams.mailboxSize.min,
+          ams.processingTime.min, ams.timeInMailbox.min, ams.mailboxSize.average,
+          ams.processingTime.percentile(0.50F), ams.timeInMailbox.percentile(0.50F), ams.mailboxSize.max,
+          ams.processingTime.percentile(0.90F), ams.timeInMailbox.percentile(0.90F),
+          ams.processingTime.percentile(0.95F), ams.timeInMailbox.percentile(0.95F),
+          ams.processingTime.percentile(0.99F), ams.timeInMailbox.percentile(0.99F), ams.errors.count,
+          ams.processingTime.percentile(0.999F), ams.timeInMailbox.percentile(0.999F),
+          ams.processingTime.max, ams.timeInMailbox.max))
+  }
+
+  def logTraceMetrics(name: String, tms: TraceMetricsSnapshot): Unit = {
+    val traceMetricsData = StringBuilder.newBuilder
+
+    traceMetricsData.append(
+      """
+        |+--------------------------------------------------------------------------------------------------+
+        ||                                                                                                  |
+        ||    Trace: %-83s    |
+        ||    Count: %-8s                                                                               |
+        ||                                                                                                  |
+        ||  Elapsed Time (nanoseconds):                                                                     |
+        |"""
+        .stripMargin.format(
+          name, tms.elapsedTime.numberOfMeasurements))
+
+    traceMetricsData.append(compactHistogramView(tms.elapsedTime))
+    traceMetricsData.append(
+      """
+        ||                                                                                                  |
+        |+--------------------------------------------------------------------------------------------------+"""
+        .stripMargin)
+
+    log.info(traceMetricsData.toString())
+  }
+
+  def logUserMetrics(ums: UserMetricsSnapshot): Unit = {
+    val userMetricsData = StringBuilder.newBuilder
+
+    userMetricsData.append(
+      """
+        |+--------------------------------------------------------------------------------------------------+
+        ||                                                                                                  |
+        ||                                       User Counters                                              |
+        ||                                       -------------                                              |
+        |""".stripMargin)
+
+    ums.counters.toList.sortBy(_._1.name.toLowerCase).foreach {
+      case (counter, snapshot) ⇒ userMetricsData.append(userCounterString(counter, snapshot))
+    }
+
+    userMetricsData.append(
+      """||                                                                                                  |
+        ||                                                                                                  |
+        ||                                      User Histograms                                             |
+        ||                                      ---------------                                             |
+        |""".stripMargin)
+
+    ums.histograms.foreach {
+      case (histogram, snapshot) ⇒
+        userMetricsData.append("|  %-40s                                                        |\n".format(histogram.name))
+        userMetricsData.append(compactHistogramView(snapshot))
+        userMetricsData.append("\n|                                                                                                  |\n")
+    }
+
+    userMetricsData.append(
+      """||                                                                                                  |
+        ||                                    User MinMaxCounters                                           |
+        ||                                    -------------------                                           |
+        |""".stripMargin)
+
+    ums.minMaxCounters.foreach {
+      case (minMaxCounter, snapshot) ⇒
+        userMetricsData.append("|  %-40s                                                        |\n".format(minMaxCounter.name))
+        userMetricsData.append(simpleHistogramView(snapshot))
+        userMetricsData.append("\n|                                                                                                  |\n")
+    }
+
+    userMetricsData.append(
+      """||                                                                                                  |
+        ||                                        User Gauges                                               |
+        ||                                        -----------                                               |
+        |"""
+        .stripMargin)
+
+    ums.gauges.foreach {
+      case (gauge, snapshot) ⇒
+        userMetricsData.append("|  %-40s                                                        |\n".format(gauge.name))
+        userMetricsData.append(simpleHistogramView(snapshot))
+        userMetricsData.append("\n|                                                                                                  |\n")
+    }
+
+    userMetricsData.append(
+      """||                                                                                                  |
+        |+--------------------------------------------------------------------------------------------------+"""
+        .stripMargin)
+
+    log.info(userMetricsData.toString())
+  }
+
+  def userCounterString(counter: UserCounter, snapshot: Counter.Snapshot): String = {
+    "|             %30s  =>  %-12s                                     |\n"
+      .format(counter.name, snapshot.count)
+  }
+
+  def compactHistogramView(histogram: Histogram.Snapshot): String = {
+    val sb = StringBuilder.newBuilder
+
+    sb.append("|    Min: %-11s  50th Perc: %-12s   90th Perc: %-12s   95th Perc: %-12s |\n".format(
+      histogram.min, histogram.percentile(0.50F), histogram.percentile(0.90F), histogram.percentile(0.95F)))
+    sb.append("|                      99th Perc: %-12s 99.9th Perc: %-12s         Max: %-12s |".format(
+      histogram.percentile(0.99F), histogram.percentile(0.999F), histogram.max))
+
+    sb.toString()
+  }
+
+  def simpleHistogramView(histogram: Histogram.Snapshot): String =
+    "|          Min: %-12s           Average: %-12s                Max: %-12s      |"
+      .format(histogram.min, histogram.average, histogram.max)
+}
+
+object LogReporterSubscriber {
+
+  implicit class RichHistogramSnapshot(histogram: Histogram.Snapshot) {
+    def percentile(q: Float): Long = {
+      val records = histogram.recordsIterator
+      val qThreshold = histogram.numberOfMeasurements * q
+      var countToCurrentLevel = 0L
+      var qLevel = 0L
+
+      while (countToCurrentLevel < qThreshold && records.hasNext) {
+        val record = records.next()
+        countToCurrentLevel += record.count
+        qLevel = record.level
+      }
+
+      qLevel
+    }
+
+    def average: Double = {
+      var acc = 0L
+      for (record ← histogram.recordsIterator) {
+        acc += record.count * record.level
+      }
+
+      return acc / histogram.numberOfMeasurements
+    }
+  }
+}
\ No newline at end of file
diff --git a/kamon-playground/src/main/resources/application.conf b/kamon-playground/src/main/resources/application.conf
index e9f73954..bac3c97e 100644
--- a/kamon-playground/src/main/resources/application.conf
+++ b/kamon-playground/src/main/resources/application.conf
@@ -1,7 +1,7 @@
 akka {
   loglevel = INFO
 
-  extensions = ["kamon.newrelic.NewRelic"]
+  extensions = ["kamon.logreporter.LogReporter"]
 
   actor {
     debug {
@@ -25,7 +25,7 @@ kamon {
 
 kamon {
   metrics {
-    tick-interval = 1 second
+    tick-interval = 10 second
 
     filters = [
       {
diff --git a/kamon-playground/src/main/scala/test/SimpleRequestProcessor.scala b/kamon-playground/src/main/scala/test/SimpleRequestProcessor.scala
index 84621927..301a9bbd 100644
--- a/kamon-playground/src/main/scala/test/SimpleRequestProcessor.scala
+++ b/kamon-playground/src/main/scala/test/SimpleRequestProcessor.scala
@@ -51,6 +51,19 @@ object SimpleRequestProcessor extends App with SimpleRoutingApp with RequestBuil
 
   implicit val timeout = Timeout(30 seconds)
 
+  val counter = Kamon(UserMetrics).registerCounter("requests")
+  Kamon(UserMetrics).registerCounter("requests-2")
+  Kamon(UserMetrics).registerCounter("requests-3")
+
+  Kamon(UserMetrics).registerHistogram("histogram-1")
+  Kamon(UserMetrics).registerHistogram("histogram-2")
+
+  Kamon(UserMetrics).registerMinMaxCounter("min-max-counter-1")
+  Kamon(UserMetrics).registerMinMaxCounter("min-max-counter-2")
+  Kamon(UserMetrics).registerMinMaxCounter("min-max-counter-3")
+
+  //Kamon(UserMetrics).registerGauge("test-gauge")(() => 10L)
+
   val pipeline = sendReceive
   val replier = system.actorOf(Props[Replier].withRouter(RoundRobinPool(nrOfInstances = 2)), "replier")
   val random = new Random()
@@ -92,6 +105,7 @@ object SimpleRequestProcessor extends App with SimpleRoutingApp with RequestBuil
         path("future") {
           traceName("OK-Future") {
             dynamic {
+              counter.increment()
               complete(Future { "OK" })
             }
           }
diff --git a/project/Projects.scala b/project/Projects.scala
index 94e8bfa2..8259f2aa 100644
--- a/project/Projects.scala
+++ b/project/Projects.scala
@@ -7,7 +7,8 @@ object Projects extends Build {
   import Dependencies._
 
   lazy val root = Project("root", file("."))
-    .aggregate(kamonCore, kamonSpray, kamonNewrelic, kamonPlayground, kamonDashboard, kamonTestkit, kamonPlay, kamonStatsD, kamonDatadog, kamonSystemMetrics)
+    .aggregate(kamonCore, kamonSpray, kamonNewrelic, kamonPlayground, kamonDashboard, kamonTestkit, kamonPlay, kamonStatsD,
+      kamonDatadog, kamonSystemMetrics, kamonLogReporter)
     .settings(basicSettings: _*)
     .settings(formatSettings: _*)
     .settings(noPublishing: _*)
@@ -57,7 +58,7 @@ object Projects extends Build {
     .settings(
       libraryDependencies ++=
         compile(akkaActor, akkaSlf4j, sprayCan, sprayClient, sprayRouting, logback))
-    .dependsOn(kamonSpray, kamonNewrelic, kamonStatsD, kamonDatadog, kamonSystemMetrics)
+    .dependsOn(kamonSpray, kamonNewrelic, kamonStatsD, kamonDatadog, kamonLogReporter, kamonSystemMetrics)
 
 
   lazy val kamonDashboard = Project("kamon-dashboard", file("kamon-dashboard"))
@@ -94,6 +95,13 @@ object Projects extends Build {
     .dependsOn(kamonCore)
     .dependsOn(kamonSystemMetrics % "provided")
 
+  lazy val kamonLogReporter = Project("kamon-log-reporter", file("kamon-log-reporter"))
+    .settings(basicSettings: _*)
+    .settings(formatSettings: _*)
+    .settings(libraryDependencies ++= compile(akkaActor) ++  test(scalatest, akkaTestKit, slf4Api, slf4nop))
+    .dependsOn(kamonCore)
+    .dependsOn(kamonSystemMetrics % "provided")
+
   lazy val kamonMacros = Project("kamon-macros", file("kamon-macros"))
     .settings(basicSettings: _*)
     .settings(formatSettings: _*)