你真的瞭解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