在日志处理的过程中，有一项非常常见的任务就是把原始的单行日志转换成结构化的日志。如果你使用了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的性能监控功能，后续还可以拿来分析用
