Herokuログ解析のためのパワーツール

あなたのログデータは、あなたのアプリケーションに関する情報の宝庫ですが、それは圧倒的でありえます.このポストは、あなたのログからメトリクスと他の役に立つ情報を抽出するためのいくつかの戦略に掘ります.の基本から始めましょうheroku logs コマンドは、我々は本当の楽しみにツールを使用して掘るよAngle Grinder .

Herokuログの表示方法

heroku logs 独自のちょうどあなたのアプリケーションから最新のログを印刷し、終了します.一般に、それは非常に役に立ちません.私はほとんど常に-t (or --tail ) オプションは、継続的に尾を私のログに.また、私は通常、それは特定のdynoプロセスにスコープしたいので、私は含まれます-d router , -d web , or -d worker それで、私は関連するログだけを見ています.
以下にルータのログをどのように渡しますか

heroku logs -t -d router

2021-07-28T16:23:07.870849+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.8&pid=4" host=api.railsautoscale.com request_id=0ce66277-877c-4d4f-91c4-2c1075089b41 fwd="3.84.54.241,172.70.34.122" dyno=web.7 connect=1ms service=156ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.774247+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.3&pid=81" host=api.railsautoscale.com request_id=fe46b69d-8938-4d41-a566-4c837050f6da fwd="3.85.98.203,172.69.62.61" dyno=web.14 connect=1ms service=14ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.627308+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.1&pid=11" host=api.railsautoscale.com request_id=f5b69be4-8283-48f6-b683-30c051b4f51d fwd="34.232.107.232,172.70.42.94" dyno=web.11 connect=0ms service=327ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.740752+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.4&pid=4" host=api.railsautoscale.com request_id=89d2da0d-e1d8-484d-99f2-bf26921ba9a5 fwd="3.249.54.29,162.158.158.123" dyno=web.11 connect=0ms service=354ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.881220+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.1&pid=24539" host=api.railsautoscale.com request_id=37171239-4524-46cf-9dce-7cdda8bd4ace fwd="3.95.158.194,172.70.34.173" dyno=web.20 connect=2ms service=34ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.743590+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.1&pid=50" host=api.railsautoscale.com request_id=bb063a51-8d83-4284-b26a-db31c3f4b485 fwd="54.204.194.19,172.70.34.122" dyno=web.8 connect=1ms service=19ms status=204 bytes=358 protocol=https

更なるスコーピング

であっても-d フィルタは、通常、あまりにも多くのデータが有用であるので、私はそれをさらにフィルタしたいと思います.これはどこで連鎖するかgrep が便利です.
ここでは、私の労働者ログを尻尾します.

heroku logs -t -d worker | grep StatWorker

2021-07-28T16:28:11.718082+00:00 app[worker.18]: pid=4 tid=1fzk class=StatWorker jid=bae74463b8a3c977aaaac6b4 args=3061,2021-07-28T16:27:50Z measure#sidekiq.queued=1069 tag#worker=StatWorker tag#queue=default INFO: start
2021-07-28T16:28:11.763375+00:00 app[worker.18]: pid=4 tid=1fy4 class=StatWorker jid=2c4de245191802b57344bae8 args=2344,2021-07-28T16:27:50Z measure#sidekiq.queued=933 tag#worker=StatWorker tag#queue=default elapsed=0.181 INFO: done
2021-07-28T16:28:11.782176+00:00 app[worker.18]: pid=4 tid=1fy4 class=StatWorker jid=c704e40d09cf93b628d023f3 args=3000,2021-07-28T16:27:50Z measure#sidekiq.queued=1129 tag#worker=StatWorker tag#queue=default INFO: start
2021-07-28T16:28:11.809741+00:00 app[worker.18]: pid=4 tid=1fzk class=StatWorker jid=bae74463b8a3c977aaaac6b4 args=3061,2021-07-28T16:27:50Z measure#sidekiq.queued=1069 tag#worker=StatWorker tag#queue=default elapsed=0.092 INFO: done
2021-07-28T16:28:11.820178+00:00 app[worker.18]: pid=4 tid=1fzk class=StatWorker jid=7af1852ff673a9f747d8f4ad args=1920,2021-07-28T16:27:50Z measure#sidekiq.queued=1171 tag#worker=StatWorker tag#queue=default INFO: start
2021-07-28T16:28:11.719832+00:00 app[worker.20]: pid=4 tid=13c4g class=StatWorker jid=c531a39bf63886c8ce386c13 args=3826,2021-07-28T16:27:50Z measure#sidekiq.queued=922 tag#worker=StatWorker tag#queue=default elapsed=0.149 INFO: done
2021-07-28T16:28:11.721947+00:00 app[worker.20]: pid=4 tid=13c4g class=StatWorker jid=4e2884278d99fb616eb452b1 args=1546,2021-07-28T16:27:50Z measure#sidekiq.queued=1073 tag#worker=StatWorker tag#queue=default INFO: start
2021-07-28T16:28:11.761234+00:00 app[worker.20]: pid=4 tid=8rk60 class=StatWorker jid=9f54c9b8418801e4274f0fe7 args=2191,2021-07-28T16:27:50Z measure#sidekiq.queued=928 tag#worker=StatWorker tag#queue=default elapsed=0.184 INFO: done

これは"pipe" 出力を送るheroku logs への入力 grep utility . grepは正規表現を用いてプレーンテキストデータを検索する.この例ではregexp構文を使用していませんが、確かに可能です.
チェーンheroku logs -t with grep 私はどのように私はHerokuログと最も頻繁に相互作用するが、時々私はより多くの力を必要とする.

特定の値の抽出

会う時間だAngle Grinder , リアルタイムログ解析パワーツールこれは、多くの形式を解析し、値を抽出し、さらに集約を行うことができます.ちょうど例で右に飛び込んでください.
Herokuのルータのログは、すべてのHerokuアプリのために同じようにフォーマットされているので、それらを使用しましょう.以下に見たのと同じルータログ出力です.

heroku logs -t -d router

2021-07-28T16:23:07.870849+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.8&pid=4" host=api.railsautoscale.com request_id=0ce66277-877c-4d4f-91c4-2c1075089b41 fwd="3.84.54.241,172.70.34.122" dyno=web.7 connect=1ms service=156ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.774247+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.3&pid=81" host=api.railsautoscale.com request_id=fe46b69d-8938-4d41-a566-4c837050f6da fwd="3.85.98.203,172.69.62.61" dyno=web.14 connect=1ms service=14ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.627308+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.1&pid=11" host=api.railsautoscale.com request_id=f5b69be4-8283-48f6-b683-30c051b4f51d fwd="34.232.107.232,172.70.42.94" dyno=web.11 connect=0ms service=327ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.740752+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.4&pid=4" host=api.railsautoscale.com request_id=89d2da0d-e1d8-484d-99f2-bf26921ba9a5 fwd="3.249.54.29,162.158.158.123" dyno=web.11 connect=0ms service=354ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.881220+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.1&pid=24539" host=api.railsautoscale.com request_id=37171239-4524-46cf-9dce-7cdda8bd4ace fwd="3.95.158.194,172.70.34.173" dyno=web.20 connect=2ms service=34ms status=204 bytes=358 protocol=https
2021-07-28T16:23:07.743590+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.1&pid=50" host=api.railsautoscale.com request_id=bb063a51-8d83-4284-b26a-db31c3f4b485 fwd="54.204.194.19,172.70.34.122" dyno=web.8 connect=1ms service=19ms status=204 bytes=358 protocol=https

メタデータがすべてフォーマットされていることに気づくでしょう[key]=[value] . この形式は logfmt . それはHerokuによって重く抱きしめられます、そして、角度グラインダーがわかる多くのフォーマットの1つです.
行くAngle Grinder installation instructions その後に沿って従って戻ってくる.
Herokuルータログのアングルグラインダーのlogfmt解析を使いましょう.

heroku logs -t -d router | agrind '* | logfmt'

[2021-07-28T16:50:11.654197+00:00=None][at=info][bytes=358][connect=1ms][dyno=web.2][fwd=54.154.157.222,162.158.159.109][heroku[router]:=None][host=api.railsautoscale.com][method=POST][path=/api/REDACTED/v2/reports?dyno=web.3&pid=79][protocol=https][request_id=d4ecf840-666b-430f-81c3-082b4e58c876][service=29ms][status=204]
[2021-07-28T16:50:11.450697+00:00=None][at=info][bytes=358][connect=4ms][dyno=web.18][fwd=34.233.123.109,172.69.62.81][heroku[router]:=None][host=api.railsautoscale.com][method=POST][path=/api/REDACTED/v2/reports?dyno=web.5&pid=242][protocol=https][request_id=1599b9f0-17ec-48ae-8341-5d917bcbd598][service=19ms][status=204]
[2021-07-28T16:50:11.644107+00:00=None][at=info][bytes=358][connect=1ms][dyno=web.16][fwd=3.84.186.26,172.70.38.19][heroku[router]:=None][host=api.railsautoscale.com][method=POST][path=/api/REDACTED/v2/reports?dyno=web.1&pid=9][protocol=https][request_id=2bef6858-458f-47f9-9e97-8c35c4d9ebef][service=12ms][status=204]

さて、それは本当に以前より良いです.キーの値のペアが解析されたが、それはまだテキストの壁です.
もう一度試してみましょう--format オプションは、“接続”と“サービス”メトリックのログからの表示を表示します.

heroku logs -t -d router | agrind '* | logfmt' --format '{connect} {service}'

2ms 9ms
1ms 160ms
1ms 15ms
0ms 6ms
4ms 192ms

今、我々はどこかに得ている!配列を展開して、より詳細なデータを表示します.さらにコマンドを複数行に分割して読みやすくします.

heroku logs -t -d router | agrind \
  '* | logfmt' \
  --format '{dyno:<6} {connect:6} {service:7} {status:4} {method:5}  {path}'

web.3     0ms    52ms  204  POST  /api/REDACTED/v2/reports?dyno=web.1&pid=37
web.23    1ms    17ms  204  POST  /api/REDACTED/v2/reports?dyno=web.2&pid=4
web.4     1ms    40ms  204  POST  /api/REDACTED/v2/reports?dyno=web.3&pid=186
web.1     1ms    17ms  204  POST  /api/REDACTED/v2/reports?dyno=web.1&pid=86
web.13    1ms    10ms  204  POST  /api/REDACTED/v2/reports?dyno=web.21&pid=65

美しい!我々は、テキストの壁をきれいに整列、人間の読み込み可能なストリームに分割しました.あなたはリアルタイムであなたのウェブトラフィックを見るためにこれを使用することができます.これから、私たちは、特定のダイノが苦戦しているか、特定の経路が我々が予想するよりしばしば要請されているならば、速くわかることができました.

角度砥石はどのように働きますか？

さて、最後の例を剥がしましょう.
まず、Heroku CLIを使ってHerokuログを最初にログします.

heroku logs -t -d router

そして、出力をagrind (私たちが配管していたようにgrep 前に).agrind “query”と呼ばれる一つの引数を取ります.これはアングルグラインダーにどのように入って来るテキストを処理するかを指示します.問い合わせはすぐにわかりますが、この例では簡単になります.

heroku logs -t -d router | agrind '* | logfmt'

ここで、クエリは* | logfmt , そして、それを1つの引用符で囲み、残りのコマンドから切り離します.問い合わせ文字列内の“pipe”文字を見て少し奇妙に見えるかもしれないので、コマンドラインパイプと混同しないよう注意してください.
アングルグラインダークエリ構文は、一連の演算子を持つ初期フィルタの構成です.以下にこのクエリの内容を説明します.

* – これは最初のフィルタです、そして、それは角度グラインダーにあらゆる入力線で動くように言います.

logfmt – これは演算子で、logfmt構文を使用してキー/値フィールドを抽出します.

最初の演算子は一般にパーサーです.次に、その後の演算子がどのようにして抽出されたフィールドで動作するかを見ます.
✉️ 我々はこのような記事を書くときに通知したいですか?サインアップMastering Heroku メーリングリスト!月に1つ未満のメールは、常に関連し、販売のピッチ.

リアルタイムでログデータを集約する

要求の安定したボリュームで、我々がこれまで見たものは、まだ圧倒的な量の情報でありえます.我々が探しているものに応じて、我々は使用することができますAngle Grinder's aggregate operators ログデータをリアルタイムで要約するには.
たとえば、Dynoによる50番目と95番目のパーセンタイルサービスタイムズのスナップショットです.

heroku logs -t -d router | agrind \
  '* | logfmt | p50(service), p95(service), count by dyno | sort by p50 desc'

dyno         p50        p95        _count
------------------------------------------------------
web.2        57         369        622
web.3        40         287        622
web.1        36         114        598
web.7        18         306        612
web.5        15         93         641
web.6        13         41         631
web.4        9          25         576

今我々のアングルグラインダーのクエリは、いくつかの操作が一緒に連鎖して、より複雑になっている

* – すべての入力行で操作します.

logfmt – LogFMTパーサーを使用してフィールドを展開します.

p50(service), p95(service), count by dyno – “dyno”フィールドでグループ化された3つの集計を計算します.これは、“dyno”フィールドをlogfmt , その通りでした.この動作の出力は、「P 50」、「P 95」、「カウント数」の3つのフィールドである.

sort by p50 desc –“p 50”フィールドに集約結果をソートします.

これらのフィールドの順序を変更することができます.

heroku logs -t -d router | agrind \
  '* | logfmt | count as count, p95(connect) as connect, p95(service) as service by dyno | sort by p50 desc'

dyno          count        connect        service
--------------------------------------------------------------
web.3         618          1              84
web.1         693          1              93
web.6         623          2              62
web.4         624          1              20
web.5         674          2              561
web.2         673          2              573
web.7         621          4              191

クエリが読みにくいので、多くの行に分割します.

heroku logs -t -d router | agrind \
  '*
    | logfmt
    | count as count,
      p95(connect) as connect,
      p95(service) as service
      by dyno
    | sort by p50 desc'

ちょうどlogfmt以上の構文解析

私が非常に便利であるとわかる1つの質問は、2番目によってグループ化することです.これは私が私のアプリが実行されている方法の2番目の要約でライブ第二を参照してください.問題が解決されるとき、私が正確に見ることができるように、生産ボトルネックがあるとき、私はこれを使います.

heroku logs -t -d router | agrind \
  '*
    | parse "T*." as time
    | logfmt
    | count as count,
      p95(connect) as connect,
      p95(service) as service
      by time
    | sort by time'

time            count        connect        service
----------------------------------------------------------------
19:20:36        354          2              1452
19:20:37        492          2              825
19:20:38        519          1              740
19:20:39        513          3              270
19:20:40        435          2              74
19:20:41        451          4              76
19:20:42        468          4              82

このクエリは新しいパーサparse . この集約のために、私は2番目に切り詰められた時間文字列を必要としました.parse ログ行の任意の場所から値を取り出すために任意の文字列マッチングの権限を与えます.
以下にリファレンス用の生ルータログの例を示します.

2021-07-28T16:23:07.870849+00:00 heroku[router]: at=info method=POST path="/api/REDACTED/v2/reports?dyno=web.8&pid=4" host=api.railsautoscale.com request_id=0ce66277-877c-4d4f-91c4-2c1075089b41 fwd="3.84.54.241,172.70.34.122" dyno=web.7 connect=1ms service=156ms status=204 bytes=358 protocol=https

タイムスタンプがlogfmtデータの前にあることに注意してください、そして、それはlogfmtキー/値組としてフォーマットされません.parse "T*." as time パターンを使用して単一のフィールドT*. . アスタリスク* ) はワイルドカードであり、消費するものはフィールドとして抽出される.したがって、単一のアスタリスクは、単一のフィールドが抽出されることを意味します.間のテキストT and . is 16:23:07 , それで、それは「時間」の値になります.
そこから、私たちが以前に見たことがあります.logfmt logfmtデータを解析し、集約演算を行い、出力をソートします.

条件集合

つの最後の例は、我々のクエリで条件論理を使用する方法を示します.

heroku logs -t -d router | agrind \
  '*
    | parse "T*." as time
    | logfmt
    | count(status == 200) as successful,
      count(status != 200) as failure,
      p95(service) as service,
      p95(connect) as connect
      by time
    | sort by time desc'

time            successful        failure        service        connect
------------------------------------------------------------------------------------
19:41:58        189               244            1803           1
19:41:57        182               120            2076           1
19:41:56        191               163            2479           1
19:41:55        174               122            2300           1
19:41:54        176               97             2196           1

この例は、別のアプリから取られ、それはあまりうまくやっていない.要求の半分以上が失敗している.😱
それでも、我々は我々のコンディショナーを使うことができるのはかなりクールですcount 「ステータス」のような抽出されたlogfmtフィールドを使用する集約.

あなたのターン

うまくいけば、今ではアングルグラインダーをインストールしているし、いくつかの楽しいスライスと自分のログデータをダイシングしている.
私たちのHerokuログストリームは完全に圧倒することができますheroku logs , grep , 特にagrind 私たちはファイアウォールから有用な情報を得るために必要なすべてを与えます.