在日志處理的過程中严肪，有一項(xiàng)非常常見的任務(wù)就是把原始的單行日志轉(zhuǎn)換成結(jié)構(gòu)化的日志秸架。如果你使用了ELK梦染，那么你可以利用ES對(duì)數(shù)據(jù)進(jìn)行聚合索赏，使用Kibana來進(jìn)行數(shù)據(jù)可視化從日志中來發(fā)現(xiàn)一些有價(jià)值的信息侵贵。
在LogStash中届搁，這項(xiàng)工作是由logstash-filter-grok來完成的，它有超過200個(gè)可用的窍育，大家都認(rèn)為是比較有用的Grok模式卡睦，例如IPv6地址、UNIX路徑等等蔫骂。
下面是一個(gè)示例日志
2016-09-19T18:19:00 [8.8.8.8:prd] DEBUG this is an example log message
使用Grok庫么翰，我們可以很容易的就完成日志格式化提取的任務(wù)
%{TIMESTAMP_ISO8601:timestamp} \[%{IPV4:ip};%{WORD:environment}\] %{LOGLEVEL:log_level} %{GREEDYDATA:message}
提取后的數(shù)據(jù)格式如下
{
"timestamp": "2016-09-19T18:19:00",
"ip": "8.8.8.8",
"environment": "prd",
"log_level": "DEBUG",
"message": "this is an example log message"
}
看起來這是一件非常簡單的事情，好吧辽旋。浩嫌。那這篇文章就這樣寫完了么，當(dāng)然不是补胚。码耐。
為什么我的Grok使用起來非常的慢
這是一個(gè)非常常見的問題。性能這個(gè)問題通常都是要被拿出來討論的溶其，用戶通常會(huì)發(fā)現(xiàn)使用了Grok表達(dá)式之后骚腥，LogStash處理日志的速度變得很慢。就像前面所說的一樣瓶逃，Grok模式是基于正則表達(dá)式的束铭，所以這個(gè)插件在性能上已經(jīng)對(duì)正則做了非常多的性能優(yōu)化的了廓块。接下來的章節(jié)，我們會(huì)討論在使用Grok模式中需要注意的點(diǎn)
多做些性能測(cè)試
在設(shè)計(jì)Grok表達(dá)式的時(shí)候契沫，我們需要一些方法來測(cè)試究竟哪種寫法性能表現(xiàn)更好带猴。出于這個(gè)原因，我些了個(gè)很小的jruby腳步用于測(cè)試Grok插件處理我所寫的Grok模式的性能懈万，你可以在這里獲取到這個(gè)腳本
留意grok匹配失敗的時(shí)候?qū)π阅艿挠绊?/h1>
盡管Grok匹配的性能是非常重要的拴清，但是匹配失敗的時(shí)候?qū)π阅艿挠绊懸彩俏覀冃枰粢獾摹．?dāng)grok匹配失敗的時(shí)候会通，插件會(huì)為這個(gè)事件打個(gè)tag口予，默認(rèn)是_grokparsefailure。LogStash允許你把這些處理失敗的事件路由到其他地方做后續(xù)的處理涕侈，例如
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 { }
}
}
這樣的話我們就可以對(duì)這些處理失敗的事件做性能基準(zhǔn)測(cè)試了沪停。
現(xiàn)在，我們要開始對(duì)Apache的日志進(jìn)行格式化處理了
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模式去進(jìn)行格式化提取
%{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}
然后我們使用三種示例日志去測(cè)試這個(gè)Grok的性能驾凶，和Grok不匹配的日志分別出現(xiàn)在開始牙甫，中間和結(jié)束的位置
# 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'
下面是性能測(cè)試的結(jié)果
基于上面這個(gè)測(cè)試結(jié)果，我們可以發(fā)現(xiàn)调违，Grok的性能和不匹配的日志所出現(xiàn)的位置有關(guān)窟哺，最快與最慢的性能差了差不多6倍。這就能解釋為什么有用戶提出當(dāng)Grok匹配日志失敗的時(shí)候CPU會(huì)被吃滿的原因了技肩，例如這個(gè)issues
https://github.com/logstash-plugins/logstash-filter-grok/issues/37.
我們能做些什么呢
快速失敗且轨，設(shè)置錨點(diǎn)
我們已經(jīng)知道了處理失敗對(duì)grok的性能影響是非常大的，所以我們需要解決這個(gè)問題虚婿。對(duì)于正則引擎來說旋奢，你需要做的最合適的事情就是減少正則表達(dá)式所需要的猜測(cè)。這就是為什么貪婪匹配最好少用的原因然痊，那回到這個(gè)問題至朗，有沒一種更好的方法來調(diào)整這個(gè)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表達(dá)式只會(huì)從開頭匹配到結(jié)束剧浸，所以導(dǎo)致了在一些普通的場(chǎng)景下也會(huì)出現(xiàn)性能問題锹引。但是實(shí)際上，Grok只是被告知“在這段文本中尋找匹配的內(nèi)容”唆香，這就意味著下面這種示例也會(huì)被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
呃腾啥。。這都行，不過解決這個(gè)問題還是很簡單的倘待，我們加一些錨點(diǎn)就搞定了疮跑。錨點(diǎn)可以讓你再一個(gè)指定的位置處理字符串。加入了開始和結(jié)束的錨點(diǎn)之后(^和$)延柠，Grok就會(huì)從開頭處理日志到結(jié)束了祸挪。這對(duì)處理那些不能匹配的日志有非常重要的作用。假如我們沒有假如錨點(diǎn)贞间，當(dāng)正則無法匹配這行日志的時(shí)候，它就會(huì)開始從子字符串中進(jìn)行匹配雹仿，然后性能就會(huì)下降增热，接下來我們把錨點(diǎn)加上，然后再做一次測(cè)試
^%{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}$
可以看到性能有了很大的提升胧辽，在一開始就匹配失敗的場(chǎng)景中峻仇，性能提升了將近10倍
留意匹配了兩次的表達(dá)式
你可能會(huì)說，“好吧邑商，我的日志都是能匹配通過的摄咆，沒有上面的問題”，但是事情可能并不是這樣的
我們看到過非常多的grok模式在處理同一個(gè)網(wǎng)關(guān)發(fā)出的多種應(yīng)用日志時(shí)候所出現(xiàn)的問題人断，例如syslog吭从。想象一下這樣一個(gè)場(chǎng)景，我們使用了“common_header: payload“這種日志格式來記錄了三種應(yīng)用日志
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'
通常我們會(huì)在一個(gè)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還是會(huì)按照順序許匹配送進(jìn)來的日志涩金，當(dāng)碰到第一個(gè)匹配成功的日志就break掉這個(gè)循環(huán)。這就要我們自己去判斷一下暇仲，怎么放是最合適的了步做，不然的話會(huì)一個(gè)一個(gè)往下進(jìn)行嘗試，畢竟是多種不同的格式奈附。
一種常用的優(yōu)化方案是使用分層匹配來對(duì)這個(gè)Grok進(jìn)行優(yōu)化
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}'
] }
}
)
這是兩種匹配方案的性能測(cè)試結(jié)果
看起來真有意思全度。。使用錨點(diǎn)的話斥滤，無論哪種方案性能都是一樣的将鸵。不用錨點(diǎn)的情況下分層Grok的方案比不分層的又快很多
那我們?cè)趺粗牢覀兯鶆?chuàng)建的Grok是合適的
我們已經(jīng)得出了對(duì)_grokparsefaiure進(jìn)行處理的必要性了，那么我們還能做什么呢中跌？
從3.2.0這個(gè)Grok插件開始咨堤，它有一些參數(shù)可以幫助你了解為什么一個(gè)事件會(huì)被處理那么久了。使用timeout_millis和tag_on_timeout可以設(shè)置Grok匹配的最大處理時(shí)長漩符。如果超時(shí)了一喘，這個(gè)事件會(huì)被打上_groktimeout的tag，然后我們就可以把他們送到一個(gè)Grok處理失敗的ES索引里面去做后續(xù)的分析了
另外一個(gè)很棒的方法是LogStash5.0帶了插件性能統(tǒng)計(jì)的功能，我們可以通過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來判斷一個(gè)插件的性能了
總結(jié)
希望這篇文章能幫你了解為什么Grok的性能會(huì)變得慢和如何去提升他的性能凸克。下面是對(duì)這篇文字的總結(jié)：
- Grok在匹配失敗的時(shí)候性能可能并不那么好
- 多留意
_grokparsefailures出現(xiàn)的頻率和出現(xiàn)時(shí)候的性能 - 寫正則的時(shí)候記得打錨點(diǎn)
- 不使用錨點(diǎn)的時(shí)候分層Grok處理的性能會(huì)比不分層的性能好议蟆，不過打了錨點(diǎn)的話兩個(gè)都一樣
- 多使用LogStash的性能監(jiān)控功能，后續(xù)還可以拿來分析用
