ECS Service Connectのデプロイ時のオーバーヘッドを確認する

昨日ECSのService Connectで遊んだ。

bufferings.hatenablog.com

Service Connectのデプロイが遅い？

書いたあとに「でも、NLBつないでないのに、デプロイとドレイニングにあんなに時間がかかるものなのかなぁ？」ってちょっと感じつつ。「まぁそんなものなのかなぁ」ってぼーっと今朝ECSまわりの記事を読んでたら、Service Connectのデプロイが遅いってIssueを見つけた。

github.com

「あぁ、確かに、昨日はService Connectを入れた状態でしか確認してなかったな。素のデプロイだとどれくらいかかるんだろう？」って気になった。

そりゃそうか

よく考えると、デプロイ時には

  • サイドカーのEnvoyイメージのダウンロードが発生する
  • CloudMapへの登録がある

ドレイニング時には

  • CloudMapからの登録解除がある
  • Envoyの終了処理が入る

だろうから、オーバーヘッドあるよな。見てみるかー。

デプロイにかかる時間を簡単に比べてみた

ってことでService Connectをオンにしたコンテナとオフにしたコンテナでデプロイにかかる時間を簡単に比べてみた。素のnginxのイメージを使って2インスタンス更新しただけ。

Service Connectをオンにしたデプロイ

❯ \time ecspresso deploy
...
      279.93 real         0.19 user         0.09 sys

オフの場合

❯ \time ecspresso deploy
...
      141.84 real         0.11 user         0.06 sys

何度か再デプロイしてみたけどだいたい同じ感じだった。NLBに対する登録・登録解除よりは短いけど、わりとオーバーヘッドある。

もうちょっと中を細かく見てみる

オンの場合

  • 起動→処理開始：15s
  • 処理開始→起動完了：80s
  • 起動完了→タスク停止：30s
  • タスク停止→完了：155s
  • トータル：280s

オフの場合

  • 起動→処理開始：14s
  • 処理開始→起動完了：30s
  • 起動完了→タスク停止：20s
  • タスク停止→完了：78s
  • トータル：142s

起動・停止・後処理それぞれにプラスで時間がかかってる。なるほど。

比べるべきだったのは

あー。じゃあ昨日の比較はこうだったけど

  • NLB + サービスコネクト利用あり
  • サービスコネクト利用あり

比べるべきだったのは

  • NLB + サービスコネクト利用なし
  • サービスコネクト利用あり

だったな。実際はNLB→SCへの切り替えをしても、そこまで速くならないのかもしれない。また今度見てみるか。

実際のログにメモを足したもの

オンの場合

❯ \time ecspresso deploy
2023/12/17 11:03:30 nginx-sc/my-ecs-cluster Starting deploy
Service: nginx-sc
Cluster: my-ecs-cluster
TaskDefinition: nginx-sc:1
Deployments:
   PRIMARY nginx-sc:1 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/6306085897779852016 completed.)
Events:
2023/12/17 11:03:31 nginx-sc/my-ecs-cluster Registering a new task definition...
2023/12/17 11:03:31 nginx-sc/my-ecs-cluster Task definition is registered nginx-sc:2
2023/12/17 11:03:31 nginx-sc/my-ecs-cluster service attributes will not change
2023/12/17 11:03:31 nginx-sc/my-ecs-cluster desired count: 2
2023/12/17 11:03:31 nginx-sc/my-ecs-cluster Updating service tasks...
2023/12/17 11:03:35 nginx-sc/my-ecs-cluster Waiting for service stable...(it will take a few minutes)
2023/12/17 11:03:45 nginx-sc/my-ecs-cluster  PRIMARY nginx-sc:2 desired:0 pending:0 running:0 IN_PROGRESS(ECS deployment ecs-svc/1349721650793842263 in progress.)
2023/12/17 11:03:45 nginx-sc/my-ecs-cluster   ACTIVE nginx-sc:1 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/6306085897779852016 completed.)
// 起動→処理開始：15s

2023/12/17 11:03:48 (service nginx-sc) has started 2 tasks: (task 72cd09fed0704feda92dbe7d21b5fff0) (task d42c6481305943eaaef3646c44efc307).
2023/12/17 11:03:55 nginx-sc/my-ecs-cluster  PRIMARY nginx-sc:2 desired:2 pending:2 running:0 IN_PROGRESS(ECS deployment ecs-svc/1349721650793842263 in progress.)
2023/12/17 11:03:55 nginx-sc/my-ecs-cluster   ACTIVE nginx-sc:1 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/6306085897779852016 completed.)
2023/12/17 11:05:05 nginx-sc/my-ecs-cluster  PRIMARY nginx-sc:2 desired:2 pending:1 running:1 IN_PROGRESS(ECS deployment ecs-svc/1349721650793842263 in progress.)
2023/12/17 11:05:05 nginx-sc/my-ecs-cluster   ACTIVE nginx-sc:1 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/6306085897779852016 completed.)
// 処理開始→起動完了：80s

2023/12/17 11:05:10 (service nginx-sc) has stopped 2 running tasks: (task 8127544057054efd917f65bcbab70d25) (task 9bf1b9a6766d417aa24b3fb4a14fac71).
2023/12/17 11:05:15 nginx-sc/my-ecs-cluster  PRIMARY nginx-sc:2 desired:2 pending:0 running:2 IN_PROGRESS(ECS deployment ecs-svc/1349721650793842263 in progress.)
2023/12/17 11:05:15 nginx-sc/my-ecs-cluster   ACTIVE nginx-sc:1 desired:0 pending:0 running:0 COMPLETED(ECS deployment ecs-svc/6306085897779852016 completed.)
2023/12/17 11:05:35 nginx-sc/my-ecs-cluster  PRIMARY nginx-sc:2 desired:2 pending:0 running:2 IN_PROGRESS(ECS deployment ecs-svc/1349721650793842263 in progress.)
2023/12/17 11:05:35 nginx-sc/my-ecs-cluster DRAINING nginx-sc:1 desired:0 pending:0 running:0 COMPLETED(ECS deployment ecs-svc/6306085897779852016 completed.)
// 起動完了→タスク停止：30s

2023/12/17 11:07:15 nginx-sc/my-ecs-cluster  PRIMARY nginx-sc:2 desired:2 pending:0 running:2 IN_PROGRESS(ECS deployment ecs-svc/1349721650793842263 in progress.)
2023/12/17 11:07:45 nginx-sc/my-ecs-cluster  PRIMARY nginx-sc:2 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/1349721650793842263 completed.)
2023/12/17 11:07:44 (service nginx-sc) (deployment ecs-svc/1349721650793842263) deployment completed.
2023/12/17 11:07:44 (service nginx-sc) has reached a steady state.
2023/12/17 11:08:10 nginx-sc/my-ecs-cluster Service is stable now. Completed!
// タスク停止→完了：155s

      279.93 real         0.19 user         0.09 sys

オフの場合

❯ \time ecspresso deploy
2023/12/17 11:02:56 nginx-nosc/my-ecs-cluster Starting deploy
Service: nginx-nosc
Cluster: my-ecs-cluster
TaskDefinition: nginx-nosc:3
Deployments:
   PRIMARY nginx-nosc:3 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/5169026132523763568 completed.)
Events:
2023/12/17 11:02:57 nginx-nosc/my-ecs-cluster Registering a new task definition...
2023/12/17 11:02:57 nginx-nosc/my-ecs-cluster Task definition is registered nginx-nosc:4
2023/12/17 11:02:57 nginx-nosc/my-ecs-cluster service attributes will not change
2023/12/17 11:02:57 nginx-nosc/my-ecs-cluster desired count: 2
2023/12/17 11:02:57 nginx-nosc/my-ecs-cluster Updating service tasks...
2023/12/17 11:03:00 nginx-nosc/my-ecs-cluster Waiting for service stable...(it will take a few minutes)
2023/12/17 11:03:10 nginx-nosc/my-ecs-cluster  PRIMARY nginx-nosc:4 desired:0 pending:0 running:0 IN_PROGRESS(ECS deployment ecs-svc/9715195868222377346 in progress.)
2023/12/17 11:03:10 nginx-nosc/my-ecs-cluster   ACTIVE nginx-nosc:3 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/5169026132523763568 completed.)
// 起動→処理開始：14s

2023/12/17 11:03:15 (service nginx-nosc) has started 2 tasks: (task 6330ce5ed50943ef878bf80b5da72d2a) (task 9e112e3bd7f84f6fb6b51144aef2b722).
2023/12/17 11:03:20 nginx-nosc/my-ecs-cluster  PRIMARY nginx-nosc:4 desired:2 pending:2 running:0 IN_PROGRESS(ECS deployment ecs-svc/9715195868222377346 in progress.)
2023/12/17 11:03:20 nginx-nosc/my-ecs-cluster   ACTIVE nginx-nosc:3 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/5169026132523763568 completed.)
2023/12/17 11:03:40 nginx-nosc/my-ecs-cluster  PRIMARY nginx-nosc:4 desired:2 pending:0 running:2 IN_PROGRESS(ECS deployment ecs-svc/9715195868222377346 in progress.)
2023/12/17 11:03:40 nginx-nosc/my-ecs-cluster   ACTIVE nginx-nosc:3 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/5169026132523763568 completed.)
// 処理開始→起動完了：30s

2023/12/17 11:03:44 (service nginx-nosc) has stopped 2 running tasks: (task 032890526f1843428a720b8eb75a512b) (task c389dd8690cc4bd0878f4483c58e4494).
2023/12/17 11:03:50 nginx-nosc/my-ecs-cluster  PRIMARY nginx-nosc:4 desired:2 pending:0 running:2 IN_PROGRESS(ECS deployment ecs-svc/9715195868222377346 in progress.)
2023/12/17 11:03:50 nginx-nosc/my-ecs-cluster   ACTIVE nginx-nosc:3 desired:0 pending:0 running:0 COMPLETED(ECS deployment ecs-svc/5169026132523763568 completed.)
2023/12/17 11:04:00 nginx-nosc/my-ecs-cluster  PRIMARY nginx-nosc:4 desired:2 pending:0 running:2 IN_PROGRESS(ECS deployment ecs-svc/9715195868222377346 in progress.)
2023/12/17 11:04:00 nginx-nosc/my-ecs-cluster DRAINING nginx-nosc:3 desired:0 pending:0 running:0 COMPLETED(ECS deployment ecs-svc/5169026132523763568 completed.)
// 起動完了→タスク停止：20s

2023/12/17 11:04:40 nginx-nosc/my-ecs-cluster  PRIMARY nginx-nosc:4 desired:2 pending:0 running:2 IN_PROGRESS(ECS deployment ecs-svc/9715195868222377346 in progress.)
2023/12/17 11:05:07 (service nginx-nosc) (deployment ecs-svc/9715195868222377346) deployment completed.
2023/12/17 11:05:07 (service nginx-nosc) has reached a steady state.
2023/12/17 11:05:11 nginx-nosc/my-ecs-cluster  PRIMARY nginx-nosc:4 desired:2 pending:0 running:2 COMPLETED(ECS deployment ecs-svc/9715195868222377346 completed.)
2023/12/17 11:05:18 nginx-nosc/my-ecs-cluster Service is stable now. Completed!
// タスク停止→完了：78s

      141.84 real         0.11 user         0.06 sys

オンの場合のログを見て DRAINING nginx-sc:1 desired:0 pending:0 running:0 COMPLETED でタスク数が0になってると思うんだけど、だとしたらその前にCloudMapからは登録解除されてるよね。そうじゃないとリクエストが来てしまうし。じゃあ、そのあとの終了処理って何をやってるんだろう？155秒かけて。

オフの場合だと78sで終わってるからその違いは何なんだろうなぁ。って、オフの場合も78sかけて何をやってるんだろう？

という疑問は残るけど、楽しかった。