How to analyze metric log?

Elastic Stack Logstash
1

Hi all. I have a file named metric.log like this:

2015-09-22 20:24:46,420 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=TIMER, name=mailman_deliver, count=15256, min=0.342485, max=11.300943, mean=0.8951640572083964, stddev=0.6954749196236861, median=0.748587, p75=0.936751, p95=1.5087139999999999, p98=2.171507, p99=5.071034, p999=6.9437, mean_rate=1.8863147356259495, m1=1.8548623655404692, m5=1.8315822655481537, m15=1.8452000458805868, rate_unit=events/second, duration_unit=milliseconds
2015-09-22 20:24:46,421 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=TIMER, name=save_rtdata, count=16200, min=0.010355, max=15.781473, mean=3.5410060138241652, stddev=3.3052328055595726, median=4.660863, p75=6.002141, p95=8.479156999999999, p98=10.513221999999999, p99=10.740746999999999, p999=15.781473, mean_rate=2.0001091440079812, m1=2.0000000000000027, m5=2.0000000000003886, m15=2.0000249577340634, rate_unit=events/second, duration_unit=milliseconds
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.filehandlers, value=0.00153125
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.gc.PS-MarkSweep.count, value=2
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.gc.PS-MarkSweep.time, value=166
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.gc.PS-Scavenge.count, value=550
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.gc.PS-Scavenge.time, value=2689
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.heap.committed, value=166199296
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.heap.init, value=132120576
2015-09-22 20:25:46,417 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.heap.max, value=477626368
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.heap.usage, value=0.16752130401644827
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.heap.used, value=80012592
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.non-heap.committed, value=68968448
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.non-heap.init, value=2555904
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.non-heap.max, value=-1
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.non-heap.usage, value=-6.5628584E7
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.non-heap.used, value=65628584
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.pools.Code-Cache.committed, value=24969216
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.pools.Code-Cache.init, value=2555904
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.pools.Code-Cache.max, value=251658240
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.pools.Code-Cache.usage, value=0.09828974405924479
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.pools.Code-Cache.used, value=24735424
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.pools.Compressed-Class-Space.committed, value=4980736
2015-09-22 20:25:46,418 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.pools.Compressed-Class-Space.init, value=0
...

This is a metric log. How to analyze with logstash ?

I want to display graph by using kibana.

2

Start with a grok filter to extract the timestamp, thread name, log level, logger name, and the final list of key=value pairs into separate fields. Use the date filter to populate @timestamp from the timestamp field and feed the key=value pairs to the kv filter. Finish off with a mutate filter that converts metric value fields to numbers.

3

Thanks. By using kv filter now I can get kv pairs.

Here is my logstash config:

filter {
        grok {
            match => { "message" => 
                "%{TIMESTAMP_ISO8601:date} \[(?<thread_name>.+?)\] (?<log_level>\w+)\s+(?<verticle>.+?)\s*?-\s*(?<content>.*)"
            }
        }
            kv {
                add_tag => [ "metrics" ]
                field_split => "[, ]"
                source => "content"
                target => "metrics"
            }
        }

        date {
            match => [ "date", "yyyy-MM-dd HH:mm:ss,SSS" ]
            target => "date"
            timezone => "PRC"
        }

        if [log_level] == "ERROR" or "Exception" in [message] {
            throttle {
                after_count => 2
                key => "%{content}"
                add_tag => "throttled"
            }
        }
    }
}

Here is rubydebug output:

{
     "@timestamp" => "2015-09-22T13:12:08.137Z",
        "message" => "2015-09-22 21:12:07,994 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.total.max, value=477626367",
       "@version" => "1",
           "host" => "master",
           "path" => "/var/log/rtds/metric.log",
           "type" => "rtds-metrics",
           "tags" => [
        [0] "rtds-metrics_log",
        [1] "vertx",
        [2] "metrics"
    ],
           "date" => "2015-09-22T13:12:07.994Z",
    "thread_name" => "metrics-logger-reporter-1-thread-1",
      "log_level" => "INFO",
       "verticle" => "hawkeyes.rtds.monitor.MetricsVerticle",
        "content" => "type=GAUGE, name=jvm.memory.total.max, value=477626367",
        "metrics" => {
         "type" => "GAUGE",
         "name" => "jvm.memory.total.max",
        "value" => "477626367"
    }
}
{
     "@timestamp" => "2015-09-22T13:12:08.138Z",
        "message" => "2015-09-22 21:12:07,994 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=GAUGE, name=jvm.memory.total.used, value=129112320",
       "@version" => "1",
           "host" => "master",
           "path" => "/var/log/rtds/metric.log",
           "type" => "rtds-metrics",
           "tags" => [
        [0] "rtds-metrics_log",
        [1] "vertx",
        [2] "metrics"
    ],
           "date" => "2015-09-22T13:12:07.994Z",
    "thread_name" => "metrics-logger-reporter-1-thread-1",
      "log_level" => "INFO",
       "verticle" => "hawkeyes.rtds.monitor.MetricsVerticle",
        "content" => "type=GAUGE, name=jvm.memory.total.used, value=129112320",
        "metrics" => {
         "type" => "GAUGE",
         "name" => "jvm.memory.total.used",
        "value" => "129112320"
    }
}
{
     "@timestamp" => "2015-09-22T13:12:08.138Z",
        "message" => "2015-09-22 21:12:07,994 [metrics-logger-reporter-1-thread-1] INFO  hawkeyes.rtds.monitor.MetricsVerticle - type=METER, name=data_packages_arrived, count=3795, mean_rate=1.7094634612549, m1=1.6928086889504304, m5=1.6990068437890478, m15=1.560542268233465, rate_unit=events/second",
       "@version" => "1",
           "host" => "master",
           "path" => "/var/log/rtds/metric.log",
           "type" => "rtds-metrics",
           "tags" => [
        [0] "rtds-metrics_log",
        [1] "vertx",
        [2] "metrics"
    ],
           "date" => "2015-09-22T13:12:07.994Z",
    "thread_name" => "metrics-logger-reporter-1-thread-1",
      "log_level" => "INFO",
       "verticle" => "hawkeyes.rtds.monitor.MetricsVerticle",
        "content" => "type=METER, name=data_packages_arrived, count=3795, mean_rate=1.7094634612549, m1=1.6928086889504304, m5=1.6990068437890478, m15=1.560542268233465, rate_unit=events/second",
        "metrics" => {
             "type" => "METER",
             "name" => "data_packages_arrived",
            "count" => "3795",
        "mean_rate" => "1.7094634612549",
               "m1" => "1.6928086889504304",
               "m5" => "1.6990068437890478",
              "m15" => "1.560542268233465",
        "rate_unit" => "events/second"
    }
}

Now I can get the metrics kv pairs. And I want to send an email if jvm.memory.heap.usage > 0.85. How can I get this value ?

4

Assuming you've converted the metric value to a float with a mutate filter:

output {
  if [metrics][name] == "jvm.memory.heap.usage" and [metrics][value] > 0.85 {
    email {
      ...
    }
  }
}
1 Like
5

Thanks. It works.