xin9le.net

Microsoft の製品/技術が大好きな Microsoft MVP な管理人の技術ブログです。

Azure Functions の TimerTrigger の処理時間を可視化する

最近、業務でバッチ処理の最適化を行っています。弊社のバッチ処理は Azure Functions の TimerTrigger で書くことが多いです。主な理由は、仮想マシンなどを利用することなくマネージドな環境でタイマーを発動できて丁度よいという点ですが、Consumption Plan (= 従量課金プラン) を利用していると非常に安価に済むというのもあります。

なのですが、Consumption Plan だと実行時間の上限が 10 分と決まっています。これが結構曲者で、タイムアウトを避けるためには処理時間を短くする努力する必要が出てきます。もしそれでも超過してしまう場合は Premium Plan か App Service Plan を選択することになりますが、できる限り 10 分以内に抑える努力をして Consumption Plan を利用したいものです。

なぜこんなことを言っているかと言うと、ちょくちょくタイムアウトが発生していて困っていたからです...(だいぶ直した

可視化に利用する KQL

パフォーマンス改善を行うに際してはまず状況の把握が大事ということで、可視化を図ります。複数あるバッチ (TimerTrigger な Function) の中でも特にどれがインパクトを与えているのかを調査し、改善に繋げます。今回は Azure Functions のログを Application Insights に送り込むようにしている前提で、Application Insights のログを KQL を使って可視化してみました。

requests
| where customDimensions.TriggerReason startswith 'Timer fired at'
| project timestamp, name, duration
| render scatterchart

このクエリを使って実際に運用している環境のログを取り出してみると、以下のようになりました。Functions の開始時間と処理時間の関係がひと目で分かりますね。

f:id:xin9le:20200412232757p:plain

上図によると概ね 5 秒 ~ 15 秒程度で処理が完了していますが、ものによっては 250 秒近くかかっていると分かります。これらに改善の余地があるかを確認すると良いでしょう。他にも

  • 処理の実行を夜間にすることが望ましいか
  • 期待した頻度/回数で実行されているか (= 無駄に実行されていないか)

などの把握や判断にも繋がるでしょう。先の KQL はどの環境でもコピペで使えるはずなので、ぜひお試しください。