App Engine で謎の Untraced Time が発生するときは
App Engine を利用していると、時たま何かに引っかかったように処理が詰まることがあります。こんな時にはもちろん StackDirver Trace を使ってボトルネックを探ったりするわけです。 しかしながら時に、何の RPC を呼び出しているわけでもないのに、何故か処理の開始が遅い場合や、レスポンスを返すのが遅いということがあります。
よくありがちな理由が、リクエストが殺到して新規インスタンスがスピンアップするときに処理が遅れることです。私の周りでは良く「スピンアップに引っかかる」と言っています。しかし、具体的に何が起こっているのか、本当にスピンアップが起因しているのかは曖昧のままでした。そのため、今回、真面目に調べてみることにしました。
Request Queue を理解する
App Engine がスケールする仕組みを詳しく知るには Pending Request Queue を理解する必要があります。もちろん公式が信頼できる情報になるわけですが、日本語の情報としては sinmetal 氏の解説が分かりやすいです。
- 公式: How Instances are Managed | App Engine standard environment for Go | Google Cloud Platform
- sinmetal 氏解説: App Engine Scaling Config - Qiita
App Engine がリクエストを受け取ると以下の流れで処理をします。
- Idle 状態またはリクエストを受け付ける余力のあるインスタンスがあればリクエストを割り振る
- 1 でリクエストを割り振れない場合 Pending Request Queue に突っ込んで空きを待つ
- 2 で指定時間以上リクエストが滞留していれば新しいインスタンスをスピンアップする
また、公式のページの通り、各インスタンスにも Request Queue があります。インスタンス上の Request Queue にリクエストが溜まり過ぎている場合にも App Engine は新しいインスタンスを立ち上げにかかります。(本来ならば max_concurrent_request を調整し、このような状態に陥らない様にするのが正しそうですね)
つまりリクエストを受付可能なインスタンスが不足している、新規インスタンスのスピンアップに時間がかかっているという場合に Pending Request Queue にリクエストが溜まることが発生します。
Loading Request を知る
本家のページを見てみると Loading Request なるものがあります。ある新規インスタンスが初めてリクエストを処理するとき、リクエストの処理の前に、アプリケーションのコードを読み込みます。この読み込みによってリクエストの処理に更に時間がかかることになります。この「初めてのリクエスト」を Loading Request と呼びます。
Loading Request もスピンアップに関連して処理が遅延しうるものです。しかし、Pending Request Queue での滞留と違って、各インスタンスへリクエストが割り振られた後に発生するものです。そのため、Scaling Type などの設定でどうこうできるものではありません。Loading Request による遅延を解消するにはアプリケーションの起動をチューニングする必要があります。Go ランタイムのような起動の早いランタイムを利用したり、初期に読み込むコードを絞って起動を早くしたりするなどの手があります。
もう一つの手として Warmup Request を使う手があります。インスタンス起動時に App Engine から、Loading Request を呼び出してもらいます。これが Warmup Request です。Warmup Request を使うことによって、ユーザーリクエストを Loading Request とすることを防ぐことができます。
https://cloud.google.com/appengine/docs/go/warmup-requests/configuring
CPU ヘビーな処理をしている
もう一つの可能性として、スピンアップに関係なく CPU ヘビーな処理をしている場合にも Untraced Time が発生します。この場合アプリケーションの処理自体を最適化する必要があります。数値計算や暗号化などの処理をヘビーに行っている場合や、reflect パッケージ を使っている場合などによく当たります。
原因を見分ける
これらの原因を見分ける方法はログを見ることです。App Engine のログには、何にどれぐらいの時間を使ったかが記録されています。
例えば以下の様に判断をすることができます。
- pending_ms が記録されている -> Pending Request Queue での待ちが発生している
- loading_request=1 が記録されている -> Loading Request として処理が遅延している
- cpu_ms が支配的 -> CPU ヘビーな処理をしている
App Engine で謎の Untraced Time が出たときにはログをよく見ましょう。
