Cloud Runをコールドスタートからレスポンスタイムが安定化されるまでどのぐらいかかるか
Cloud Runの概要は
さんの”Cloud Run が GA になったから改めて色々見てみる”を是非見てください。最近、2019年11月14日にGAになったGCPのCloud Runを試しましたが、”トラフィックに応じてゼロからNまで自動的にスケールします”という点が気になりました。
文字通りに解析すると急にトラフィックが増えても対応できますし、深夜になってトラフィックが減った時には課金を節約できる、すごく理想的な話です。
ただ、公式文書を詳しく読んで見ると0からスタートする時（必ず0からスタートではなくコンテナの準備が必要な時）にはコールドスタートが発生して、レスポンスに遅延が発生することでした。どのぐらいの遅延が発生するかの内容はなかったので検証して見ました。
テスト・アプリケーション
アプリケーションのレスポンスタイムはアプリケーションのワークロードや他のリソースへのアクセス等で変化する思いますが、今回は ”クイックスタート：ビルドとデプロイ”のJavaで書かれたサンプル・アプリケーションをベースして、レスポンスする前に200msのsleepをを追加してコンテナ化して実施しました。
また、コンテナが起動した時間をStackdriverに出力するためにlogbackを追加しました。
*Java 用 Stackdriver Loggingの設定
ソースコードに変更内容を反映するために”クイックスタート：ビルドとデプロイ”からソースコードをダウンロードし、zipファイルをローカルに展開し、HelloworldApplication.javaにsleepコードとloggerを追加します。
*logbackを使うためにはpom.xmlに必要な依存関係を使いする必要があります。
package com.example.helloworld;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@SpringBootApplication
public class HelloworldApplication {
private static final Logger logger = LoggerFactory.getLogger(HelloworldApplication.class);
@Value("${TARGET:World}")
String target;
@RestController
class HelloworldController {
@GetMapping("/")
String hello() {
try{
Thread.sleep(200);
}catch(Exception e){
}
return "Exit Test version Hello " + target + "!";
}
}
public static void main(String[] args) {
logger.info("Start: Helloworld from Cloud Run! The container started successfully and is listening");
SpringApplication.run(HelloworldApplication.class, args);
}
}ビルドと展開
必要なコードを追加したあとはCloud buildsでビルドし、コンテナ・レジストリ(Google Container Resistry)に登録します。
$ gcloud builds submit --tag gcr.io/[[ Project ID ]]/helloworld
……
[INFO] Replacing main artifact with repackaged archive
[INFO] -------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] -------------------------------------------------------------
[INFO] Total time: 34.230 s
[INFO] Finished at: 2019-12-23T04:19:17Z
[INFO] -------------------------------------------------------------
……
latest: digest: sha256:e1e2b9f3bff2099cefb5cf5e664e7bec8dd9e0e830dd41a3de50d7165c8978be size: 1371
DONE
--------------------------------------------------------------------
ID CREATE_TIME DURATION SOURCE IMAGES STATUS
d0add437-86f6-4b54-a432-9ed2a0570ba4 2019-12-23T04:18:26+00:00 1M7S gs://[[ Project ID]]_cloudbuild/source/1577074704.52-6832d372531d4bc1a258c3bb3bc101cf.tgz gcr.io/[[ Project ID]]/helloworld (+1 more) SUCCESS*[[ Project ID]]は検証を行うGCP ProjectのIDになります。
ビルドができたら次はCloud RunへDeployをします。Deploy時に、コンテナに付与する最大メモリ数と１つのコンテナで同時に処理するリクエスト数を指定します。
コンテナのメモリの指定は ”--memory SIZE”オプションを付けて指定しますが、指定しない場合には基本メモリサイズの256MiBが付与されます。このオプションで指定したメモリは主に下記の３つで使われます。
- サービスを処理する
- ファイルをディスクに書き込む
- nginx ウェブサーバーなど、コンテナ内でバイナリまたは他のプロセスを実施する
メモリの設定に関するより詳細な内容はは ”メモリ制限を構成する” から確認できます。
Javaの環境変数は “--set-env-vars=JAVA_TOOL_OPTIONS=”で指定します。今回はJavaのインスタンスの最大メモリをコンテナと同じ256MBを指定します。
同時に処理するリクエスト数は1にします。(“--concurrency=1”)
$ gcloud beta run deploy --image gcr.io/[[ Project ID]]/helloworld --set-env-vars="JAVA_TOOL_OPTIONS=-XX:MaxRAM=256m" --concurrency=1Deployを実行するとtarget platformとリージョン、サービス名を求められます。今回は Fully managedでasia-northeast1、helloworldというサービス名で登録します。
Please choose a target platform:
[1] Cloud Run (fully managed)
[2] Cloud Run for Anthos deployed on Google Cloud
[3] Cloud Run for Anthos deployed on VMware
[4] cancel
Please enter your numeric choice: 1
To specify the platform yourself, pass `--platform managed`. Or, to make this the default target platform, run `gcloud config set run/platform managed`.
Please specify a region:
[1] asia-northeast1
[2] europe-west1
[3] us-central1
[4] us-east1
[5] cancel
Please enter your numeric choice: 1
To make this the default region, run `gcloud config set run/region asia-northeast1`.
Service name (helloworld): helloworld
Deploying container to Cloud Run service [helloworld] in project [Project ID] region [asia-northeast1]
⠹ Deploying... Deploying Revision...
⠹ Creating Revision...
. Routing traffic...Deployが完了すると下記のように出力されます。
Service name (helloworld): helloworld
Deploying container to Cloud Run service [helloworld] in project [Project ID] region [asia-northeast1]
✓ Deploying... Done.
✓ Creating Revision...
✓ Routing traffic...
Done.
Service [helloworld] revision [helloworld-00022-jot] has been deployedDeployされた内容はCloud Consoleからも確認することができます。
名前の”helloworld”をクリッして、詳細画面に移動した後に画面上段にあるURLをクリックしてアプリケーションが動くことを確認します。
ロードテストツール
次はRequestを送るツールを準備します。ロードテストツールとしては Apache Bench, Apache Jmeter, HEYとかがあると思いますが、今回はLocustを使います。
まず、Cloud Runを配置した同じリージョンで（asia-northeast1）でテストVMを立ち上げてLocustをインストールします。
$python -m pip install locustio
$ locust --version
locust 0.13.5次はシンプルなHTTP GETテストのためlocustのScriptを作成します。
* Scriptの詳細の説明はここを参照してください。
$ vim locustfile.py
from locust import HttpLocust,TaskSet,task,between
class MyTaskSet(TaskSet):
@task
def index(self):
self.client.get("/")
class MyLocus(HttpLocust):
task_set = MyTaskSet
wait_time = between(3,5)作成したScriptを使ってlocustを起動します。
$ locust -f ./locustfile.py --port 8080
[2019-12-23 07:58:49,714] load-tools/INFO/locust.main: Starting web monitor at http://*:8080
[2019-12-23 07:58:49,714] load-tools/INFO/locust.main: Starting Locust 0.13.5プラウザでVMのIP Addressへ接続してlocustが正しく起動していることを確認します。* 対象ポートに外部から接続できるように必要に応じて、事前にFW設定を行ってください。
各項目の説明は下記の通りです。
Number of total users to simulate: 同時接続数
Hatch rate(users spawned/second): 1秒間に増加させる接続数
Host: テストするURL
これでテストの準備ができました。
テストケース１
同時接続数: 500
1秒間に増加させる接続数: 30
テストするURL: helloworldの公開URL
“Start swarming”をクリックして開始した後、”Charts”タブをクリックしてモニタリングをします。一定時間を経過してレスポンスタイムが安定したら”STOP”ボタンをクリックして停止します。
3つのChartが表示されます。
Total Request per Second: locustで前のRequestが完了した後、次にRequestを送るので、ほぼ1秒で処理できるRequestの数と見てもいいと思います（アプリケーションで200ms sleepがある状態）
Response Times (ms): 1秒間の平均レスポンスタイム
Number of Users: 同時接続数
1秒に30接続ずつ増やして500まで増やした場合にResponse Times(ms)のChartを見ると約1秒6秒ぐらいでレスポンスタイムが約250msで安定されることが確認できました。
この間にどのぐらいのCloud Runのコンテナが起動したかを確認するためにStackdriverのLoggingでアプリケーションで指定したログを確認しました。
Stackdriver LoggingからデータをCSVに落としてChart化したすると
この２つのデータから読めるのは（Locustからは秒以下のデータの取得ができなかったため、誤差は1秒ぐらい発生する可能性があります。）
１。Total Request per Secondから最初のRequestが記録されて時間とStackdriver Loggingで記録されている最初起動ログから見ると今回のCloud Run コールドスタートからCloud Runが起動されるまで約2秒がかかっている（最初のRequest: 5時12分27秒、最初の起動ログ: 5時12分29秒）
２。Total Request per Secondから最初のRequestが記録されて時間とResponse Times(ms)の最初の値を値比較すると最初のResponseまで約4秒がかかっている（最初のRequest: 5時12分27秒、最初のレスポンスタイム: 5時12分31秒）
３。同時接続が318になった5時12分38秒にStackdriver Loggingデータを見ると一番多くコンテナが追加されたので、すぐレスポンスタイムが早くなるかと思いましたが、実際にレスポンスタイムが安定してきたのは約30秒後の5時13分8秒辺であることから、コンテナの起動後のentrypointを叩いて実際サービスを開始するまで時間がかかることがわかった。今回のケース（数）では30秒ぐらいかかったが状況によって変更はありそう
４。レスポンスタイムが安定した5時13分8秒以降には新しく起動されるコンテナの数が大きく減っていることから5時13分8秒には今回のトラフィックに対応できる準備ができてると言える。開始から約37秒経過
テストケース２
テストケース１ではconcurrency=1でやった結果です。Cloud Runの最大concurrencyの80した場合にはケース１より早く安定されるかを確認して見ました。
concurrnecyを変更するために再Deployをします。
$ gcloud beta run deploy --image gcr.io/[[ Project ID]]/helloworld --set-env-vars="JAVA_TOOL_OPTIONS=-XX:MaxRAM=256m" --concurrency=80
…….
Deploying container to Cloud Run service [helloworld] in project [minsoojunprj] region [asia-northeast1]
✓ Deploying... Done.
✓ Creating Revision...
✓ Routing traffic...
Done.
Service [helloworld] revision [helloworld-00024-fav] has been deployed新しくDeployしたバージョンがサービスを受けるように変更した後locustで前回と同じ設定でテストを開始します。
同時接続数: 500
1秒間に増加させる接続数: 30
テストするURL: helloworldの公開URL
concurrency=1と比較すると山ができるポイントが変わってきているように見えます。
Total Requests per Secondで concurrency=1では105が出ましたが、concurrency=80では120ぐらいになってます。
同然のことですが、concurrency=1の場合は開始直後からResponse Times(ms)が遅くなったですが、concurrency=80にしたことで１コンテナで対応できるRequestが増えたことで比較的に安定的動いているように見えます。
ただ、Response Times(ms)に11時50分13秒から11時50分40秒に出来ているスパイクしたのは起動しているコンテナが足りなくなったので新しいコンテナを起動したことでしょう。
Stackdriver Loggingから取得した開始ログの結果は下記の通りです。
コンテナの起動ログを見ると11時49分12秒から11時49分35秒間には起動されなかったことがわかります。多分、その影響で大きくTotal Request per Secondの数字が落ちたと思われるし、Response Timesにも影響がでたと思います。
このような結果が出たのは、たまたまリソースの確保が出来ないので発生したことか、またはこのようなRequestパタンで起きることかを確認知るために同じテストをもう一度実施して見ました。
* warm-upされたコンテナが残っているかも知らないので、新しくDeployをしてテスト
山の数とか高さの差はありますが、ほぼ同じパターンになりました。このようなスパイクを減らすためには動かすアプリケーションに合わせて、メモリサイズとconcurrencyを最適化する必要があると思います。最適化についてはここを参考してください。
まとめ
上記の３つのテストでわかったのは同時接続500のワークロードでかつ、コールドスタートの場合には最初のResponseを返すまでは2〜5秒かかるし、レスポンスタイムが安定するまでは約30秒ぐらいかかる。
