しばやん雑記

Azure とメイドさんが大好きなフリーランスのプログラマーのブログ

Application Insights と KQL を使って複雑な解析を行いたい

Application Insights

最近は地味に KQL (Kusto Query Language) を書く機会が多くなってきたので、忘れないようにはまったポイントと書いたクエリを残しておくことにします。

Application Insights を使っていますが、KQL 自体は Azure Data Explorer と同じなのでリファレンスは同じものが使えます。というか Azure Data Explorer の上に Application Insights が乗っかっています。

KQL で迷ったら以下のリファレンスを読めば、大体は解決するはずです。読んでおきましょう。

Application Insights 側のドキュメントにもサンプルがいくつか用意されています。読んでおくと良いです。

クエリエディタでは入力補完が効くので、比較的簡単に書くことは出来ます。よく使うのは where / project / summarize / render とかだと思います。

一番はまったポイントとしてはデータ型でした。Kusto は以下のドキュメントにあるようにいくつかの型を持っていますが、スキーマとして定義されているもの以外は実行時に確認するしかないです。

例えば Azure Functions が送信したログには Function の実行時間を表す FunctionExecutionTimeMs が含まれているので、その値を利用してグラフを描こうとしてみます。

KQL は以下のようなものを用意しましたが、実行するとエラーになります。

requests
| project execution_Time = customDimensions['FunctionExecutionTimeMs'], timestamp
| render timechart

エラーメッセージが出てるので理由は分かります。今回は FunctionExecutionTimeMs の値はぱっと見 double のように見えても、実体は string なのが原因です。

f:id:shiba-yan:20190414015638p:plain

なので解決法としては以下のように double に変換してあげるだけです。

requests
| project execution_Time = todouble(customDimensions['FunctionExecutionTimeMs']), timestamp
| render timechart

これで実行すると思った通りのグラフが描画されます。このようにデータ型を意識しないとはまります。

f:id:shiba-yan:20190414015900p:plain

グラフの描画でエラーになるのはほぼデータ型だと思うので、この点だけ理解しておけば大体解決すると思います。ただし timespan 型に関しては、そのまま表示出来そうなのにエラーになるので注意が必要でした。

Function の Cold Start にかかった時間を調べる

ちょっとしたサンプルという感じで Azure Functions の Cold Start にかかった時間を調べる KQL を書いてみます。Azure Functions Host は Application Insights に起動開始時と完了時にログを送信しているので、その時間の差を取れば分かります。

別々の条件で絞り込んで結合しないといけないので join を使って対応します。この時 join に使う条件としてはインスタンス ID を選びました。*1

traces
| where message == "Initializing Host."
| project start = timestamp, cloud_RoleInstance
| join kind=inner (
   traces
   | where message == "Job host started"
   | project end = timestamp , cloud_RoleInstance
) on cloud_RoleInstance
| project start, duration = (end - start) / 1s
| render timechart

いきなり複雑な感じの KQL になりましたが、やっていることは大したことありません。join した結果に対して project をかけて、所要時間を計算しています。

この時 duration をそのまま duration = (end - start) とすると、計算結果の型が timespan になりグラフの表示時にエラーとなるため、1s で割って秒単位に変換しています。

f:id:shiba-yan:20190414005200p:plain

datetime / timespan の計算結果については以下の図を見てもらえれば理解できるはずです。

f:id:shiba-yan:20190414021629p:plain

とりあえず上のクエリで時系列データとしてグラフを表示出来ましたが、Host が起動していない時間帯などは当然データが存在しないので、グラフもデータが欠落していて分かりにくくなっています。

もっと綺麗に表示するために専用のオペレータを使って対応します。Kusto には時系列データを扱うための機能がちゃんと用意されているので、簡単に組み込めます。

今回は make-series を使って欠落したデータを補います。range を使って指定した範囲にデータが存在しない場合は default で指定した値が使われます。

traces
| where message == "Initializing Host."
| project start = timestamp, cloud_RoleInstance
| join kind=inner (
   traces
   | where message == "Job host started"
   | project end = timestamp , cloud_RoleInstance
) on cloud_RoleInstance
| project start, duration = (end - start) / 1s
| make-series duration = max(duration) default = 0 on start in range(ago(7d), now(), 1h)
| render timechart

上の KQL を実行すると、先ほどのグラフとは異なり欠落している部分は 0 が使われて、分かりやすいグラフとなりました。圧倒的にこちらのグラフの方が良いですね。

f:id:shiba-yan:20190414005145p:plain

Cold Start にかかった時間を調べるのに join を使うクエリを書きましたが、実は Azure Functions Host が所要時間をログに送信してくれているので、それを使う方法も試します。

メトリクスとして送信してくれていれば簡単なのですが、以下のようにテキスト中に含まれる形になっているため、そのメッセージをパースしないと使えないのが厄介です。

f:id:shiba-yan:20190414161057p:plain

SQL なら面倒なクエリを書くことになると思いますが、KQL の場合は組み込みでテキストデータのパース機能を持っているので、直感的に書くことが出来ます。

先ほどのメッセージをパースして、所要時間だけを取り出す場合は以下のようなクエリを書きます。パースしたいテキストをテンプレートのように記述して処理できるので楽です。

マッチしなかった場合には空文字列が入ってくるので where でフィルタリングしておきます。当然文字列なので double に変換してグラフとして表示します。

traces
| parse message with "Host started (" Duration "ms)"
| where Duration != ""
| project duration = todouble(Duration) / 1000, timestamp
| render timechart

実行するとちゃんとグラフが表示されます。parse は割と使い道が多そうなので覚えておきたいです。

f:id:shiba-yan:20190414005523p:plain

今回は使わなかったですが、timespan として扱いたい場合は make_timespan を挟めば良いです。

Function の実行回数を調べる

元々 Application Insights を見れば大体わかってましたが、分かりやすい題材だったので取り上げてみます。Function 実行時には InvocationId が常に割り振られているので、それを使って集計します。

InvocationId は customDimensions に入っているので、取り出すときには少し注意が必要です。更に型は guid なので油断すると死にます。

let step = 5m;
let begin = ago(3d);
requests
| where timestamp > begin
| project customDimensions.InvocationId, timestamp
| make-series invocation_Count = count() default = 0 on timestamp in range(begin, now(), step)
| render timechart

この KQL を実行すると、Function 全体での実行回数がグラフになります。

f:id:shiba-yan:20190414011044p:plain

Function の処理時間も customDimensions から取れるので、継続的なパフォーマンスモニタリングとしても十分使えるはずです。

おまけとして、Function 単位での実行回数もグラフにしてみます。日付は関係ないので無視してください。

let step = 1s;
let begin = datetime("2019-03-30 14:59:30");
let end = datetime("2019-03-30 15:01:20");
requests
| where timestamp between(begin .. end)
| make-series invocation_Count = count() default = 0 on timestamp in range(begin, end, step) by operation_Name
| render barchart kind=stacked

単純に make-series を operation_Name 単位にしてあげるだけです。

今回は見た目に分かりやすそうな棒グラフにしておきました。

f:id:shiba-yan:20190414163752p:plain

それぞれの Function がどの時間帯に何回実行されたのか分かります。Durable Functions を使っているので複数回呼び出されてることも、このグラフから読み取れますね。

Consumption で利用されたインスタンス数を調べる

Azure Functions の Consumption Plan や Premium Plan は App Service Plan の時とは異なり、スケーリングのログが Activity Log から確認出来ないので、消費されたインスタンス数を簡単に確認できません。

ただし Application Insights にはインスタンス ID が送信されているので、これを使ってインスタンス数でのグラフを描いてみます。KQL は以下のような感じに。

let step = 5s;
let begin = ago(20m);
requests
| where timestamp > begin
| distinct cloud_RoleInstance, bin(timestamp, step)
| make-series instance_Count = count() default = 0 on timestamp in range(begin, now(), step)
| render timechart

当然ながら複数回、同じインスタンス ID が付いたログが飛んでくるので、さっきまでのように単純に集計していると実行回数のログになるので、先に distinct を入れてインスタンス ID の重複を排除しています。

実行すると Consumption でインスタンスがどれぐらい使われたのかグラフで確認できます。

f:id:shiba-yan:20190414013408p:plain

Consumption Plan に負荷をかけるために loader.io を使いました。Azure DevOps の Load Test が廃止決定したので、割と便利に使わせてもらっています。

Azure Portal から操作は出来ないですが、Consumption から Premium への移行も簡単なので、移行を検討するメトリクスの一つとして使えるのではないかと。

*1:Consumption の場合は起動時にほぼ確実に別の値になるので結合に使える