OpenTelemetry .NETを理解する (4) Spanに情報を追加する

今回は、第2回目で計装したコードを基に、計測したSpanに情報を追加してみます。

tech.tanaka733.net

以下のコードを出発点にします。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var forecast = Enumerable.Range(1, 5).Select(index =>
       new WeatherForecast
       (
           DateTime.Now.AddDays(index),
           Random.Shared.Next(-20, 55),
           summaries[Random.Shared.Next(summaries.Length)]
       ))
        .ToArray();
    try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        logger.LogError(e, "error happened");
    }
    logger.LogInformation("Response1 length: {Length}", forecast.Length);
    return forecast;
})
.WithName("GetWeatherForecast");

今回の操作はOpenTelemetry .NETのドキュメントではここに記述されています。

opentelemetry.io

SpanとActivity

.NET には従来 System.Diagnostics.Activityという診断のために利用できるクラスがあります。

docs.microsoft.com

OpenTelemetry .NETでは（他の言語のOpenTelemetry実装と異なり）この言語備え付けの Activityを内部で利用しており、Activityを操作することでOpenTelemetryの計測も操作できるようになっています。この記事ではActivityクラスを使って操作する方法を紹介します。OpenTelemetryの仕様にもとづいたAPIで操作する方法もあり、そちらはOpenTelemetry Tracing Shimとして紹介されています。

Manual Instrumentation | OpenTelemetry

かんたんにいうと、ActivityとSpanは「計測するために区切られたある作業の単位」という同じ概念を表しています。

現在のSpanを取得する

第2回で紹介したASP.NET Coreで自動計装を適用している場合、Spanに情報を追加するためにはまず現在記録しているSpanを取得する必要があります。これはActivity.Currentプロパティで取得することが可能です。なお、計測していない場合などにnullが返る可能性があります。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    //以下略
}

タグを追加する

OpenTelemetryのSpanにはタグとよばれるキー・値のペアを追加することができます。タグの重要性については先日のObservability Conferenceの資料にも書いています。

tech.tanaka733.net

タグはActivity.SetTagメソッドで追加できます。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    activity?.SetTag("operation.value", 1);
    activity?.SetTag("operation.name", "Saying hello!");
    //以下略
}

イベントを追加する

Spanにイベントを追加することができます。イベントはTimestampと文字列情報およびキー値のペアを持つことができます。これはActivity.AddEventにActivityEventオブジェクトを渡して追加できます。ActivityEventのコンストラクタでこれらの情報を指定しますが、Timestampはデフォルトで現在時刻になるので、通常は指定しないことになります。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    activity?.SetTag("operation.value", 1);
    activity?.SetTag("operation.name", "Saying hello!");

    var spanTags = new ActivityTagsCollection(new KeyValuePair<string, object?>[]
        {
            new ("mode", "normal"),
            new ("speed", 10),
        });
    activity?.AddEvent(new ActivityEvent("Start", tags: spanTags));

    var forecast = Enumerable.Range(1, 5).Select(index =>
       new WeatherForecast
       (
           DateTime.Now.AddDays(index),
           Random.Shared.Next(-20, 55),
           summaries[Random.Shared.Next(summaries.Length)]
       ))
        .ToArray();
    
    activity?.AddEvent(new ActivityEvent("End"));
    logger.LogInformation("Response1 length: {Length}", forecast.Length);
    return forecast;
})
.WithName("GetWeatherForecast");

Spanの状態を設定する

これもObservability Conferenceにて発表したことにつながりますが、処理の中で異常な状態になった（通常例外が発生した）のであれば、Spanの状態もエラーとマークすべきです。これにより分析が可能になります。Activity.SetStatusというメソッドがあるのでこれで設定できるはずなのですが、現時点ではまだこのAPIを呼び出してもOpenTelemetry側のSpanの状態がマークされません。

try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        //これは現時点ではOpenTelemetry側に作用しない
        activity?.SetStatus(ActivityStatusCode.Error, "error happened.");
        
        logger.LogError(e, "error happened");
    }

この問題は以下のIssueで議論されています。

github.com

現時点ではotel.status_codeとotel.status_descriptionを使って手動でタグとして設定します。また、例外オブジェクトを記録したい場合、Activity.RecordExceptionを使うと例外オブジェクトを格納したイベントを追加してくれます。したがってcatch節に書くであろうコードはこうなります。

    try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        activity?.SetTag("otel.status_code", "ERROR");
        activity?.SetTag("otel.status_description", "error happened.");
        activity.RecordException(e);
        logger.LogError(e, "error happened");
    }

まとめ

以上でコードはこのようになります。

app.MapGet("/weatherforecast", (ILogger<Program> logger, HttpContext context) =>
{
    var activity = Activity.Current;
    activity?.SetTag("operation.value", 1);
    activity?.SetTag("operation.name", "Saying hello!");

    var spanTags = new ActivityTagsCollection(new []
        {
            new KeyValuePair<string, object?>("mode", "normal"),
            new KeyValuePair<string, object?>("speed", 10),
        });
    activity?.AddEvent(new ActivityEvent("Start", tags: spanTags));
    var forecast = Enumerable.Range(1, 5).Select(index =>
       new WeatherForecast
       (
           DateTime.Now.AddDays(index),
           Random.Shared.Next(-20, 55),
           summaries[Random.Shared.Next(summaries.Length)]
       ))
        .ToArray();
    try
    {
        throw new Exception("error!!!!");
    }
    catch (Exception e)
    {
        // このコードは https://github.com/open-telemetry/opentelemetry-dotnet/issues/2569 によりOpenTelemetry側に作用しない
        //activity?.SetStatus(ActivityStatusCode.Error, "error happened.");
        activity?.SetTag("otel.status_code", "ERROR");
        activity?.SetTag("otel.status_description", "error happened.");
        activity.RecordException(e);
        logger.LogError(e, "error happened");
    }
    activity?.AddEvent(new ActivityEvent("End"));
    logger.LogInformation("Response1 length: {Length}", forecast.Length);
    return forecast;
})
.WithName("GetWeatherForecast");

これを実行するとバックエンドで追加した情報が見えるようになります。New RelicであればSpanの状態をエラーにすると下のように赤色になります。

また属性が追加されていることもわかります。

View Span eventsというリンクをクリックするとSpanに追加したイベントの一覧が確認できます。Spanイベントに追加したタグや例外オブジェクトも確認できます。

さて、OpenTelemetry .NETのドキュメントには子スパンの作成とSpanのLinkの機能も紹介されていますが、これは改めて紹介したいと思います。

Observabilty Conference 2022 by CloudNative Daysで登壇しました

所属は明らかにしていますが、個人登壇という立場で「Deep Dive Distributed Tracing」というセッションをしてきました。発表内容もW3C Trace ContextやOpenTelemetryなどを中心にしつつ、できるだけ特定のツールの考え方ではなく共通で考えられているものをもとに整理しています。アーカイブ視聴が可能なようです。

event.cloudnativedays.jp

リアルタイムでzoomから発表したため、Q&Aができませんでした。コメントを基に2つほど回答したいと思います。追加で質問がある、という場合はTwitter までコメントお願いします。

1. 分散トレースはUI、LoadBalancer、API Gateway、DBといったインフラ要素まで串刺しで見られないと不十分ではないか？

2. ボトルネックを分析する上で不十分なケースはあるでしょう。UI（Browser）上の処理は分散トレースを計測可能なことが多いですが、それ以外のLoadBalancerなどは現状難しいようです。アプリ内のトレースを分析することによって、まずアプリに原因があるかどうかの手がかりが得られます。また、アプリとアプリの間に原因がある場合、その間にある要素に手がかりがある可能性が高いので、その要素のトレメトリーデータ（メトリクスやログなど）を分析するという次のアクションに進むことができます。 また、それぞれの要素で少し異なるので補足します。

3. UI: UI側の理も最近では分散トレースの計測が可能になっています。例えばBrowserであれば、OpenTelemetryだとこのドキュメントです。また、Mobile やデスクトップクライアントアプリの場合も可能です。UIから直接バックエンドアプリを呼び出すのではなく、間に次に出てくるLoadBalancerやAPI Gatewayといった中間要素を挟むケースが増えてきており、どこにボトルネックがあるか分析しやすくするためにも分散トレースとして計測しておく価値が増えてきていると感じます。

4. LoadBalancer、API Gateway: 分散トレースに参加させることが難しいものが多いため、前後のスパンから遅延があるかどうか見つけるというのが現状の分析手段になるかと思います。これらの要素はメトリクスやログをテレメトリーデータとして取得できることが多いため、分散トレースとこれらのデータを突き合わせて分析することになりそうです。そのため、例えば特定のHTTPヘッダーを記録に使っている場合は、そのヘッダーをトレース・スパンにもタグとして記録しておくことが重要になります。

5. DB: DBでの処理結果は、できるかぎりDB呼び出ししたスパンがDB呼び出しライブラリ経由で取得し、記録しておくことが重要です。例えばOpenTelemetryでどんなデータを記録すべきと考えているかは仕様のドキュメントにかかれています。

6. OpenTelemetryではサンプリングアルゴリズムはどれが選択できるのか？

7. OpenTelemetryではSamplerを設定することでアルゴリズムの選択が可能です。組み込みで用意されているものはこちらのドキュメントに記載されていますが、カスタマイズしたものを追加することも可能です。

OpenTelemetry .NETを理解する (3) デバッグログを出す

OpenTelemetry .NET で計測していると、正しく動作しているか確認したいときがあります。OpenTelemetry .NETにはこのようなときのために、自己診断機能が用意されています。

opentelemetry-dotnet/README.md at main · open-telemetry/opentelemetry-dotnet · GitHub

このドキュメントにあるとおり、計装コード側を変更する必要はなく、カレントディレクトリに以下の形式のOTEL_DIAGNOSTICS.jsonという名前のファイルを配置するだけです。

{
    "LogDirectory": ".",
    "FileSize": 1024,
    "LogLevel": "Error"
}

設定パラメータもドキュメントに説明されています。

• LogDirectory にログファイルを出力するディレクトリを指定します。ここではカレントディレクトリに出力します。
• FileSize にログファイルのサイズをKiB単位で指定します。1~128MiBの間で指定でき、ここでは1MiBを指定しています。
• LogLevel に指定したレベル以上のログが記録されます。EventLevel列挙型の値を指定できます。

出力されるログファイルは{実行ファイルの名前}.{プロセスID}.logというフォーマットになります。また、FileSizeで指定したサイズになるよう、ログ出力が少ないときは末尾がNULで埋められています。