[譯]你真的理解grok嗎

neal發表於2018-01-30

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'

這些日誌行在文章開頭提到的指令碼進行基準測試，結果如下：

jndER.md.png

每秒匹配的日誌數

我們可以看到，對於這個 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}$

下面是結果：

jncKe.md.png

對於不匹配的場景，這是一個相當顯著的變化！ 不僅我們在中端和末端場景中消除了巨大的效能下降，而且使初始匹配失敗檢測速度提高了 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倍。 但是如果我們新增我們的同伴錨呢？

jnTxS.md.png

有意思！新增錨點使得兩個架構的效能同樣出色！ 事實上，由於失敗的匹配效能大大提高，我們最初的單杆設計稍微好一點，因為有一個比較少的匹配正在執行。

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

我們已經得出結論，監控“_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 是如何工作的，並且是效能分析的第一點。

相關文章