Azure Monitor でログがクエリできるまでの待ち時間を調べる

Intro

目的

Azure Monitor で発生するログの待ち時間を理解して、どこで待ち時間が発生しているか収集されたログを調べてみましょう。

結論

Azure Monitorに収集されるログレコードには、標準で、ログ生成時刻 TimeGenerated、インデックス完了時刻 ingestion_time() が記録されているので、これらの差分を見るとどれだけ待ち時間があったかわかります。

仕組みの理解

Azure Monitor は、Azure の共通基盤として提供されているログデータサービスです。

待ち時間 latency について

集めているはずのログをクエリしても結果に出てこない！となることがありますが、これは、ログが収集されてからクエリできるようになるまでにいくつか必要なプロセスがあり、それぞれに待ち時間が発生するためです。

以下の図を見てください。

ログ収集エージェント

それぞれのマシン上でログ収集用のエージェントが動いていて、マシン上に生成されるログを Azure Monitor へ送り出す役割をしています。

上図、A => B の時刻の間には、以下のような待ち時間が発生しています。

• ログは細かい頻度でマシン上に出力されますが、エージェントはその都度送らずに、ある程度ためてからAzure Monitorに送信します。一般的にはバッファリングといわれるものです。
• 送信し始めてから、Azure Monitorに達するまでにネットワーク待ち時間が発生します。これは同じAzureリージョン上のマシンとAzure Monitorであれば非常に短い時間になりますが、地理的に異なる場所からログを収集すると、もちろんその待ち時間は大きくなります。

Azure Monitor

そして、Azure Monitorはエージェントからログデータを受け取りますが、すぐにこのログレコードが検索できるようになるわけではありません。

上図、B => C の時刻の間には、以下のような待ち時間が発生しています。

• ログの中身には数多くのプロパティが含まれていて、これらを解析します。
• プロパティを解析したのち、レコードをクエリできるようにインデックスを作成する必要があります。

KQL でクエリしてみましょう

さてここからが本題です。それらの待ち時間を Azure Monitor 上で調べていきます。

Azure Portal で Log Analytics Workspace というコンポーネント上で、左メニューから Logs を選択すると、ログデータをクエリできる画面になります。

事前知識

ログレコード上のプロパティ

まず、待ち時間を調べるために以下3つの時刻が格納されるプロパティを知っておく必要があります。

1. 対象のマシン上でログが生成された時刻です。
   レコード上の、TimeGenerated というプロパティに格納されています。
2. エージェントからの送信が Azure Monitor に到達した時刻です。
   レコード上の、_TimeReceived というプロパティに格納されています。
3. Azure Monitor がインデックスを完了しクエリの準備ができた時刻です。
   レコード上の、ingestion_time() というプロパティに格納されています。

関数

使用するのは時刻の差分を求める datatime_diff() 関数のみです。

...
minute = datetime_diff('minute',datetime(2017-10-30 23:05:01),datetime(2017-10-30 23:00:59)),
second = datetime_diff('second',datetime(2017-10-30 23:00:10.100),datetime(2017-10-30 23:00:00.900)),
...

今回は秒単位 second を使いましたが、ナノ秒までサポートしています。

'millisecond', 'microsecond', 'nanosecond'

A => B : ログが生成されてから、Azure Monitor に到達するまでの時間

TimeGenerated から、_TimeReceived です。

ContainerLog
| extend LatencyAtoBInSeconds = datetime_diff('second', _TimeReceived, TimeGenerated)
| project TimeGenerated, _TimeReceived, LatencyAtoBInSeconds
| order by LatencyAtoBInSeconds

B => C : ログがAzure Monitor に到達してから、クエリ可能になるまでの時間

_TimeReceived から、ingestion_time() です。

ContainerLog
| extend LatencyBtoCInSeconds = datetime_diff('second', ingestion_time(), _TimeReceived)
| project _TimeReceived, ingestion_time(), LatencyBtoCInSeconds
| order by LatencyBtoCInSeconds

A => C : ログが生成されてから、クエリ可能になるまでの時間

まわりくどかったですが、全部でどれだけ待ち時間が発生しているか、調べてみましょう。

TimeGenerated から、ingestion_time() です。上記2つの結果も同時にクエリします。

ContainerLog 
| extend LatencyAtoBInSeconds = datetime_diff('second', _TimeReceived, TimeGenerated)
| extend LatencyBtoCInSeconds = datetime_diff('second', ingestion_time(), _TimeReceived)
| extend LatencyAtoCInSeconds = datetime_diff('second', ingestion_time(), TimeGenerated)
| project TimeGenerated, LatencyAtoBInSeconds, _TimeReceived, LatencyBtoCInSeconds, ingestion_time(), LatencyAtoCInSeconds
| order by LatencyAtoCInSeconds

この結果から、一番時間がかかっていたもので、38秒の待ち時間が発生していたことがわかります。

※このクエリは24時間以内のデータを範囲としています。

内訳は、A => B が35秒、B => C が3秒だったので、ログ生成されてからエージェントがAzureMonitorに送信完了するまでに多くの時間がかかっていることがわかりました。この部分に時間がかかる理由は、先述の行われる処理を見てください。

今回は特に理由もなく、ContainerLog テーブルを選択しましたが、この部分を差し替えるだけで他のテーブルも同様に確認できます。

これでどこで待ち時間が発生しているかクエリで確認できるようになりました。

おまけ：どの時間帯で平均待ち時間が多く発生しているかのグラフ

過去5日間の範囲で、15分ごとの平均待ち時間がどのように遷移しているかクエリ結果をグラフにしてみましょう。

KQL でログからグラフを作成するためには、summarize や render を使います。

https://docs.microsoft.com/ja-jp/azure/azure-monitor/log-query/charts

ContainerInventory
| where TimeGenerated > ago(5d) 
| extend LatencyAtoBInSeconds = datetime_diff('second', _TimeReceived, TimeGenerated)
| extend LatencyBtoCInSeconds = datetime_diff('second', ingestion_time(), _TimeReceived)
| extend LatencyAtoCInSeconds = datetime_diff('second', ingestion_time(), TimeGenerated)
| summarize avg(LatencyAtoCInSeconds), avg(LatencyAtoBInSeconds), avg(LatencyBtoCInSeconds) by bin(TimeGenerated, 15m)
| render timechart

青：A=>C、黒：A=>B、緑：B=>C、です。結果から以下のようなことがわかりました。
※この傾向は、あくまでこのマシン＆このログの特有のものであり、一般的な傾向を示すものではありません。

• 時間が経つにつれて待ち時間が大きくなりある一定の時間で一気に解消されている
• 15分平均で慣らしてしまうと、大きくても20秒ほどの待ち時間におさまっている
• 緑のAzure Monitor解析＆インデックス部分は全体待ち時間の大小に関わらず一定で、黒のエージェントで発生している待ち時間が全体待ち時間の遷移に作用している

参考ドキュメント

公式ドキュメント

Azure Monitor でのログ データ インジェスト時間

一般的な待機時間

ログ データを取り込むための一般的な待機時間は 2 分から 5 分です。

待機時間に影響する要因

• エージェント時間
• パイプライン時間
• インデックス作成時間

インジェスト時間のチェック

Azure Monitor ログ レコードの標準プロパティ

• TimeGenerated
• _TimeReceived
• ingestion_time()

Azure Monitor ログ クエリからのグラフと図の作成

• 結果のグラフ表示
• 時間グラフ
• 複数のディメンション