计算事件之间的时间

Question

我有一条消息流经多个系统,每个系统记录消息进入和退出时带有时间戳和uuid messageId.我通过以下方式摄取所有日志:

filebeat --> logstash --> elastic search --> kibana

结果我现在有这些事件:

@timestamp                      messageId                               event 
May 19th 2016, 02:55:29.003     00e02f2f-32d5-9509-870a-f80e54dc8775    system1Enter
May 19th 2016, 02:55:29.200     00e02f2f-32d5-9509-870a-f80e54dc8775    system1Exit
May 19th 2016, 02:55:29.205     00e02f2f-32d5-9509-870a-f80e54dc8775    system2Enter
May 19th 2016, 02:55:29.453     00e02f2f-32d5-9509-870a-f80e54dc8775    system2Exit

我想在每个系统中生成一个报告(理想情况是堆积条或列):

messageId                               in1:1->2:in2
00e02f2f-32d5-9509-870a-f80e54dc8775    197:5:248

做这个的最好方式是什么？Logstash过滤器？kibana计算字段？

Answer 1

你只能通过Logstash aggregate过滤器来实现这一点,但是,你必须大大重新实现elapsed过滤器已经做的事情,所以这是一种耻辱,对吧？

然后让我们使用Logstash aggregate过滤器和elapsed过滤器的混合.后者用于测量每个阶段的时间,前者用于将所有时间信息聚合到最后一个事件中.

旁注:你可能要重新考虑你的时间戳格式进行解析它的东西更多的标准.我已经将它们转换为ISO 8601以使其更容易解析,但随意滚动自己的正则表达式.

所以我从以下日志开始:

2016-05-19T02:55:29.003 00e02f2f-32d5-9509-870a-f80e54dc8775 system1Enter
2016-05-19T02:55:29.200 00e02f2f-32d5-9509-870a-f80e54dc8775 system1Exit
2016-05-19T02:55:29.205 00e02f2f-32d5-9509-870a-f80e54dc8775 system2Enter
2016-05-19T02:55:29.453 00e02f2f-32d5-9509-870a-f80e54dc8775 system2Exit

首先,我使用三个elapsed过滤器(每个阶段一个in1,1->2然后in2),然后使用三个聚合过滤器来收集所有定时信息.它看起来像这样:

filter {
  grok {
    match => ["message", "%{TIMESTAMP_ISO8601:timestamp} %{UUID:messageId} %{WORD:event}"]
    add_tag => [ "%{event}" ]
  }
  date {
    match => [ "timestamp", "ISO8601"]
  }
  # Measures the execution time of system1
  elapsed {
    unique_id_field => "messageId"
    start_tag => "system1Enter"
    end_tag => "system1Exit"
    new_event_on_match => true
    add_tag => ["in1"]
  }
  # Measures the execution time of system2
  elapsed {
    unique_id_field => "messageId"
    start_tag => "system2Enter"
    end_tag => "system2Exit"
    new_event_on_match => true
    add_tag => ["in2"]
  }
  # Measures the time between system1 and system2
  elapsed {
    unique_id_field => "messageId"
    start_tag => "system1Exit"
    end_tag => "system2Enter"
    new_event_on_match => true
    add_tag => ["1->2"]
  }
  # Records the execution time of system1
  if "in1" in [tags] and "elapsed" in [tags] {
    aggregate {
      task_id => "%{messageId}"
      code => "map['report'] = [(event['elapsed_time']*1000).to_i]"
      map_action => "create"
    }
  }
  # Records the time between system1 and system2
  if "1->2" in [tags] and "elapsed" in [tags] {
    aggregate {
      task_id => "%{messageId}"
      code => "map['report'] << (event['elapsed_time']*1000).to_i"
      map_action => "update"
    }
  }
  # Records the execution time of system2
  if "in2" in [tags] and "elapsed" in [tags] {
    aggregate {
      task_id => "%{messageId}"
      code => "map['report'] << (event['elapsed_time']*1000).to_i; event['report'] = map['report'].join(':')"
      map_action => "update"
      end_of_task => true
    }
  }
}

在前两个事件之后,你将得到一个像这样的新事件,它表明在system1中花了197ms:

{
                 "@timestamp" => "2016-05-21T04:20:51.731Z",
                       "tags" => [ "elapsed", "elapsed_match", "in1" ],
               "elapsed_time" => 0.197,
                  "messageId" => "00e02f2f-32d5-9509-870a-f80e54dc8775",
    "elapsed_timestamp_start" => "2016-05-19T00:55:29.003Z"
}

在第三个事件之后,你将得到一个这样的事件,它显示了system1和system2之间花费了多少时间,即5ms:

{
                 "@timestamp" => "2016-05-21T04:20:51.734Z",
                       "tags" => [ "elapsed", "elapsed_match", "1->2" ],
               "elapsed_time" => 0.005,
                  "messageId" => "00e02f2f-32d5-9509-870a-f80e54dc8775",
    "elapsed_timestamp_start" => "2016-05-19T00:55:29.200Z"
}

在第四个事件之后,你将得到一个像这样的新事件,它显示在system2中花了多少时间,即248ms.该事件还包含一个包含report消息的所有定时信息的字段

{
                 "@timestamp" => "2016-05-21T04:20:51.736Z",
                       "tags" => [ "elapsed", "elapsed_match", "in2" ],
               "elapsed_time" => 0.248,
                  "messageId" => "00e02f2f-32d5-9509-870a-f80e54dc8775",
    "elapsed_timestamp_start" => "2016-05-19T00:55:29.205Z"
                     "report" => "197:5:248"
}