你真的了解Grok吗

在日志处理的过程当中，有一项很是常见的任务就是把原始的单行日志转换成结构化的日志。若是你使用了ELK，那么你能够利用ES对数据进行聚合，使用Kibana来进行数据可视化从日志中来发现一些有价值的信息。

在LogStash中，这项工做是由logstash-filter-grok来完成的，它有超过200个可用的，你们都认为是比较有用的Grok模式，例如IPv6地址、UNIX路径等等。

下面是一个示例日志

2016-09-19T18:19:00 [8.8.8.8:prd] DEBUG this is an example log message

使用Grok库，咱们能够很容易的就完成日志格式化提取的任务

%{TIMESTAMP_ISO8601:timestamp} \[%{IPV4:ip};%{WORD:environment}\] %{LOGLEVEL:log_level} %{GREEDYDATA:message}

提取后的数据格式以下

{
  "timestamp": "2016-09-19T18:19:00",
  "ip": "8.8.8.8",
  "environment": "prd",
  "log_level": "DEBUG",
  "message": "this is an example log message"
}

看起来这是一件很是简单的事情，好吧。。那这篇文章就这样写完了么，固然不是。。

#为何个人Grok使用起来很是的慢

这是一个很是常见的问题。性能这个问题一般都是要被拿出来讨论的，用户一般会发现使用了Grok表达式以后，LogStash处理日志的速度变得很慢。就像前面所说的同样，Grok模式是基于正则表达式的，因此这个插件在性能上已经对正则作了很是多的性能优化的了。接下来的章节，咱们会讨论在使用Grok模式中须要注意的点

#多作些性能测试

在设计Grok表达式的时候，咱们须要一些方法来测试究竟哪一种写法性能表现更好。出于这个缘由，我些了个很小的jruby脚步用于测试Grok插件处理我所写的Grok模式的性能，你能够在这里获取到这个脚本

#留意grok匹配失败的时候对性能的影响

尽管Grok匹配的性能是很是重要的，可是匹配失败的时候对性能的影响也是咱们须要留意的。当grok匹配失败的时候，插件会为这个事件打个tag，默认是_grokparsefailure。LogStash容许你把这些处理失败的事件路由到其余地方作后续的处理，例如

input { # ... }
filter {
  grok {
    match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} \[%{IPV4:ip};%{WORD:environment}\] %{LOGLEVEL:log_level} %{GREEDYDATA:message}" }
  }
}
output {
  if "_grokparsefailure" in [tags] {
    # write events that didn't match to a file
    file { "path" => "/tmp/grok_failures.txt" }
  } else {
     elasticsearch { }
  }
}

这样的话咱们就能够对这些处理失败的事件作性能基准测试了。

如今，咱们要开始对Apache的日志进行格式化处理了

220.181.108.96 - - [13/Jun/2015:21:14:28 +0000] "GET /blog/geekery/xvfb-firefox.html HTTP/1.1" 200 10975 "-" "Mozilla/5.0 (compatible; Baiduspider/2.0; +http://www.baidu.com/search/spider.html)"

而后咱们使用下面的Grok模式去进行格式化提取

%{IPORHOST:clientip} %{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\] "%{WORD:verb} %{DATA:request} HTTP/%{NUMBER:httpversion}" %{NUMBER:response:int} (?:-|%{NUMBER:bytes:int}) %{QS:referrer} %{QS:agent}

而后咱们使用三种示例日志去测试这个Grok的性能，和Grok不匹配的日志分别出如今开始，中间和结束的位置

# beginning mismatch - doesn't start with an IPORHOST
'tash-scale11x/css/fonts/Roboto-Regular.ttf HTTP/1.1" 200 41820 "http://semicomplete.com/presentations/logs'

# middle mismatch - instead of an HTTP verb like GET or PUT there's the number 111
'220.181.108.96 - - [13/Jun/2015:21:14:28 +0000] "111 /blog/geekery/xvfb-firefox.html HTTP/1.1" 200 10975 "-" "Mozilla/5.0 (compatible; Baiduspider/2.0; +http://www.baidu.com/search/spider.html)"'

# end mismatch - the last element isn't a quoted string, but a number
'220.181.108.96 - - [13/Jun/2015:21:14:28 +0000] "GET /blog/geekery/xvfb-firefox.html HTTP/1.1" 200 10975 "-" 1'

下面是性能测试的结果

基于上面这个测试结果，咱们能够发现，Grok的性能和不匹配的日志所出现的位置有关，最快与最慢的性能差了差很少6倍。这就能解释为何有用户提出当Grok匹配日志失败的时候CPU会被吃满的缘由了，例如这个issues https://github.com/logstash-plugins/logstash-filter-grok/issues/37.

咱们能作些什么呢

#快速失败，设置锚点

咱们已经知道了处理失败对grok的性能影响是很是大的，因此咱们须要解决这个问题。对于正则引擎来讲，你须要作的最合适的事情就是减小正则表达式所须要的猜想。这就是为何贪婪匹配最好少用的缘由，那回到这个问题，有没一种更好的方法来调整这个Grok模式呢，让咱们从新来看看这行Apache的日志

220.181.108.96 - - [13/Jun/2015:21:14:28 +0000] "GET /blog/geekery/xvfb-firefox.html HTTP/1.1" 200 10975 "-" "Mozilla/5.0 (compatible; Baiduspider/2.0; +http://www.baidu.com/search/spider.html)"

刚才咱们使用的Grok模式是这样的

%{IPORHOST:clientip} %{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\] "%{WORD:verb} %{DATA:request} HTTP/%{NUMBER:httpversion}" %{NUMBER:response:int} (?:-|%{NUMBER:bytes:int}) %{QS:referrer} %{QS:agent}

因为用户觉得Grok表达式只会从开头匹配到结束，因此致使了在一些普通的场景下也会出现性能问题。可是实际上，Grok只是被告知“在这段文本中寻找匹配的内容”，这就意味着下面这种示例也会被Grok所匹配。。。

OMG OMG OMG EXTRA INFORMATION 220.181.108.96 - - [13/Jun/2015:21:14:28 +0000] "GET /blog/geekery/xvfb-firefox.html HTTP/1.1" 200 10975 "-" "Mozilla/5.0 (compatible; Baiduspider/2.0; +http://www.baidu.com/search/spider.html)" OH LOOK EVEN MORE STUFF

呃。。这都行，不过解决这个问题仍是很简单的，咱们加一些锚点就搞定了。锚点可让你再一个指定的位置处理字符串。加入了开始和结束的锚点以后(^和&)，Grok就会从开头处理日志到结束了。这对处理那些不能匹配的日志有很是重要的做用。假如咱们没有假如锚点，当正则没法匹配这行日志的时候，它就会开始从子字符串中进行匹配，而后性能就会降低，接下来咱们把锚点加上，而后再作一次测试

^%{IPORHOST:clientip} %{USER:ident} %{USER:auth} \[%{HTTPDATE:timestamp}\] "%{WORD:verb} %{DATA:request} HTTP/%{NUMBER:httpversion}" %{NUMBER:response:int} (?:-|%{NUMBER:bytes:int}) %{QS:referrer} %{QS:agent}$

能够看到性能有了很大的提高，在一开始就匹配失败的场景中，性能提高了将近10倍

#留意匹配了两次的表达式

你可能会说，“好吧，个人日志都是能匹配经过的，没有上面的问题”，可是事情可能并非这样的

咱们看到过很是多的grok模式在处理同一个网关发出的多种应用日志时候所出现的问题，例如syslog。想象一下这样一个场景，咱们使用了“common_header: payload“这种日志格式来记录了三种应用日志

Application 1: '8.8.8.8 process-name[666]: a b 1 2 a lot of text at the end'
Application 2: '8.8.8.8 process-name[667]: a 1 2 3 a lot of text near the end;4'
Application 3: '8.8.8.8 process-name[421]: a completely different format | 1111'

一般咱们会在一个Grok里面就把三种日志都处理掉

grok {
  "match" => { "message => [
    '%{IPORHOST:clientip} %{DATA:process_name}\[%{NUMBER:process_id}\]: %{WORD:word_1} %{WORD:word_2} %{NUMBER:number_1} %{NUMBER:number_2} %{DATA:data}',
    '%{IPORHOST:clientip} %{DATA:process_name}\[%{NUMBER:process_id}\]: %{WORD:word_1} %{NUMBER:number_1} %{NUMBER:number_2} %{NUMBER:number_3} %{DATA:data};%{NUMBER:number_4}',
    '%{IPORHOST:clientip} %{DATA:process_name}\[%{NUMBER:process_id}\]: %{DATA:data} | %{NUMBER:number}'
    ] }
}

值得留意的是即便你的日志是能正常匹配的，Grok仍是会按照顺序许匹配送进来的日志，当碰到第一个匹配成功的日志就break掉这个循环。这就要咱们本身去判断一下，怎么放是最合适的了，否则的话会一个一个往下进行尝试，毕竟是多种不一样的格式。 一种经常使用的优化方案是使用分层匹配来对这个Grok进行优化

filter {
  grok {
    "match" => { "message" => '%{IPORHOST:clientip} %{DATA:process_name}\[%{NUMBER:process_id}\]: %{GREEDYDATA:message}' },
    "overwrite" => "message"
  }
  grok {
    "match" => { "message" => [
      '%{WORD:word_1} %{WORD:word_2} %{NUMBER:number_1} %{NUMBER:number_2} %{GREEDYDATA:data}',
      '%{WORD:word_1} %{NUMBER:number_1} %{NUMBER:number_2} %{NUMBER:number_3} %{DATA:data};%{NUMBER:number_4}',
      '%{DATA:data} | %{NUMBER:number}'
    ] }
  }
)

这是两种匹配方案的性能测试结果

看起来真有意思。。使用锚点的话，不管哪一种方案性能都是同样的。不用锚点的状况下分层Grok的方案比不分层的又快不少

#那咱们怎么知道咱们所建立的Grok是合适的

咱们已经得出了对_grokparsefaiure进行处理的必要性了，那么咱们还能作什么呢？ 从3.2.0这个Grok插件开始，它有一些参数能够帮助你了解为何一个事件会被处理那么久了。使用timeout_millis和tag_on_timeout能够设置Grok匹配的最大处理时长。若是超时了，这个事件会被打上_groktimeout的tag，而后咱们就能够把他们送到一个Grok处理失败的ES索引里面去作后续的分析了

另一个很棒的方法是LogStash5.0带了插件性能统计的功能，咱们能够经过API来查看插件处理日志的性能了

$ curl localhost:9600/_node/stats/pipeline?pretty | jq ".pipeline.plugins.filters"
[
  {
    "id": "grok_b61938f3833f9f89360b5fba6472be0ad51c3606-2",
    "events": {
      "duration_in_millis": 7,
      "in": 24,
      "out": 24
    },
    "failures": 24,
    "patterns_per_field": {
      "message": 1
    },
    "name": "grok"
  },
  {
    "id": "kv_b61938f3833f9f89360b5fba6472be0ad51c3606-3",
    "events": {
      "duration_in_millis": 2,
      "in": 24,
      "out": 24
    },
    "name": "kv"
  }
]

而后咱们就能够经过duration_in_millis来判断一个插件的性能了

#总结

但愿这篇文章能帮你了解为何Grok的性能会变得慢和如何去提高他的性能。下面是对这篇文字的总结：

• Grok在匹配失败的时候性能可能并不那么好
• 多留意_grokparsefailures 出现的频率和出现时候的性能
• 写正则的时候记得打锚点
• 不使用锚点的时候分层Grok处理的性能会比不分层的性能好，不过打了锚点的话两个都同样
• 多使用LogStash的性能监控功能，后续还能够拿来分析用

原文：https://www.elastic.co/blog/do-you-grok-grok