Cloud Run（フルマネージド）でリクエスト外に処理をすると200倍遅くなる

はじめに

Cloud Runはサーバーレスなコンテナ実行基盤です。この記事ではフルマネージド版のCloud Runのみを対象とし、フルマネージド版のCloud Runを指して、単にCloud Runと表記します。

Cloud Runの料金プランの特徴として、リクエストの実行中のみ課金対象になるという点が挙げられます。しかし、リクエストのたびにコンテナの起動と終了を繰り返すわけではなく、起動したコンテナはある程度使い回されます。リクエストが無い間は、コンテナが起動していても課金されないというわけです。

f:id:mi_kattun:20200517165916p:plain — 課金対象の時間 (https://cloud.google.com/run/pricing?hl=ja より引用)

だからと言って無料で使い放題というわけではなく、コンテナランタイムの契約として、リクエスト中しかCPUが使えないと明記されています

You should only expect to be able to do computation within the scope of a request: a container instance does not have any CPU available if it is not processing a request.

https://cloud.google.com/run/docs/reference/container-contract?hl=ja より引用

ですが、実際にデプロイしたアプリケーションの挙動を見る限り、まったくCPUが使えないわけではなく、リクエスト外でも処理は動いています。例えばコネクションプールライブラリのHikariCPを使っていると、30秒に1回コネクションプールがメンテナンスされ、必要に応じて再接続するログが出力されます。

あるCloud Runアプリケーションで、レスポンスを返した直後に追加で処理を行っていました。リクエスト中に処理した方が良いことは知っていましたが、動いてるならまあいいかと放置していたら、運用中にエラーが発生してしまいました。そこで、Cloud Runでリクエスト外に処理を行った場合の挙動を改めて実験してみました。実験結果は2020-05-17時点のもので、今後変わる可能性があることに留意してください。

実験方法

リクエストを受けるたびに、同じ処理を以下のタイミングで3回行うアプリケーションを作成し、それぞれの実行時間を計測しました。

(A) リクエスト中（レスポンスを返す前）
(B) レスポンスを返した直後
(C) Bの完了後、1秒経過してから

以下の3種類のワークロードで実験しました。

乱数生成
Cloud Tasksのタスク作成
Cloud SQLへのINSERT

実験用のコードを抜粋するとこんな感じになります。KotlinとKtorで書きました。詳しくはリポジトリを参照してください。

    routing {
        post("/calc") {
            calc() // (A) リクエスト中
            call.respondText("OK", status = HttpStatusCode.Created)
        }
    }

    intercept(ApplicationCallPipeline.Call) {
        proceed()
        if (call.request.httpMethod == HttpMethod.Post) {
            when (call.request.uri) {
                "/calc" -> {
                    calc() // (B) レスポンスを返した直後
                    delay(1000)
                    calc() // (C) Bの完了後、1秒経過してから
                }
            }
        }
    }

実験結果

初回はキャッシュなどの影響で (A) リクエスト中の実行時間が相対的に長くなるので無視して、5回計測した結果を掲載します。実行時間の単位はmsです。

1. 乱数生成

ランダムなUUID v4を10万個生成するのにかかる時間を計測しました。アプリケーションは -Djava.security.egd=file:/dev/./urandom をつけて実行しています。

試行	(A) リクエスト内の実行時間	(B) リクエスト直後の実行時間	(C) リクエスト外の実行時間	何倍遅いか (C/A)
1回目	123	5379	33600	273.2
2回目	124	5431	36899	297.6
3回目	128	8431	30907	241.5
4回目	123	4804	35000	284.6
5回目	124	5246	35699	287.9

2. Cloud Tasksのタスク作成

Cloud Tasksのタスクを作成するのにかかる時間を計測しました。

試行	(A) リクエスト内の実行時間	(B) リクエスト直後の実行時間	(C) リクエスト外の実行時間	何倍遅いか (C/A)
1回目	250	4014	9801	39.2
2回目	175	2378	27700※	158.3
3回目	313	2072	10300	32.9
4回目	222	1913	13001	58.6
5回目	239	3510	11899	49.8

※ DEADLINE_EXCEEDED: deadline exceeded after 19.700177855s. と例外が発生したので、例外が発生するまでの時間を実行時間としました。

3. Cloud SQLへのINSERT

Cloud SQLのテーブルにINSERTするSQLを実行するのにかかる時間を計測しました。

試行	(A) リクエスト内の実行時間	(B) リクエスト直後の実行時間	(C) リクエスト外の実行時間	何倍遅いか (C/A)
1回目	12	9	2610	217.5
2回目	11	9	1900	172.7
3回目	9	8	1500	166.7
4回目	10	11	2400	240.0
5回目	13	9	1492	114.8

考察

ワークロードによって異なりますが、(C) リクエスト外の実行時間は、(A) リクエスト内の実行時間に比べて30倍〜300倍程度遅くなることがわかりました。やはりCPUの実行が制限されているようです。

(B) リクエスト直後の実行時間が (C) より短くなるのは、アプリケーションがレスポンスを返した直後はまだリクエスト内だとみなされる時間が少しだけあり、その間に処理が進むためだと考えられます。

なお、リクエスト外に処理を行っていても、そのタイミングでちょうどアプリケーションにリクエストが来ると、リクエスト内とみなされて、CPU割り当てが元に戻って処理が進むようになります*1。このため、アプリケーションへのリクエストが多いときには、リクエスト外で処理をしていても問題が顕在化しないことがあります。

まとめ

実験から、Cloud Runでリクエスト外に処理を行うと、30倍〜300倍程度遅くなることがわかりました。コンテナランタイムの契約にある通り、Cloud Runで実行するアプリケーションは、リクエストの外で処理を行うことがないようにしましょう。

*1:実験では毎回 (C) の処理が完了してから次のリクエストを送信しました。

orangain flavor

じっくりコトコト煮込んだみかん2。知らないことを知りたい。