OpenTelemetryで“初回だけ遅い”を解剖する：依存ロード・DB接続・外部APIをトレースで可視化する入門

はじめに

「起動はした。でも最初のアクセスが遅い。」
この“初回だけ遅い”は、開発でも本番でも地味に厄介です。ログには「処理開始」「処理終了」くらいしか残らず、結局は体感と推測で原因を当てにいくことになりがちです。

依存（モジュール）のロードに時間がかかっている？
テンプレートの初回コンパイルが重い？
DB接続が遅い（DNS/TLS/コネクションプール初期化）？
外部APIが遅い（ネットワーク・リトライ・タイムアウト）？
あるいは全部が少しずつ遅い？

これらが混ざると、最適化は“手当たり次第”になってしまいます。そこで登場するのが OpenTelemetry（OTel） です。
OTelを入れると、初回処理を「スパン（Span）」に分解して、どの処理に何ミリ秒かかったかを“1本のトレース”として可視化できます。さらに、HTTPだけでなく、DBや外部HTTP呼び出し、そしてアプリ内部の初期化処理も同じ時間軸で並べられます。

この記事の狙いは、APMの選定や運用論ではなく、もっと手前の 「初回処理をトレース化して、ボトルネックを言い当てられる状態を作る」 ことです。
言語は例としてPython（FastAPI）を使いますが、設計の考え方はNode/Go/Javaでもそのまま応用できます。

座学

1) 「初回処理」をトレースで捉えると何が変わるか

トレースは、ある1回の処理（たとえば1リクエスト）を「親スパン＋子スパンの木構造」で表現します。
ログは時系列の“点”ですが、トレースは処理の“構造”が見えます。

例：GET / のトレースがこう見えるとします。

HTTP GET /（親）
- template.render（子）
- db.connect（子）
- db.query SELECT ...（子）
- http.client GET https://...（子）

これが見えると、「遅い」の議論が “外部APIが1.2sで支配的” みたいに断言できるようになります。
さらに強いのは、初回だけ遅い処理（テンプレ初回コンパイル、依存ロード、コネクション確立など）を 手動スパンで押さえ込めることです。

2) 自動計測と手動計測の使い分け

OTelには大きく2つの入れ方があります。

自動計測（Instrumentation）
フレームワークやHTTPクライアント、DBクライアントに仕込まれた計測を有効化する。
例：FastAPIの受信HTTP、requestsの外部HTTP、DBドライバのクエリなど。
手動計測（Manual Span）
アプリ独自の処理にスパンを追加する。
例：設定ロード、テンプレ初回コンパイル、キャッシュ生成、DI初期化、マイグレーション、初回Warm-upなど。

初回処理を追う場合、自動だけだと粒度が足りないことがよくあります。
そこで「自動計測で“外枠”を作り、疑わしい初回処理だけ手動スパンで切る」という方針が一番速いです。

3) “起動時”と“初回リクエスト”は別物として計測する

初回遅延は大きく2種類に分かれます。

起動時に発生する初期化：import、設定ロード、DBプール初期化、キャッシュ読み込み
初回アクセス時に発生する初期化：テンプレ初回コンパイル、遅延ロードされたモジュール、最初の外部接続確立

ここを混ぜると原因が濁るので、次のようにスパンを設計します。

起動時：startup 配下に load_config / init_db / warmup_cache
初回リクエスト：HTTP GET / 配下に template.render / external_api_call / db.query

「どっちの初回が遅いのか」が分かると、改善の打ち手（起動時に前倒しするか、初回を軽くするか）が決まります。

4) Collectorを挟む意味（最初から挟んだ方が楽）

アプリからトレースの送り先を直接Jaegerやベンダー製品にすると、後から差し替えがしづらくなります。
Collectorを挟むと次がやりやすいです。

送信先変更（Jaeger→Tempo→商用APM）
環境タグ付け、PIIマスキング
サンプリング戦略（初回だけ残す、遅いものだけ残すなど）

最初から App → Collector（OTLP） → Backend にしておくと、アプリ側の設定が薄く保てます。

ハンズオン

ここでは「トレースがUIで見えて、初回の内訳が言える」までを一気に作ります。
構成は最小で、Collector＋Jaeger＋FastAPIです。

0) 事前準備

Docker（composeが使えること）
Python 3.10+（例）

1) Jaeger＋Collectorを立ち上げる

`docker-compose.yml`

services:
  jaeger:
    image: jaegertracing/all-in-one:1.57
    ports:
      - "16686:16686"  # UI
      - "14250:14250"  # gRPC ingest
    environment:
      - COLLECTOR_OTLP_ENABLED=true  otel-collector:
    image: otel/opentelemetry-collector-contrib:0.98.0
    command: ["--config=/etc/otelcol/config.yaml"]
    volumes:
      - ./otel-collector-config.yaml:/etc/otelcol/config.yaml:ro
    ports:
      - "4317:4317"  # OTLP gRPC
      - "4318:4318"  # OTLP HTTP
    depends_on:
      - jaeger

`otel-collector-config.yaml`

receivers:
  otlp:
    protocols:
      grpc:
      http:processors:
  batch:exporters:
  jaeger:
    endpoint: jaeger:14250
    tls:
      insecure: trueservice:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [batch]
      exporters: [jaeger]

起動：

docker compose up -d

Jaeger UI：http://localhost:16686

2) “初回処理が目立つ”アプリを作る（わざと遅くする）

初回可視化のデモでは、遅さが見える方が理解しやすいので、意図的に「起動時の初期化」「初回アクセスの重い処理」を用意します。
実際のアプリでは time.sleep の部分が、依存ロード・テンプレコンパイル・DB接続・外部APIの遅延に相当します。

`requirements.txt`

fastapi
uvicorn[standard]
requestsopentelemetry-api
opentelemetry-sdk
opentelemetry-exporter-otlp
opentelemetry-instrumentation-fastapi
opentelemetry-instrumentation-requests

`app.py`

import os
import time
import requests
from fastapi import FastAPIfrom opentelemetry import trace
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporterfrom opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.instrumentation.requests import RequestsInstrumentorSERVICE_NAME = os.getenv("OTEL_SERVICE_NAME", "otel-coldstart-demo")
DEPLOYMENT_ENV = os.getenv("DEPLOYMENT_ENV", "local")
OTLP_ENDPOINT = os.getenv("OTEL_EXPORTER_OTLP_ENDPOINT", "localhost:4317")def setup_tracing():
    resource = Resource.create({
        "service.name": SERVICE_NAME,
        "deployment.environment": DEPLOYMENT_ENV,
    })    provider = TracerProvider(resource=resource)
    exporter = OTLPSpanExporter(endpoint=OTLP_ENDPOINT, insecure=True)
    provider.add_span_processor(BatchSpanProcessor(exporter))
    trace.set_tracer_provider(provider)    # 外部HTTP（requests）を自動計測
    RequestsInstrumentor().instrument()setup_tracing()
tracer = trace.get_tracer(__name__)app = FastAPI()
FastAPIInstrumentor.instrument_app(app)# --- 起動時の初期化（＝依存ロード/設定ロード/DB初期化の代替） ---
def load_dependencies_like():
    time.sleep(0.25)def compile_templates_like():
    time.sleep(0.30)def init_db_pool_like():
    time.sleep(0.45)@app.on_event("startup")
def on_startup():
    with tracer.start_as_current_span("startup"):
        with tracer.start_as_current_span("deps.load"):
            load_dependencies_like()
        with tracer.start_as_current_span("template.compile"):
            compile_templates_like()
        with tracer.start_as_current_span("db.pool.init"):
            init_db_pool_like()# --- 初回アクセスで目立つ処理（＝外部APIや遅延ロードの代替） ---
def render_template_like():
    time.sleep(0.20)
    return "<html><body>Hello</body></html>"@app.get("/health")
def health():
    return {"ok": True}@app.get("/")
def index():
    # 依存ロードが“初回アクセス時”に寄っているケースを想定
    with tracer.start_as_current_span("template.render"):
        html = render_template_like()    # 外部API呼び出し（requests instrumentationでさらに詳細スパンが出る）
    with tracer.start_as_current_span("external_api_call"):
        r = requests.get("https://httpbin.org/delay/1", timeout=5)
        r.raise_for_status()    return {"message": "ok", "html_len": len(html)}

3) アプリ起動 → 初回/2回目を叩いて差を見る

セットアップして起動：

python -m venv .venv
# mac/linux:
source .venv/bin/activate
# windows:
# .venv\Scripts\activatepip install -r requirements.txtexport OTEL_SERVICE_NAME=otel-coldstart-demo
export DEPLOYMENT_ENV=local
export OTEL_EXPORTER_OTLP_ENDPOINT=localhost:4317uvicorn app:app --host 0.0.0.0 --port 8080

別ターミナルで叩く：

curl -s http://localhost:8080/health
curl -s http://localhost:8080/   # 1回目（コールド）
curl -s http://localhost:8080/   # 2回目（ウォーム）

ここまでで、少なくとも / のトレースがJaegerに飛びます。
さらに startup スパンも送れていれば、起動時の初期化が“塊”ではなく内訳で見えます。

4) Jaegerで「遅さの支配項」を特定する読み方

Jaeger UI（http://localhost:16686）で Service に otel-coldstart-demo を選択し、トレースを開きます。

見るポイントは以下です。

起動時の内訳（startup）
- deps.load が支配的か
- template.compile が支配的か
- db.pool.init が支配的か
  起動が遅いなら、まずここが“犯人の候補”になります。
HTTP GET / の内訳
- template.render にどれだけ使っているか
- external_api_call の中に、requestsの詳細スパン（HTTP client）が出ているか
  外部APIが遅いなら、DNS/TLS/待ちがここで見えます（タイムアウトやリトライも追えるようになります）。
1回目と2回目の差
1回目だけ遅いスパンがあるなら、そこが初回問題の本体です。
たとえばテンプレが初回だけ長い、外部APIが初回だけ長い、など差分で言えます。

5) 実務に寄せる：初回判定や環境差を“属性”で埋める

「本番だけ遅い」「特定のビルドだけ遅い」を追うなら、トレースに属性を入れます。

deployment.environment=dev/stg/prod
service.version（git commitやtag）
cold_start=true（初回だけ付与したいなら、初回判定フラグをアプリ内で持つ）

これを入れると、観測が“点”ではなく“比較”になります。
初回最適化は比較が命なので、ここまでやると改善が続きやすいです。

まとめ

OpenTelemetryで初回処理を可視化すると、最適化のやり方が根本から変わります。
「遅い気がする」から、「このスパンが何msで支配している」に変わるからです。

起動時の初期化は startup スパン配下で分解する
初回アクセス時の重い処理は手動スパンで切り、外部I/Oは自動計測で拾う
1回目/2回目を比較して、コールドスタートの正体を差分で特定する
Collectorを挟んでおくと、送信先やサンプリングの戦略変更が容易になる

この状態に持っていければ、次にやることは単純です。
“重いスパン”を短くする施策を打ち、もう一度トレースを見て数字が下がったことを確認する。
それだけで、初回遅延の改善が「再現性のある作業」になります。

投稿日

2024年4月30日

カテゴリー:

未分類

投稿者:

saigo

タグ:

OpenTelemetryで“初回だけ遅い”を解剖する：依存ロード・DB接続・外部APIをトレースで可視化する入門

はじめに

座学

1) 「初回処理」をトレースで捉えると何が変わるか

2) 自動計測と手動計測の使い分け

3) “起動時”と“初回リクエスト”は別物として計測する

4) Collectorを挟む意味（最初から挟んだ方が楽）

ハンズオン

0) 事前準備

1) Jaeger＋Collectorを立ち上げる

`docker-compose.yml`

`otel-collector-config.yaml`

2) “初回処理が目立つ”アプリを作る（わざと遅くする）

`requirements.txt`

`app.py`

3) アプリ起動 → 初回/2回目を叩いて差を見る

4) Jaegerで「遅さの支配項」を特定する読み方

5) 実務に寄せる：初回判定や環境差を“属性”で埋める

まとめ

コメント

コメントを残すコメントをキャンセル

OpenTelemetryで“初回だけ遅い”を解剖する：依存ロード・DB接続・外部APIをトレースで可視化する入門

はじめに

座学

1) 「初回処理」をトレースで捉えると何が変わるか

2) 自動計測と手動計測の使い分け

3) “起動時”と“初回リクエスト”は別物として計測する

4) Collectorを挟む意味（最初から挟んだ方が楽）

ハンズオン

0) 事前準備

1) Jaeger＋Collectorを立ち上げる

docker-compose.yml

otel-collector-config.yaml

2) “初回処理が目立つ”アプリを作る（わざと遅くする）

requirements.txt

app.py

3) アプリ起動 → 初回/2回目を叩いて差を見る

4) Jaegerで「遅さの支配項」を特定する読み方

5) 実務に寄せる：初回判定や環境差を“属性”で埋める

まとめ

コメント

コメントを残す コメントをキャンセル

`docker-compose.yml`

`otel-collector-config.yaml`

`requirements.txt`

`app.py`

コメントを残すコメントをキャンセル