シンプルな例から学ぶ、トレーシングを使って問題を発見する方法

はじめに

Mackerelでは先ごろ、分散トレーシングサービスのVaxilaが使えるようになりました。Mackerelがこれまで提供していた監視（モニタリング）も、この度お使いいただけるようになったトレーシングも、システムの状態の把握や理解をするための手法ですが、視点や手法が異なります。

このエントリでは、ごくシンプルなアプリケーションからトレースやスパンを送信しVaxilaの画面を交えながら、トレーシングの見方や活用方法をご紹介します。

はじめに
トレーシングとは何か
シンプルなWebアプリケーションを用いたトレーシングの例
- アプリケーションを起動する
トレース画面の見方
- 全体のリクエストフロー
- 各スパンの詳細を見ていく
トレーシングを用いてどのように課題を発見するか
まとめ

トレーシングとは何か

まず、トレーシングについておさらいしましょう。

トレーシングとは、アプリケーションの処理フローを可視化し、リクエストやデータの流れがシステム内をどのように移動し何が起こっているかを追跡する技術です。特に昨今ではシステムが複雑化しアプリケーションが大きくなってきたり、複数のマイクロサービスが協調して動くようなシステム環境では、リクエストが複数のサービスをまたいで処理されるため、その全体像を把握するのは困難です。ここでトレーシングが活躍します。

トレーシングでは、以下のような要素を把握できます。

各サービスでの処理時間や遅延の要因
エラーや例外が発生した箇所とその原因
リクエストがどのサービスをどのような順番で通過したか

たとえば、あるユーザーが「ブログ投稿」ボタンをクリックしたとしましょう。そのリクエストは、フロントエンドからバックエンドのアプリケーション、データベースを経由して処理されたり保存された後、レスポンスとしてクライアントであるユーザーへ返却されます。トレーシングは、この一連の流れを「スパン」という単位で記録し、可視化します。

従来の監視では単一のサーバーやシステム全体の状態や起きていることを把握することができましたが、トレーシングではある特定のリクエストや処理の流れに着目し、その中のどこで何が起こっているかを特定できるという点が異なります。

シンプルなWebアプリケーションを用いたトレーシングの例

以下はGoで書いたシンプルなWebアプリケーションでトレースをOpenTelemetryによって計装したものです。OpenTelemetryとはベンダーやツールに依存しない、テレメトリデータ（メトリックやトレースなど）を作成・管理するためのツールキットです。Mackerelでもラベル付きメトリックやVaxilaがOpenTelemetyに対応しています。以下の例には、トレーシングやOpenTelemetryに関する概念がいくつか出てきますが、リンクしているドキュメントをご参照ください。

アプリケーションの処理の流れは次の通りです。ソースコード中の(1)のような数字表記と対応しています。

エンドポイントは /heavy のみが動作しています。このエンドポイントでは以下のような処理を行います (1)
- 2秒間スリープします (2)
- 重い処理をする関数を直列に3回呼び出します (3)
- 最後に This is heavy endpoint というテキストをレスポンスとして返します (4)

また、アプリケーションの処理に対してトレースを計装するための準備をする部分のコードは以下のようになります。ソースコード中の(a)のようなアルファベットの小文字表記と対応しています。

VaxilaのAPIにHTTPでトレースを送信するクライアントを初期化します (a)
トレースエクスポーターを初期化しクライアントを設定します (b)
リソースの設定をします (c)
トレーサープロバイダーを初期化しエクスポーターとリソースを設定します (d)

最後にトレースのためのスパンを作成している部分は以下のようになっています。ソースコード中の(A)のようなアルファベットの大文字表記と対応しています。

otelhttp.NewHandler を用いることでエンドポイントのハンドラーをラップしたスパンを作成します (A)
重い処理をする関数を表すスパンの作成します。名前は引数として与えられた秒数 n を用いて span n とします (B)
5秒より処理に時間がかかった場合、スパンイベントに例外を、スパンステータスに Error をそれぞれ設定します (C)

このプログラムは以下のバージョンで動作確認をしています。

package main

import (
    "context"
    "fmt"
    "net/http"
    "os"
    "time"

    "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
    "go.opentelemetry.io/otel"
    "go.opentelemetry.io/otel/codes"
    "go.opentelemetry.io/otel/exporters/otlp/otlptrace"
    "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp"
    "go.opentelemetry.io/otel/sdk/resource"
    sdktrace "go.opentelemetry.io/otel/sdk/trace"
    semconv "go.opentelemetry.io/otel/semconv/v1.20.0"
    "go.opentelemetry.io/otel/trace"
)

func initTracerProvider(ctx context.Context) (*sdktrace.TracerProvider, error) {
    // (a) トレースを送信するクライアントの初期化
    client := otlptracehttp.NewClient(
        otlptracehttp.WithEndpoint("otlp-vaxila.mackerelio.com"),
        otlptracehttp.WithHeaders(map[string]string{
            "Accept":           "*/*",
            "Mackerel-Api-Key": os.Getenv("MACKEREL_APIKEY"),
        }),
        otlptracehttp.WithCompression(otlptracehttp.GzipCompression),
    )
    // (b) トレースエクスポーターの初期化
    exporter, err := otlptrace.New(ctx, client)
    if err != nil {
        return nil, err
    }

    // (c) リソース情報の設定
    resources, err := resource.New(
        ctx,
        resource.WithProcessPID(),
        resource.WithHost(),
        resource.WithAttributes(
            semconv.ServiceName("sample-service"),
            semconv.DeploymentEnvironment("development"),
            semconv.ServiceNamespace("sample-namespace"),
        ),
    )
    if err != nil {
        return nil, err
    }

    // (d) トレーサープロバイダーの初期化
    tp := sdktrace.NewTracerProvider(
        sdktrace.WithBatcher(exporter),
        sdktrace.WithResource(resources),
    )
    otel.SetTracerProvider(tp)

    return tp, nil
}

// 引数で与えられた秒数だけスリープする関数
func superHeavyFunc(ctx context.Context, t trace.Tracer, n int) {
    // (B) superHeavyFunc のスパンを作成
    _, span := t.Start(ctx, fmt.Sprintf("Heavy func %d", n))
    defer span.End()

    time.Sleep(time.Duration(n) * time.Second)

    // (C) 5秒より処理に時間がかかったらエラーとする
    if n > 5 {
        msg := "timeout!"
        span.RecordError(fmt.Errorf("%s", msg))
        span.SetStatus(codes.Error, msg)
    }
}

func main() {
    ctx := context.Background()

    tp, err := initTracerProvider(ctx)
    if err != nil {
        panic(err)
    }
    defer tp.Shutdown(ctx)
    tracer := tp.Tracer("main")

    // (1) /heavy エンドポイントの定義
    http.Handle("/heavy",
        // (A) スパンでハンドラーをラップ
        otelhttp.NewHandler(
            http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
                // (2) 2秒間スリープ
                time.Sleep(time.Duration(2) * time.Second)

                // (3) 重い処理をする関数を3回呼び出す
                superHeavyFunc(r.Context(), tracer, 8)
                superHeavyFunc(r.Context(), tracer, 3)
                superHeavyFunc(r.Context(), tracer, 5)

                // (4) テキストでレスポンスを返す
                fmt.Fprintln(w, "This is heavy endpoint")
            }),
            "heavy-endpoint",
        )
    )

    fmt.Println("Starting server at :8080...")
    if err := http.ListenAndServe(":8080", nil); err != nil {
        fmt.Println("Server failed:", err)
    }
}

アプリケーションを起動する

このアプリケーションからMackerelにトレースを送信する準備をします。

まず、以下のエントリを参考にAPIキーを取得してください。

分散トレーシングサービス Vaxila（ヴァキシラ）が Mackerel の機能として使えるようになりました - Mackerel ブログ #mackerelio

取得したAPIキーを環境変数 MACKEREL_APIKEY にセットしてプログラムを起動します。以下はプログラムを main.go として保存した例です。

$ export MACKEREL_APIKEY={取得したAPIキー}
$ go run main.go
Starting server at :8080...

次に、起動したアプリケーションにブラウザからアクセスしてみましょう。http://localhost:8080/heavy にブラウザからアクセスし、しばらくすると以下のように This is heavy endpoint と表示されます。これでトレースを確認する準備が整いました。

トレース画面の見方

Mackerelのトレース画面にアクセスし、サービスから sample-service|sample-namespace を選択します。トレースの送信が成功している場合、画面の下部にトレースが表示されているはずです。そのうちの一つを開き詳細を見てみましょう。

全体のリクエストフロー

Vaxilaのトレース画面では、リクエストが /heavy エンドポイントに到達し、superHeavyFunc が呼び出される流れが視覚的に示されます。これにより、どの処理でボトルネックが発生しているかを一目で確認できます。

heavy-endpoint スパンの下に Heavy func スパンが3つ並んでいることから、heavy-endpoint スパンの子スパンが3つあるということがわかります。このことから Heavy func の各処理は heavy-endpoint から呼び出され、かつ直列に処理されているということがわかります。

heavy-endpoint, Heavy func それぞれのスパンが表示されている

各スパンの詳細を見ていく

各スパンを詳細に見ていきましょう。文中の(A)や(d)などの記載は、先ほど提示したソースコードおよび解説と対応しています。

heavy-endpoint がこのエンドポイント全体のスパン(A)、その下に並んでいる Heavy func: 8, Heavy func: 3, Heavy func: 5 がそれぞれ superHeavyFunc を呼び出している様子です(B)。さらに、Heavy func: 8 は5秒より処理に時間がかかっているためエラーとなり赤く表示されます(C)。

各スパンには、開始時刻、終了時刻、処理時間、エラーメッセージ（あれば）や属性が記録されています。これらの情報をもとに、遅延やエラーの原因を特定できます。また、traceId、spanId、parentSpanId から、このスパンはどのトレースの一部なのか、親がどのスパンなのかなどがわかります。

otelhttp ライブラリによって記録されたエンドポイントのスパン(A)の詳細を見ると、http. や net. で始まる属性や user_agent.original という属性が記録されています。このエンドポイントがどのようなリクエストでどのようなレスポンスを返したかなどがわかります。

また、エラーとなっている Heavy func: 8 スパン(C)の詳細を見ると、例外(exception)のイベントが発生し、ステータスは ERROR に設定され timeout! というエラーメッセージが表示されています。現実のアプリケーションではエラーの原因の特定に役立つ情報をエラーメッセージに設定するとよいでしょう。

全てのスパンに共通して記録されているリソースはトレースを生成する実体を表します。ソースコード中の(c)の部分でこのアプリケーションのプロセスIDや動作しているホスト名を設定しています。また、semconv. で始まる関数を用いて設定されている属性は、Semantic Conventions（略してsemconv）と呼ばれるOpenTelemetryで用いられる命名規約です。これはトレースに限らず、メトリクスでも用いられます。semconvの意義に関しては「OpenTelemetry Casual Talk - コンセプトのおさらいと実践入門！」での「OpenTelemetry のサービスという概念について」というトークでも解説していますのでご覧ください。

トレーシングを用いてどのように課題を発見するか

これまで見てきたように、トレーシングはスパンによって各処理が可視化されるため、問題のある処理を素早く特定でき、スパンの詳細を見ることで処理時間やエラーの原因を分析できます。

例えば、ぱっと見でスパンの幅が広いものがあれば詳細を開き処理時間を確認する、さらに子スパンを見ていくことで処理に時間のかるドメインロジック、N+1になっている関数呼び出し、処理に時間のかかるSQLクエリの発行などを見つけることができるかもしれません。また、今回は単一のシンプルなアプリケーションを例にしましたが、単一のアプリケーションでも規模が大きかったり、複数のマイクロサービスからなるシステムの場合は、処理に時間がかかっている箇所やエラーが発生している箇所をすばやく特定することの手助けとなるはずです。

まとめ

本エントリでは、簡単なWebアプリケーションを題材としてトレーシングの始め方を解説しました。今回トレースの可視化に使用した分散トレーシングサービスVaxilaは現在無料でお使いいただけます。以下のエントリに始め方を掲載していますのでぜひお試しください！ご要望や使い方の疑問などがありましたら、Webコンソール右上に表示されているサポートチームへ連絡からお気軽にお寄せください。

ブログ

#mackerelio