摘要：允許你將這些事件路由到可以統(tǒng)計和檢查的地方。實際上，被告知的是在一行文本中找到這個元素序列?？偨Y希望這篇博文能夠幫助你理解的行為，以及如何提高吞吐量。監(jiān)測發(fā)生的情況并且對于他們的消耗進行基準測試。如果懷疑的話，直接測量。

原文：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.

解析日志數(shù)據(jù)時最常見的任務是將原始文本行分解為其他工具可以操作的一組結構化字段。 如果你使用 Elastic Stack，則可以利用 Elasticsearch 的聚合和 Kibana 的可視化，從日志中提取的信息（如 IP 地址，時間戳和特定域的數(shù)據(jù)）解釋業(yè)務和操作問題。

對于 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"

}

很簡單，是不是？

是！

很棒！就到這了么？不！因為...

這是一個非常普遍的說法！性能是一個經(jīng)常從社區(qū)引發(fā)的話題，用戶或客戶通常會創(chuàng)建一個 grok 表達式，這將極大地減少 logstash 管道每秒處理的事件數(shù)量。

如前所述，grok 模式是正則表達式，因此這個插件的性能受到正則表達式引擎嚴重影響。 在接下來的章節(jié)中，我們將提供一些關于創(chuàng)建 grok 表達式來匹配日志行的操作指南。

為了在 grok 表達式設計過程中驗證決策和實驗，我們需要一種方法來快速測量兩個或更多表達式之間的性能。 為此，我創(chuàng)建了一個小的 jruby 腳本，它直接使用logstash-filter-grok 插件，繞過 logstash 管道。

你可以從這獲取腳本。我們將使用它來收集性能數(shù)據(jù)來驗證（或者推翻?。┪覀兊募僭O。

盡管知道 grok 模式與日志條目可以多快匹配非常重要，但是了解它在什么時候匹配失敗也很重要。匹配成功和匹配失敗的性能可能會差異很大。

當 grok 無法匹配一個事件的時候，它將會為這個事件添加一個 tag。默認這個 tag 是 _grokparsefailure。

Logstash 允許你將這些事件路由到可以統(tǒng)計和檢查的地方。 例如，你可以將所有失敗的匹配寫入文件：

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 { }
  }
}

如果發(fā)現(xiàn)有多個模式匹配失敗，則可以對這些行進行基準測試，并找出它們對管道吞吐量的影響。

現(xiàn)在我們將使用 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}

現(xiàn)在，我們將比較成功匹配的匹配速度和不符合格式的其他三個日志條目，無論是在開始，中間還是在行尾：

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"

這些日志行在文章開頭提到的腳本進行基準測試，結果如下：

每秒匹配的日志數(shù)

我們可以看到，對于這個 grok 表達式，取決于不匹配的位置，檢查一行不匹配的時間可能比常規(guī)（成功）匹配慢6倍。 這有助于解釋在行數(shù)不匹配時 grok 最大化 CPU 使用率的用戶報告，如https://github.com/logstash-p...。

對此我們可以做什么呢？

既然現(xiàn)在我們知道匹配失敗對你的管道性能是很危險的，我們需要修復它們。 在正則表達式設計中，你可以做的最好的事情來幫助正則表達式引擎是減少它需要做的猜測工作。 這就是為什么通常會避免貪婪模式的原因，但是我們稍微回顧一下，因為有一個更簡單的變化來改變模式的匹配。

讓我們回到我們可愛的 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 被告知的是“在一行文本中找到這個元素序列”。

等一下，什么？就是它了，“在一行文本中”。這意味著比如一行數(shù)據(jù)...

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 表達式中添加行錨點（^和$）的開始和結束，我們確保我們只會匹配整個字符串從開始到結束，而不包含其他的。

這在匹配失敗的情況下非常重要。 如果錨點不在位，并且正則表達式引擎不能匹配一行日志，它將開始嘗試在初始字符串的子字符串中查找該模式，因此我們在上面看到了性能下降。

因此，為了看到性能影響，我們產(chǎ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}$

下面是結果：

對于不匹配的場景，這是一個相當顯著的變化！ 不僅我們在中端和末端場景中消除了巨大的性能下降，而且使初始匹配失敗檢測速度提高了 10 倍左右。 贊。

你可能會說：“好吧，我的所有行都格式正確，所以我們沒有匹配失敗”，但情況可能并非如此。

隨著時間的推移，我們已經(jīng)看到了 grok 用法的一個非常常見的模式，尤其是當來自多個應用程序的日志行通過單個網(wǎng)關（如 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}"
    ] }
}

現(xiàn)在請注意，即使你的應用程序正確日志記錄，grok 仍然會依次嘗試將傳入日志行與三個表達式進行匹配，從而在第一次匹配時中斷。

這意味著確保我們盡可能快地跳到正確的位置仍然很重要，因為應用程序2總是有一個失敗的匹配，應用程序3有兩個失敗的匹配。

我們經(jīng)?？吹降牡谝粋€策略是對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倍。 但是如果我們添加我們的同伴錨呢？

有意思！添加錨點使得兩個架構的性能同樣出色！ 事實上，由于失敗的匹配性能大大提高，我們最初的單桿設計稍微好一點，因為有一個比較少的匹配正在執(zhí)行。

我們已經(jīng)得出結論，監(jiān)控“_grokparsefaiure”事件的存在是必不可少的，但是你可以做更多的事情：

自從版本 3.2.0 grok 插件，已經(jīng)有很多設置可以幫助你什么時候事件需要花費長時間來匹配（或者失敗匹配）。使用timeout millis 以及 timeout 標簽能夠?qū)τ?grok 匹配的時間設置一個上限。如果達到了限制時間，這次匹配就會被中斷并且被打上 _groktimeout 標簽。

使用我們之前介紹的相同的條件策略，你·可以將這些事件重定向到 elasticsearch 中的文件或不同的索引，以供日后分析。

另一個非常酷的事情，我們將在 Logstash 5.0 中引入度量的上下文是能夠提取管道性能的數(shù)據(jù)，最重要的是，每個插件的統(tǒng)計數(shù)據(jù)。 在 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”是否快速增長，如果失敗的數(shù)量在增加，可以作為警告標志，表明某些模式設計不好，或者消耗的時間比預期的多。

希望這篇博文能夠幫助你理解 grok 的行為，以及如何提高吞吐量。 總結我們的結論：

grok 匹配失敗的時候性能可能表現(xiàn)不好。

監(jiān)測發(fā)生 _grokfailures的情況并且對于他們的消耗進行基準測試。

使用錨比如 ^ 以及$ 避免歧義并且?guī)椭齽t引擎。

如果你不使用錨的話使用分層匹配會提高性能。如果懷疑的話，直接測量。

使用超時設置或者即將推出的 Metrics API 能夠讓你更好地了解 grok 是如何工作的，并且是性能分析的第一點。