【Unit4 ブログリレー10日目】エムスリーエンジニアリンググループの松山です。Unit4(m3.com開発チーム)のチームSREをしています。最近突然aikoにハマり、300曲弱を再履修 しています。

この記事では、あるサービスでのパフォーマンス低下の原因をAWS Application Signalsによるトレースなどを用いて解決した話を書きます。

今回題材となるメンバーズメディアというサービスは、医師向けの記事執筆サービスです。医師をはじめとする様々な分野の専門家が、医師向けの記事を執筆しています。当サービスはバックエンドがKotlinで書かれており、ECSでホスティングされています。

うちの猫(推定もうすぐ5歳)。世界一かわいい生き物ですが、記事内容とは関係ありません

ある時期、このサービスで不定期にパフォーマンス関連のアラートが発生するようになりました。具体的にはレスポンスタイムの低下や5XX系のレスポンスの発生です。

一通りの調査として、次のような確認も行いました

DB/クエリ起因ではない (performance insightなどによる)
アプリケーションエラーではない (Sentryなどによる)
リクエストの集中によるダウンではない (ALBのモニタリングによる)
コンテナでOOMが起きているわけではない (ECSに設定したPrometheusによる)
同様にメモリリークが発生しているわけではない (ヒープダンプの解析による)
直近の機能追加に伴うものではない

一方で当サービスではインメモリキャッシュを利用しており、挙動を踏まえるとかなり怪しい箇所です。コードを確認しつつ、さらなる証拠集めを行いたいと思いました。

traceの追加

当時本サービスのバックエンドには、各種ログの出力やSentryによるエラー検知は実装されていましたが、トレーシング機能までは実装されていませんでした。いくつかの理由から、Application Siganlsを導入してX-Ray トレースを取得するようにしました。Application SignalsはOpenTelemetryの自動計装を利用してX-Rayトレースや各種メトリクスを収集できます。利点としては

コード変更の必要がないためすぐに実装できる
AWSで完結する (cloudwatchからアラート設定もできる)

などから実装および運用の手間が少ないことが挙げられます。

当チームのインフラはすべてTerraformによるIaC化されています。 Application Signalsの設定にあたっては、次のようなインフラ変更が必要です。(ここではサイドカーを用いた設定方法を採用しています)

ECSのタスクロールへのポリシー追加

resource "aws_iam_role_policy_attachment" "ecs_task_role_cw_agent" {
　role       = aws_iam_role.task_role.name
　policy_arn = "arn:aws:iam::aws:policy/CloudWatchAgentServerPolicy"　
}

タスク定義へのvolume追加

resource "aws_ecs_task_definition" "app" {
  ...
  volume {
    name = "opentelemetry-auto-instrumentation"
  }
}

追加したvolumeのアプリケーションコンテナからのマウント

resource "aws_ecs_task_definition" "app" {
    ...
    container_definitions = jsonencode([
        local.app_container_definition,
        ...
        local.cw_agent_container_definition,
        local.cw_ecs_agent_init_definition,
    ])
    ...
}

locals {
    app_container_definition = {
    ...
        mountPoints = [
            {
                sourceVolume  = "opentelemetry-auto-instrumentation",
                containerPath = "/otel-auto-instrumentation",
                readOnly      = false,
            }
        ]
    }
}

javaagentを設定するためのinitコンテナの追加

locals {
    ...
    cw_ecs_agent_init_container_definition = {
      name      = "init"
      image     = "public.ecr.aws/aws-observability/adot-autoinstrumentation-java:v1.33.0"
      essential = false
      command = [
        "cp",
        "/javaagent.jar",
        "otel-auto-instrumentation/javaagent.jar"
      ]
      mountPoints = [
        {
          sourceVolume  = "opentelemetry-auto-instrumentation",
          containerPath = "/otel-auto-instrumentation",
          readOnly      = false,
        }
      ]
    }
}

アプリケーションコンテナへの環境変数追加 (環境変数の一覧)

収集したメトリクスをもとにSLI/SLOの設定やエラーバジェットのアラートも実装できるのですが、今回は割愛します

原因の特定と修正

設定したトレースを見てみましょう。次の画像は、発見した異常なリクエストの一例です

DBへのリクエストの合間に、長い待機時間を取らされていることがわかります。そこでECS Execを使ってスレッドダンプを取って確認することにしました。

(ECS Execについては便利ですが、セキュリティ面のリスク及び、そもそもそんな強い権限持ちたくない　という理由で原則offとしておき、調査時のみonにしたうえで実施内容の証跡を残す、という運用にしています)

スレッドダンプを読むと、プロセスの半分ほどがConcurrentHashMapのPutをするためのlockを待っているようだ、ということがわかりました。

#47 "http-nio-8080-exec-4"
      java.base/java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1031)
      java.base/java.util.concurrent.ConcurrentHashMap.putIfAbsent(ConcurrentHashMap.java:1541)
      com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:2312)
      com.github.benmanes.caffeine.cache.BoundedLocalCache.put(BoundedLocalCache.java:2278)
      com.github.benmanes.caffeine.cache.LocalManualCache.put(LocalManualCache.java:126)
      org.springframework.cache.caffeine.CaffeineCache.put(CaffeineCache.java:172)

ここまでくれば充分です。ソースコードをさらに読んでいくと、次のことがわかりました

キャッシュ単位が大きかった　例えばarticleというキャッシュに対して、記事に関する多数のメソッドから読み書きが存在していました
1リクエストで多重に同じキャッシュへの読み書きをする実装があった　ServiceAのメソッドa から ServiceBのメソッドb という呼び出しがあるとして、a、b 双方にキャッシュが設定されていました。よって1つのリクエストで複数回キャッシュが起こるようになっていました

これによりキャッシュの読み書きが多くなり、そこがボトルネックになっていました。開発当時のサービス状況であれば問題なかったものが、利用者の拡大や機能の拡張に伴って問題として顕在化するようになったというわけですね。

これらを修正して再度負荷試験を行ったところ、本番でも問題なくリクエストを処理できるという結論になりました。

上の画像は本番デプロイ前後でのECSのCPU利用率の推移です。パフォーマンス問題も解消されており、アラートが鳴ることはなくなりました。付随してECSのリソースを減らすことができインフラコスト削減にも繋がりました。

補足

Application Signalsは今回の状況にて多くの利点がありましたが、いくつかの制限もあります

対応している言語/フレームワーク

対応している言語/フレームワークの一覧はこちらにあります。徐々に増えていますが、当チームで採用例の多いGoは未対応です。なぜなら前提となる自動計装の開発が他言語と比べると難航しているためです。 ( 現在はβ版です )。 SREとしては、トレーシング基盤は統一されていることが運用上望ましく、したがって現在は全面的な利用はせず一部のサービスのみで様子見をしている段階です。
料金面

すべてのリクエストに対して通していると料金がかかります。そこでサンプリングレートを設定したり、次のようにcloudwatch agentコンテナの設定から取得するリクエストの対象を絞ることで対応しています

cw_agent_container_definition {
...
    logs = {
        metrics_collected = {
            application_signals = {
                rules = [
                    {
                        rule_name = "keep_rule_healthcheck",
                        selectors = [
                            {
                                dimension = "Operation",
                                match     = "GET /admin/healthcheck"
                            },
                        ]
                        action = "keep"
                    },
                    {
                        rule_name = "keep_rule_summary"
                        selectors = [
                            {
                                dimension = "Operation",
                                match     = "GET /"
                            }
                        ],
                        action = "keep"
                    },
                    ...

まとめ

本記事では、サービスのパフォーマンス低下の原因を探って改善するまでの話を書きました。

Unit4のチームSREでは、他にも様々なサービスのパフォーマンスを開発メンバーやビジネスチームと連携しながら改善を続けています。

We are Hiring!

エムスリーでは一緒にプロダクト開発をするエンジニアを絶賛募集中です。ご興味ある方は是非カジュアル面談等ご応募ください！

traceの追加

原因の特定と修正

補足

まとめ

We are Hiring!

エンジニア採用ページはこちら

エンジニア新卒採用サイト

カジュアル面談はこちら