ログ解析

DevOps開発運用モデルでのOpsの部分で非常に重要なのが、ログ解析です。

サービスに障害が発生した時に、最初に見に行くところがログであることは今も昔も変わりません。また、サービスが正常に機能しているか、近い将来問題になりそうなところはないか、などの疑問がある時も、ログを解析して答えを得ることも出来ます。

Azure Application Insights とKQL

Microsoft/Azureプラットフォームでサービスをデプロイしているなら、ログは全部Azure Application Insight に放り込むという選択は間違ってはいなでしょう。そうやって大量のデータが記録されていきますが、それを取り出すのに使うのが「Kustoクエリ言語（KQL)」です。Azureのサービスの一つである、Application Insight はそれだけでとても便利です。例えば、ログを時系列で表示、グラフで可視化、ドリルダウンで詳細情報に降りていく、アラートを仕掛ける、などなどすぐに使える機能ですでに満載です。ですがどうしても「帯に短し、たすきに長し」という状況が出てきます。そういう場合は、Azure Application Insight の「素のデータ」を「Kustoクエリ言語」を使って分析する、という2段構えのログ解析が可能です。

Kustoクエリ言語はAzure Application Insight だけでなく、より包括的な、Azureを取り巻く実行環境のテレメトリを1元的にモニターできる、Azure Monitor の標準クエリ言語でもあります。

記事の目的

私自身も実をいうと、Application Insight のUIを通して提供されている範囲の機能しか使ってきませんでした。AnalyticsとKustoクエリ言語の存在はもちろん知っていましたが、「しっかり理解して、Opsのユースケースでフルに活用する」というレベルではありませんでした。ということで、じっくり見ていくことにしました。

テスト環境は Azure Application Insightsのデモ https://aka.ms/AIAnalyticsDemo を使います。
（Azure Log Analytics のデモ https://portal.loganalytics.io/demo#/discover/query/main でもKQLを使えますが、データのスキーマが異なります。）

本記事はチュートリアルとしては、KQLの言語の基本機能をコツコツと積み上げるのではなく、より実践的なDevOpsが調べたいであろう内容のひとつ「サービスAPIで失敗しているエンドポイントはどれ？」を想定しています。

サービスのリクエストをざっくり眺めたい

テーブルの名前だけのクエリを実行するだけで、そのテーブルのレコードを10,000、得られます。情報としてはほぼ使い物になりませんが、ここをスタート地点にして絞り込んでいきましょう。

requests

リクエストのAPIエンドポイントと結果をざっくり眺めたい

興味のある特定のカラムを指定して（他のカラムを除外）、知りたいデータにフォーカスした結果を得る。SQLで言うところのSELECTですね。

requests
| project name, success, resultCode

APIのエンドポイント名、成功か失敗か、Httpステータスコードのみ表示されるようになりました。
クエリ文に時間の抽出条件が指定されていない場合、システム側がデフォルトで過去24時間に条件設定しています。
結果の件数もシステム側のデフォルトで10,000件に限定されています。

ところで、実行されるクエリは薄い灰色バックグラウンドでハイライト表示されているクエリだけなので、複数のクエリを同時に書いていくことも出来ます。この特徴を利用して、正しい動作を確認しつつクエリをコピペして、少しだけ変更を加えていくというワークフローで進めていきます。その方が安全に実験できますし、ハマってしまった時に安定している時点まで簡単に戻ることができます。

時間系の抽出条件を自由に指定したい

過去24時間見たい場合もあれば、過去10日間だったり、過去15分だったりといろいろあります。システム側のデフォルト設定に依存しないで、クエリ文に時間系の抽出条件をします。条件はSQLでもおなじみのwhereを使います。

requests
| where timestamp > ago(24h)
| project name, success, resultCode

timestampの値が24時間前の値より大きいレコードのみ抽出しています。ago()関数のパラメーターで簡単に時間系の条件は変えられます。

どのエンドポイントが何回呼び出されたかを知りたい

name カラムはサービスのエンドポイントに対応しています。それぞれのエンドポイントが過去24時間に何回リクエストされたかを調べます。

requests
| where timestamp > ago(24h)
| summarize count() by name 
| project name, count_

requests テーブルのレコードをnameカラムの値でグループ分けし、さらにそれぞれのグループでのレコード総数をカウントして、結果に表示（project）しています。
同じクエリを数回実行してみてください。結果がわりと大きく異なります。というのも返される結果の順序は安定していないからです。
ソートして、回数が多い順（もしくは少ない順）にしてみましょう。

呼び出し回数が多いエンドポイントを調べたい

ソートするにはSQLでもおなじみのorder by を使います。昇順・降順の指定もascとdescを使うのは同じです。回数が大きいから小さいに「降りていく」ので descending (desc) を指定します。

requests
| where timestamp > ago(24h)
| summarize count() by name 
| project name, count_
| order by count_ desc 

GET /FabrikamProd/Content/fonts/segoewp-light-webfont.eot リクエストが20,644回要求されているのが分かります。2番目に多いのはGET /FabrikamProd/Content/fonts/segoewp-webfont.eotですね。
（フォントのダウンロードっぽいですね。キャッシュの出番でしょうか）

エンドポイントの失敗回数を調べたい

DevOpsとして気になるのは、どのエンドポイントが失敗しているかですね。それぞれのエンドポイントで、successカラムの値がブール値のFalse（偽）のレコードを数えて表示してみましょう。

requests
| where timestamp > ago(24h)
| summarize failed=countif(not(tobool(success))) by name
| project name, failed
| order by failed

success カラムの値をtobool()関数で包んでブール値に変換し、さらにそれをnot()で包んで「成功→ 失敗」の意味に反転して、countif()関数で「失敗した」という条件を満たすレコードだけを数えています。
failed= はカラム名を明示的に指定しています。カラム名はこの方法で簡単に変更できます。

GET ServiceTickets/Detailsというエンドポイントが過去24時間で4,464回失敗しています。

エンドポイントの失敗回数と成功回数を比べたい

失敗回数を数えるやり方と同様に、成功回数も数えて、エンドポイントごとに見ていきましょう。

requests
| where timestamp > ago(24h)
| summarize succeeded=countif(tobool(success)), failed=countif(not(tobool(success))) by name
| project name, succeeded, failed
| order by failed

GET ServiceTickets/Details は1回も成功してないってやばくないですか？
でもよくみるとほぼ失敗しているエンドポイントが結構ありますね。これってサービスとしては成立してませんね、たぶん・・・

失敗率が高いエンドポイントを調べたい

成功回数と失敗回数が出たので、合算してリクエスト総数が出ます。そこから成功率を計算して、成功率の低い順に並べてみます。

requests
| where timestamp > ago(24h)
| summarize succeeded=countif(tobool(success)), failed=countif(not(tobool(success))) by name
| project name, succeeded, failed, successRate = round(toreal(succeeded)/(succeeded + failed) * 100, 2)
| order by successRate asc

toread()関数で整数から実数に変換し、あとはパーセンテージのフォーマットに調整しています。

ここでもGET ServiceTickets/Detailsエンドポイントが見えます。1回も成功していないので、成功率は０％になっています。

もうちょっと現実的な成功率があるエンドポイントが見つかるまでスクロールダウンしてみます。

GET Customers/Detailsの成功率が0.56%なんてユーザーはさぞ怒ってることでしょう。

失敗率が高くて要求回数が多いエンドポイントを調べたい

過去24時間に1回だけ要求されて失敗したエンドポイントと、数千回要求されて1度も成功していないエンドポイントとでは、どちらも成功率で言えば0%ですが、重要度が異なるかもしれません。過去24時間に1回の要求が送金で、数千回の要求がKeepAliveであれば、1回でも深刻な失敗でしょう。今回は数千回要求されたエンドポイントが重要だと仮定して、要求総数も並べ替えに反映させてみましょう。

requests
| where timestamp > ago(24h)
| summarize succeeded=countif(tobool(success)), failed=countif(not(tobool(success))) by name
| extend total = succeeded + failed
| project name, total, succeeded, failed, successRate = round(toreal(succeeded)/(succeeded + failed) * 100, 2)
| order by successRate asc, total desc

extend オペレータを使ってtotalという新しいカラムを結果に追加します。その後に続くエクスプレッションで、totalを使うことが出来ます。

要求回数が多く、成功率が低いレコードから表示されるようになりました。

少なくとも1回失敗していて要求回数が多いエンドポイントを調べたい

ここまで来て、そもそも知りたいのは「失敗したエンドポイント」なので、なるべく早い段階で、1度も失敗していないエンドポイントは結果から排除した方がよいと気づきました。

where を使って残したいレコードの条件「少なくとも1回は失敗している」に合うものだけ残すようにしましょう。

requests
| where timestamp > ago(24h)
| summarize succeeded=countif(tobool(success)), failed=countif(not(tobool(success))) by name
| where failed > 0
| extend total = succeeded + failed
| project name, total, succeeded, failed, successRate = round(toreal(succeeded)/(total) * 100, 2)
| order by successRate asc, total desc

結果の総数が２０になりました。

これで「過去24時間で、少なくとも1回は失敗したリクエストエンドポイントを、要求数の多い順に並べて表示する」ことが出来るようになりました。

可視化してみよう

これまでの結果をグラフにしてみます。

requests
| where timestamp > ago(24h)
| summarize succeeded=countif(tobool(success)), failed=countif(not(tobool(success))) by name
| where failed > 0
| extend total = succeeded + failed
| project name, total, succeeded, failed, successRate = round(toreal(succeeded)/(total) * 100, 2)
| order by successRate asc, total desc
| render barchart 

render barchartでグラフ化出来ました。しかし、データとしてはちょっと訳が分かりませんね。totalはsucceededとfailedを積み重ねれば、その長さがtotalを表すので要りません。successRateは全体（total）に対するsucceededの占める割合なので、グラフ化すると直感的に分かります。

ということで、totalとsuccessRateを取り除きましょう。方法としては、それらのカラムを生成しないようにする方法と、現在のクエリから要らないカラムをprojectしないようにする方法があります。前者の方がパフォーマンス的には良いですが、今回は途中結果をさらに絞り込む方法でやってみましょう。

グラフ化する直前に| project name, succeeded, failedを挟みこむことで、グラフを簡略化しました。これで、水色のエリアが失敗を表すグラフになりました。（色を指定できればさらにいいんですが、今のところ色指定は出来ないようです）

まとめ

Kustoクエリ言語を使って Azure Application Insights のデータから意味あるデータ（インサイト）を抽出することが出来ます。SQLと微妙に作法が異なりますが、直感的で簡潔な文法でデータを加工することが可能です。Azure Application Insights のデモデータを使ってクエリの練習が出来ます。KQLの基本をマスターして開発・保守しているAzureサービスのログ解析作業の効率化を図りましょう！