CIの実行時間が伸びたり、タイムアウトでジョブが失敗したりすると、タイムアウト延長やresource_classのスケールアップで対処したくなります。ただしそれだけでは、テストやアプリケーション側の本当のボトルネックを見落とすことがあります。

今回は、デモ用にAIコーディングしていたアプリで実際に起きたCI遅延を例に、CircleCI CLI（同等のデータはCircleCI MCPでも取得可能）で実測し、仮説を検証しながら修正した手順を紹介します。

本稿のコマンドはCircleCI CLIを前提とします。事前にcircleci auth login、または環境変数CIRCLE_TOKENの設定が必要です。ジョブUUIDはジョブ詳細ページからコピーできます。

テストジョブが CPU 100%に張り付き、遅延し始める

アプリをAIコーディングしていたところ、CIの実行時間が伸び始めていることに気づきました。CircleCIのCPU利用状況を確認すると、ほとんどの時間でCPU Usageが100%に張り付いていました。

見た目だけだと、「Docker small」のようなコスト優先のリソースクラスでvCPUが足りず、アプリ成長に伴いCPUを使い切っている、という説明が自然に見えます。

CircleCI CLIでデータを取得する

より詳細に分析するため、CircleCI CLIでリソース使用状況を取得しました。同じ系統のデータはCircleCI MCP（CLI連携版）からも取得できます。

circleci job resource-usage get 7c19e993-b6eb-458d-8799-8eec4ee50e7a --json

引数のIDはジョブUUIDです。ジョブ詳細ページからコピーできます。

--jsonを付けると、次のようなJSONが得られます。

{
  "id": "7c19e993-b6eb-458d-8799-8eec4ee50e7a",
  "resource_class": {
    "name": "small",
    "cpu_count": 1,
    "memory_limit_bytes": 2147483648
  },
  "executions": [
    {
      "cpu": {
        "max": 1.0006455333333333,
        "peak_percent_of_limit": 100.06455333333332
      },
      "memory": {
        "max": 1802809344,
        "peak_percent_of_limit": 83.9498519897461
      },
      "duration_seconds": 540
    }
  ]
}

CPU使用率のピークは100.06%、メモリ使用率のピークは約84%です。メモリには余裕がある一方、CPUは上限付近まで使い切っており、負荷がCPU側に偏っています。duration_seconds: 540はジョブ全体の長さで、このあとのテストステップ単体の約378秒とは別の指標です。

続いてテストステップのログも確認します。ステップ番号はcircleci job getの結果から分かり、このジョブではTestステップが110でした。

circleci job output get 7c19e993-b6eb-458d-8799-8eec4ee50e7a --step-num 110

ログを見ると、pnpm run test（約378秒）の内側で動く3コマンドの実行時間に大きな差がありました。

PASS cdk test/vibes-wp-content-enrichment.test.ts (356.188 s)
...
   Duration  4.30s (import 54%, transform 27%, tests 15%, worker 3%)
...
   Duration  12.98s (import 40%, tests 39%, transform 14%, worker 6%)

コマンド別にまとめると、次のとおりです。

コマンド	テストランナー	実行時間
`test:cdk`	Jest（CDK synthを含む）	356.19秒
`test:lambda`	Vitest	4.30秒
`test:unit`	Vitest	12.98秒

monorepoのため、テストはランナーを分けて実行しています。内訳を見ると、壁時計時間の大半はAWS CDK向けのJestテストに集中しています。

Jestの設定を確認し、テストコードを調べる

ジョブはresource_class: small（1 vCPU）なので、まずJestが割当以上のワーカーを立ててCPU競合している可能性を疑いました。別リポジトリでVitestがワーカーを過剰に割り当てていた事例もあり、今回も同様ではないかと考えて調査しました。

しかしjest.config.jsではmaxWorkers: 2が既に固定されていました。加えてtest:cdkが実行するテストファイルは1つだけなので、Jestは実質1ワーカーしか使っておらず、この仮説には当たりませんでした。

そこでテストコード自体を見ました。対象ファイルには54個のtest()があり、各テスト直前のbeforeEachが1つ定義されています。その中ではCDKスタックのビルドを定義しています。スタックにはNodejsFunction Constructが含まれ、ビルド時にLambda関数のコードをesbuildでバンドルする処理も走ります。templateの内容を検証するだけのテストでも、beforeEachのたびにこのビルドが繰り返されていました。

`beforeEach`を`beforeAll`に変え、効果を実測する

各test()はapp/stackを変更せず、ビルド済みtemplateを読むだけだと確認できました。一度スタックをビルドすれば足りる設計なので、beforeEachをbeforeAllへ変更します。

- beforeEach(() => {
+ beforeAll(() => {
    app = new cdk.App();
    stack = new VibesWpContentEnrichmentStack(app, 'TestStack');
    template = Template.fromStack(stack);
  });

beforeEachは各test()の直前に呼ばれ、beforeAllはそのブロック内で最初の1回だけ呼ばれます。スタックを変更しないテストなら、置き換えても判定結果は変わりません。

変更後のCIで、同じCLIコマンドを使って再計測しました。

circleci job resource-usage get ad224a03-906c-4247-8aa7-ee292d46ff9a --json
circleci job output get ad224a03-906c-4247-8aa7-ee292d46ff9a --step-num 110

pnpm run testステップは約378秒から約37秒に短縮され、内訳は次のとおりでした。

PASS cdk test/vibes-wp-content-enrichment.test.ts (14.715 s)
...
   Duration  4.61s (import 56%, transform 27%, tests 14%, worker 4%)
...
   Duration  13.54s (import 41%, tests 39%, transform 15%, worker 5%)

コマンド	修正前	修正後
`test:cdk`	356.19秒	14.72秒
`test:lambda`	4.30秒	4.61秒
`test:unit`	12.98秒	13.54秒

ボトルネックだったtest:cdkが大きく短縮されました。

まとめ

CIが長く、CPU使用率が100%に張り付いていると、ランナーのスペック（resource_classなど）不足を疑いたくなります。今回の主因はそこではなく、beforeEachでのCDK synth（と付随するesbuildバンドル）が54回繰り返されていたことでした。AIコーディングでは、要件の抜けや認識のずれから、こうしたテスト設計が入り込むこともあります。

ジョブのリソース使用状況とステップログをCircleCI CLI（または同等のMCP）で確認すれば、思い込みをデータで反証しやすくなります。同じ手順で、スケールアップの前に実測から原因を絞り込めます。

関連リンク