SQLで遅いGoリクエストを見つける：gospanでnet/httpのスパンをSQLiteに保存する

GoのAPIは通常、数ミリ秒で応答しますが、一部のリクエストには40ミリ秒かかります。ログを見れば遅延は確認できます。しかし、その時間がデータベースクエリ、レンダリング、外部呼び出しのどこに費やされたかはわかりません。

トレーシング基盤を導入する方法もあります。ただし、問題が単一プロセス内に収まっているなら、SQLiteファイルだけで十分かもしれません。

akmadian/gospanは、入れ子になったスパンを記録し、SQLiteまたはlog/slogに書き込みます。net/httpハンドラーに計測コードを追加してワークロードを実行し、生成されたファイルにクエリを実行することで、遅い処理とそれに関連する入力を見つけられます。

役立つのは、親子関係、処理時間、属性が組み合わさり、通常のSQLで調べられるテーブルに格納される点です。一方、記録は非同期で行われるため、イベントが破棄される可能性があります。

この記事は、2026年10月7日に検証されたgospan v0.1.0の提供調査資料に基づいています。以下の測定値はその調査によるもので、この記事のために別途実行して得たものではありません。READMEでは、ファイル形式は変更しない契約として定義されていますが、Go APIは1.0までに変更される可能性があります。

調査対象が単一プロセス内に収まる場合に使う#

gospanは、「このプログラム内のどの処理がリクエストを遅くしているのか」という、対象を絞った調査に適しています。

コア部分はGoの標準ライブラリを使用しています。SQLiteシンクは、Pure Goドライバーのmodernc.org/sqliteを使用します。提供された検証では、サンプルをCGO_ENABLED=0でビルドしています。コレクターやエージェントは不要です。

プロセス間でコンテキストを伝播する機能はありません。そのため、別のサービスへのHTTP呼び出しが同じトレースを自動的に引き継ぐことはありません。複数のサービスをまたいでリクエストを追跡したい場合、この境界が重要になります。

OpenTelemetryについても、正確に比較する必要があります。OpenTelemetryのSDKはコレクターなしでも実行でき、必要なインフラはエクスポーターとデプロイ構成によって決まります。ここでのgospanの魅力は、ローカルでの計測から、クエリ可能なSQLiteファイルの生成までを直接つなげられる点です。

ファイルを作成し、リクエストの入口に計測を追加する#

検証に使用されたモジュールは次のとおりです。

github.com/akmadian/gospan v0.1.0
github.com/akmadian/gospan/sqlite v0.1.0

検証対象のgospanモジュールにはGo 1.25.0が必要です。この例を再現する際は、バージョンを固定してください。

アプリケーション起動時に、シンクを一度だけ初期化します。

sink, err := sqlite.New("traces")
if err != nil {
    log.Fatal(err)
}

tracer, err := gospan.New(sink)
if err != nil {
    log.Fatal(err)
}

gospan.SetDefault(tracer)

デフォルトでは、シンクは実行ごとに別のファイルを作成します。ファイルの場所はsink.Path()で取得できます。

リクエストの入口でルートスパンを作成し、返されたコンテキストをハンドラーに渡します。

func traced(route string, next http.HandlerFunc) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        ctx, span := gospan.Start(
            r.Context(),
            "http.request",
            slog.String("http.method", r.Method),
            slog.String("http.route", route),
        )
        defer span.End()

        next(w, r.WithContext(ctx))
    })
}

このr.WithContext(ctx)の呼び出しにより、ハンドラー内の処理に対する親スパンが設定されます。元のリクエストコンテキストで子スパンを開始すると、その親子関係が失われます。

スパン名は固定してください。名前にはdb.queryを使い、テーブル、識別子、クエリの分類は属性に格納します。個々のユーザーIDを名前に含めると、メモリ内の集計で不要に種類数が増えます。

改善につなげられる処理にスパンを追加する#

データベース用のヘルパーでは、入力とエラーを記録できます。

func loadUser(ctx context.Context, id int) error {
    ctx, span := gospan.Start(
        ctx,
        "db.query",
        slog.String("db.table", "users"),
        slog.Int("db.id", id),
    )
    defer span.End()

    err := queryUser(ctx, id)
    if err != nil {
        span.Fail(err)
    }
    return err
}

Failは結果を記録するだけで、スパンを終了しません。deferによるEndは残してください。

errors.Isでcontext.Canceledまたはcontext.DeadlineExceededに一致するエラーは、canceledになります。それ以外のエラーはerrorになります。このため、タイムアウトした依存先への呼び出しと、それを含むHTTPリクエストで、異なる結果を記録できます。子スパンはキャンセル扱いになり、リクエストは502を返したためエラーとして記録される、といった形です。

行数など、後から判明する情報にはSetAttrsを使います。Endの後に変更を加えても反映されません。

子を持たない小さな処理には、より短く書けるTrackを使えます。

func checkCache(ctx context.Context) {
    defer gospan.Track(ctx, "cache.lookup")()
    // キャッシュを検索する。
}

Trackは、そのスパンを含むコンテキストを返しません。後続の処理を子スパンにする必要がある場合は、Startを使ってください。

シャットダウン時は、リクエストの受け付けを停止し、実行中のハンドラーが完了するのを待ってから、適切なコンテキストを指定してtracer.Closeを呼び出します。クローズ処理では、キュー内のイベントを処理し、最後のフラッシュを実行します。

原因がわかっているワークロードを用意する#

提供された実験では、8つの並行ワーカーを使い、次のエンドポイントに合計300リクエストを送信しました。

| エンドポイント | 意図的に設定した動作 | |---|---| | GET /users/{id} | 模擬的なデータベース処理に、id % 10 == 7なら40 ms、それ以外は2 msかかる | | GET /report | データベース呼び出しを3回逐次実行した後、レンダリングに15 msかかる | | POST /checkout | 決済呼び出しのタイムアウト期限は30 msで、8件に1件の入力では50 msの処理を試みる |

これらの遅延は意図的に加えたものです。既知の原因をトレースから突き止められるかを示すためのものであり、実際のデータベースに性能問題があることを示すものではありません。

記録された実行では、287件が成功し、13件がステータス502を返しました。トレーサーの統計は次のとおりです。

started=1100 completed=1100 written=2500
dropped=0 write_errors=0

1,100個のスパンには、リクエストのルートスパンと子の処理が含まれます。Writtenが数えるのは、完了したスパンではなくイベントです。開始1,100件、終了1,100件、属性更新300件で、合計2,500イベントになります。

ファイルを解釈する前に、破棄数と書き込みエラー数の両方を確認してください。クエリ結果に問題がないように見えても、記録が不完全な可能性はあります。

完了した処理のうち、最も遅いものを調べる#

SQLiteシンクには、読みやすい名前と計算済みのduration_ns列を持つspans_namedビューが用意されています。属性は別のattrsテーブルに格納されます。

記録が完了したファイルを読み取り専用で開きます。

sqlite3 -readonly traces/your-run.sqlite

まず、完了したスパンを所要時間の長い順に調べます。

SELECT
    trace_id,
    id,
    parent_id,
    name,
    ROUND(duration_ns / 1e6, 2) AS duration_ms
FROM spans_named
WHERE end_ns IS NOT NULL
ORDER BY duration_ns DESC
LIMIT 20;

遅いリクエストのルートスパンは、調査対象を示します。その子スパンを見れば、記録されたどの処理が遅延に寄与したかがわかります。

123を取得したトレースIDに置き換えて、1つのトレースを詳しく調べます。

SELECT
    id,
    parent_id,
    name,
    ROUND(duration_ns / 1e6, 2) AS duration_ms,
    status,
    error
FROM spans_named
WHERE trace_id = 123
ORDER BY start_ns;

各行の所要時間をすべて足して、リクエスト時間として扱わないでください。親の時間には子の処理時間が含まれます。また、並行して実行される子の時間帯は重なることがあります。階層とタイムスタンプを使って、それぞれの時間区間を解釈してください。

レポート用エンドポイントでは、逐次実行されるデータベース呼び出しとレンダリングが、別々の処理として見えます。そこから、「データベース処理をまとめられるか」「遅延の大半はレンダリングによるものか」という、具体的な次の問いにつなげられます。

遅いスパンを入力と結び付ける#

処理時間からは、どの処理が遅いかを特定できます。属性からは、その条件を探れます。

次のクエリは、20ミリ秒を超えるデータベーススパンを見つけ、記録されたIDを一覧にします。

SELECT
    t.value AS db_table,
    COUNT(*) AS slow_calls,
    group_concat(i.value, ',') AS ids
FROM spans_named AS s
JOIN attrs AS t
    ON t.span_id = s.id AND t.key = 'db.table'
JOIN attrs AS i
    ON i.span_id = s.id AND i.key = 'db.id'
WHERE s.name = 'db.query'
  AND s.end_ns IS NOT NULL
  AND s.duration_ns > 20e6
GROUP BY t.value;

この条件を制御したワークロードでは、遅くなると予想されるユーザーIDはid % 10 == 7を満たします。実際のサービスでも、同じ形式のクエリにより、特定のクエリ分類や入力サイズに遅延が集中していることがわかるかもしれません。

ただし、その相関だけでは原因の説明にはなりません。データベースが原因と疑われる場合は、クエリプランとデータベース側の測定で確認してください。

失敗した処理や未完了の処理には、次のクエリを使います。

SELECT
    CASE
        WHEN end_ns IS NULL THEN 'incomplete'
        WHEN status = 1 THEN 'error'
        ELSE 'canceled'
    END AS outcome,
    name,
    COUNT(*) AS spans,
    MIN(error) AS sample_error
FROM spans_named
WHERE end_ns IS NULL OR status <> 0
GROUP BY outcome, name
ORDER BY spans DESC;

終了時刻がnullであることは、終了が永続化されていないことを意味します。考えられる原因には、処理が未完了であること、イベントが破棄されたこと、フラッシュ前にプロセスが終了したことなどがあります。

記録の信頼性も結果の一部として扱う#

gospanは、容量に上限のあるチャネルを通じて、1つの書き込み用goroutineにイベントを送ります。デフォルトの容量は8,192イベントです。チャネルが満杯になると、デフォルトのポリシーでは新たに届いたイベントを破棄し、Stats().Droppedを増やします。

代わりにWithBlockingPolicy()を使うと、空きができるまで待機します。これによりイベントをキューに入れられますが、計測対象の処理に待ち時間が加わります。

提供された高頻度ループのベンチマークでは、検証した構成のslogシンクで、イベントのおよそ80%が破棄されました。欠損を確認せずにオーバーヘッドを評価してはいけないことを示しています。

SQLiteでは、さらに別の境界があります。Writtenはシンクがイベントを受け付けたことを意味し、永続ストレージに保存されたことまでは保証しません。シンクはイベントをバッファリングし、Flush時にコミットします。フラッシュに失敗すると、保留中のデータは再試行されずに破棄され、失敗はWriteErrorsに計上されます。

正常なシャットダウンが重要です。強制終了すると、キュー内のイベントや未コミットのイベントが失われる可能性があります。

ローカルでの調査なら、これらの制約を明示的に確認することで、許容できる場合があります。まずは遅いエンドポイントを1つ選び、リクエストスパンと、負荷の高い処理を囲むスパンを追加して、代表的なワークロードを実行してください。Dropped=0とWriteErrors=0を確認し、最も時間のかかったトレースを調べ、その属性をもとに次の測定対象を選びます。

出典: https://zenn.dev/nonejp/articles/c7dd2859872f9d