デプロイにかかる時間をトレースとして可視化する

この記事はMackerel Advent Calendar 2024の15日目の記事です。14日目は@sogahisashiさんでOpenTelemetry デモアプリケーションを使って Mackerel のメトリックエクスプローラーを体験でした。16日目は@inommmさんです。

デプロイは速ければ速いほどいい。だがアプリケーションの成長などによって遅くなっていくものだ。デプロイが遅くなったときに、アプリケーションが順調に成長しているのか、それとも設定がおかしくて余計に時間がかかっているのかなど、どこに時間がかかっているのかがわかっているのがよいだろう。

デプロイと一言に言っても様々な工程がある。どの工程で時間がかかっているのかを一連の流れ、つまりトレースとして見れると便利だ。そんなときに活躍するのが分散トレーシングサービスのVaxilaだ。

mackerel.io

本記事ではVaxilaでデプロイにかかる時間をトレースとして可視化する。前提として、デプロイはECSに対してCodeDeployを利用したBlue/GreenデプロイをGitHub Actions上でecspressoから行っている。

GitHub Actionsのワークフローを可視化する

corentinmusard/otel-cicd-action というActionを使うことで簡単にワークフローを可視化することができる。このActionは inception-health/otel-export-trace-action というActionのforkで otlpEndpointにhttpsを指定することができる。fork元ではgrpcしか対応していないので注意が必要。Vaxilaのエンドポイントはhttpsなのでotel-cicd-actionを使うことになる。

以下のような設定をワークフローの最後に設定すればよい。サンプルではworkflow_runイベントで発火するようになっているが、otelServiceName を動的に変更したいのでrepository_dispatchイベントで発火させるようにした。

otlpEndpoint には https://otlp-vaxila.mackerelio.com ではなく https://otlp-vaxila.mackerelio.com/v1/traces というように /v1/traces を明示することが重要になる。これを明示していないと動かないので注意。

# outputsを後で参照したいのでidを付けている
- id: export-trace
  uses: corentinmusard/otel-cicd-action@v1
  with:
    # 例) deploy-hoge-production
      otelServiceName: ${{ github.event.client_payload.otelServiceName }}
      otlpEndpoint: https://otlp-vaxila.mackerelio.com/v1/traces
      otlpHeaders: Accept=*/*,Mackerel-Api-Key=${{ secrets.MACKEREL_APIKEY }}
      githubToken: ${{ secrets.GITHUB_TOKEN }}
      # ${{ github.run_id }}を渡している
      runId: ${{ github.event.client_payload.run_id }}

設定がうまく行っていればVaxilaでワークフローの可視化ができている。このデプロイワークフローは4つのJobが動いているが、同じトレースに含まれている。

ここまででワークフローの可視化ができたがデプロイ完了を待っている時間が支配的と、当然とも思える結果が得られた。これでは面白みにかけるのでこのトレースにCodeDeployのLifecycle Eventsも含めてみよう。

CodeDeployのLifecycle Eventsをトレースに含める

OpenTelemetryではトレースIDや親のスパンIDを含むコンテキストを伝搬させることで、スパンが生成された場所に関係なくトレースを組み立てることができる。

コンテキスト伝搬のデフォルトはW3C TraceContextの仕様で指定されたヘッダを利用する。今回は単にスクリプトを実行したいのでヘッダだと少し面倒。なので環境変数を利用してコンテキスト伝搬を行う。

func ExtractContext(ctx context.Context) context.Context {
    prop := propagation.NewCompositeTextMapPropagator(
        propagation.TraceContext{},
        propagation.Baggage{},
    )
    carrier := propagation.MapCarrier{
        "traceparent": os.Getenv("TRACEPARENT"),
        "tracestate":  "",
    }
    return prop.Extract(ctx, carrier)
}

環境変数 TRACEPARENT は export TRACEPARENT="00-${{ steps.export-trace.outputs.traceId }}-1111111111111111-01" と設定した。トレースIDにはotel-ci-cdが出力するtraceIdを利用することでワークフローのトレースにスパンを追加する準備をしている。親のスパンIDは使えない(例えばecspresso-deployというスパンを親にしようとしても、そのスパンの情報を知ることができないため)ので適当に設定している。

ここまでで同じトレースにスパンを送信する準備ができたので、CodeDeployのLifecycle Eventsを取得してスパンを作成する。

今回はLifecycle Event通りのスパン、つまり開始時刻と終了時刻がわかっているスパンを作ることになる。スパンを作成する際のオプションで開始/終了時刻を設定することが可能だ。

func GenerateSpanFromLifecycleEvent(ctx context.Context, event types.LifecycleEvent) {
    spanCtx, createdSpan := otel.Tracer("").
        Start(ctx, *event.LifecycleEventName, trace.WithTimestamp(*event.StartTime))
    createdSpan.End(trace.WithTimestamp(*event.EndTime))
}

以上をつなぎこむとCodeDeployのLifecycle Eventsをトレースに含めることができた。

トレースを眺めるとecspressoのwaitが完了する時間とCodeDeployの完了する時間の間に不審な空白があることがわかった。原因はまだ不明。exponential backoffか？と思ったが、ecspresso側で常に15秒のリトライになっているので50秒ほど待ち時間が発生しているのは何かおかしそう。ちなみに termination_wait_time_in_minutes は0になっている。

終わりに

デプロイにかかる時間をトレースで可視化することで不審な空白を発見することができた。各工程にかかる時間はこれまでも見ようと思えば見れたが、やはりトレースになることで一連の流れが明らかとなり、見やすくなった効果はあると感じた。