銀の光と碧い空

クラウドなインフラとC#なアプリ開発の狭間にいるエンジニアの日々

OpenTelemetry .NETを理解する (5) HttpClientによる外部通信処理を計測する

前回はスパンに情報を追加しました。

tech.tanaka733.net

次にトレースをさらにスパンで区切ってどの処理に時間がかかっているか計測することにします。スパンは作業の単位で区切ります。原理的には1メソッド1スパンで記録することもできますが、計測のオーバーヘッドや分析のノイズになることから、意味のある作業の単位でスパンを作成するのがおすすめです。そして、トレースで注目したいボトルネックになりうる作業の単位としては、HTTPでの外部呼び出しやデータベースへの呼び出しが典型的です。そのため、OpenTelemetry .NETでもそれらのライブラリに対して自動計装する機能が用意されています。今回は、HttpClientによる外部呼び出しを自動計装する機能を紹介します。

最初のコードはこのような状態です。

app.MapGet("/external", async () =>
{
    var client = new HttpClient();
    var req = await client.GetAsync("http://httpbin.org/get");
    var res = await req.Content.ReadAsStringAsync();
    Console.WriteLine(res);
    return res;
});

app.MapGet("/external/error", async () =>
{
    var client = new HttpClient();
    var req = await client.GetAsync("http://httpbin.org/status/502");
    try
    {
        var res = await req.EnsureSuccessStatusCode().Content.ReadAsStringAsync();
        Console.WriteLine(res);
    }
    catch (Exception e)
    {
        Console.WriteLine(e.Message);
    }
});

HttpClientの自動計装については、次のようにASP.NET Coreの最初の設定時にAddHttpClientInstrumentationメソッドを呼び出すことで行います。そのため、個別のHttpClientの呼び出し部分に処理を追加する必要はありません。

builder.Services.AddOpenTelemetryTracing((builder) => builder
        .AddAspNetCoreInstrumentation()
        .SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Hello-Otel").AddAttributes(tags))
        //以下1行を追加する
        .AddHttpClientInstrumentation()
        .AddOtlpExporter(options => 
        {
            options.Endpoint = new Uri("https://otlp.nr-data.net:4317/");
            options.Headers = $"api-key={Environment.GetEnvironmentVariable("OTEL_API_KEY")}";
        })
    );

すると、/externalのエンドポイントは次のようにトレースが記録されます。HttpClientによる通信処理が1つの子スパンとして記録されています。これにより、全体の処理(親スパン)のうち、外部通信でどれだけかかっているかがわかります。また、レスポンスのステータスコードなどの情報がhttp.ではじまる属性として記録されています。

一方、external/error のエンドポイントは次のようにトレースが記録されます。通信処理が子スパンとして記録された上で、スパンの状態をエラーとして記録しているため赤く表示されています。

さて、子スパンはエラーとして記録されていますが、親スパンの側はエラーとしては記録されていません。これは外部通信処理がエラーであっても、必ずしも親スパンの状態がエラーになるべきではないからです。通信処理でエラーが発生した場合に親スパンもエラーとして記録したい場合、前回の記事で紹介した方法で記録することになります。

app.MapGet("/external/error", async () =>
{
    var client = new HttpClient();
    var req = await client.GetAsync("http://httpbin.org/status/502");
    try
    {
        var res = await req.EnsureSuccessStatusCode().Content.ReadAsStringAsync();
        Console.WriteLine(res);
    }
    catch (Exception e)
    {
        var activity = Activity.Current;
        activity?.SetTag("otel.status_code", "ERROR");
        activity?.SetTag("otel.status_description", "required service is down.");
        activity?.RecordException(e);
    }
});

これで親スパンもエラーとして記録されるようになります。

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_codeotel.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の状態をエラーにすると下のように赤色になります。

f:id:tanaka733:20220319233423p:plain

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

f:id:tanaka733:20220319233300p:plain

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

f:id:tanaka733:20220319233529p:plain

f:id:tanaka733:20220319233552p:plain

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