[譯]你真的理解grok嗎

Do you grok Grok?

原文： Do you grok Grok?

譯者：neal1991

welcome to star my articles-translator , providing you advanced articles translation. Any suggestion, please issue or contact me

LICENSE: MIT

grok (verb)

understand (something) intuitively or by empathy.

解析日誌數據時最多見的任務是將原始文本行分解爲其餘工具能夠操做的一組結構化字段。 若是你使用 Elastic Stack，則能夠利用 Elasticsearch 的聚合和 Kibana 的可視化，從日誌中提取的信息（如 IP 地址，時間戳和特定域的數據）解釋業務和操做問題。

對於 Logstash，這個解構工做由 logstash-filter-grok 來承擔，它是一個過濾器插件，能夠幫助你描述日誌格式的結構。

這裏有超過200個 grok 模式對於一些概念進行歸納，如IPv6 地址，UNIX 路徑和月份名稱。

爲了以 grok 庫匹配下列一行的格式，只須要將一些模式組合在一塊兒：

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

%{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 腳本，它直接使用logstash-filter-grok 插件，繞過 logstash 管道。

你能夠從這獲取腳本。咱們將使用它來收集性能數據來驗證（或者推翻！）咱們的假設。

留意 grok 匹配失敗時的性能影響

儘管知道 grok 模式與日誌條目能夠多快匹配很是重要，可是瞭解它在何時匹配失敗也很重要。匹配成功和匹配失敗的性能可能會差別很大。

當 grok 沒法匹配一個事件的時候，它將會爲這個事件添加一個 tag。默認這個 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 { }
  }
}

若是發現有多個模式匹配失敗，則能夠對這些行進行基準測試，並找出它們對管道吞吐量的影響。

如今咱們將使用 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}

如今，咱們將比較成功匹配的匹配速度和不符合格式的其餘三個日誌條目，不管是在開始，中間仍是在行尾：

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 使用率的用戶報告，如https://github.com/logstash-p...。

對此咱們能夠作什麼呢？

設置錨能夠提高匹配失敗的性能

既然如今咱們知道匹配失敗對你的管道性能是很危險的，咱們須要修復它們。 在正則表達式設計中，你能夠作的最好的事情來幫助正則表達式引擎是減小它須要作的猜想工做。 這就是爲何一般會避免貪婪模式的緣由，可是咱們稍微回顧一下，由於有一個更簡單的變化來改變模式的匹配。

讓咱們回到咱們可愛的 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 模式！好消息是修復很簡單，咱們只須要添加一些錨！

錨容許你將正則表達式固定到字符串的某個位置。 經過在咱們的 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 中匹配三種格式：

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 仍然會依次嘗試將傳入日誌行與三個表達式進行匹配，從而在第一次匹配時中斷。

這意味着確保咱們儘量快地跳到正確的位置仍然很重要，由於應用程序2老是有一個失敗的匹配，應用程序3有兩個失敗的匹配。

咱們常常看到的第一個策略是對Grok匹配進行分層：首先匹配 header，覆蓋 message 字段，而後僅匹配 bodies：

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}'
    ] }
  }
)

僅僅這一個就是一個有趣的性能提高，匹配行比初始方法快了2.5倍。 可是若是咱們添加咱們的同伴錨呢？

有意思！添加錨點使得兩個架構的性能一樣出色！ 事實上，因爲失敗的匹配性能大大提升，咱們最初的單杆設計稍微好一點，由於有一個比較少的匹配正在執行。

好的，那麼咱們如何知道事情進行得如何？

咱們已經得出結論，監控「_grokparsefaiure」事件的存在是必不可少的，可是你能夠作更多的事情：

自從版本 3.2.0 grok 插件，已經有不少設置能夠幫助你何時事件須要花費長時間來匹配（或者失敗匹配）。使用timeout millis 以及 timeout 標籤可以對於 grok 匹配的時間設置一個上限。若是達到了限制時間，此次匹配就會被中斷而且被打上 _groktimeout 標籤。

使用咱們以前介紹的相同的條件策略，你·能夠將這些事件重定向到 elasticsearch 中的文件或不一樣的索引，以供往後分析。

另外一個很是酷的事情，咱們將在 Logstash 5.0 中引入度量的上下文是可以提取管道性能的數據，最重要的是，每一個插件的統計數據。 在 logstash 運行時，你能夠查詢其 AP I端點，並查看 logstash 在一個插件上花費的累積時間：

$ 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"
  }
]

有了這些信息，你能夠看到grok的「duration_in_millis」是否快速增加，若是失敗的數量在增長，能夠做爲警告標誌，代表某些模式設計很差，或者消耗的時間比預期的多。

總結

但願這篇博文可以幫助你理解 grok 的行爲，以及如何提升吞吐量。 總結咱們的結論：

1. grok 匹配失敗的時候性能可能表現很差。
2. 監測發生 _grokfailures的狀況而且對於他們的消耗進行基準測試。
3. 使用錨好比 ^ 以及$ 避免歧義而且幫助正則引擎。
4. 若是你不使用錨的話使用分層匹配會提升性能。若是懷疑的話，直接測量。
5. 使用超時設置或者即將推出的 Metrics API 可以讓你更好地瞭解 grok 是如何工做的，而且是性能分析的第一點。