概要

ASP.NETCoreのWebアプリケーションに、.NETAgentを導入した環境においてTransactionとSpanは標準で以下のようになっています。

Transaction
- 外部からのHTTPリクエスト受信からレスポンス返却
Span
- EntityFrameworkCoreによるSQLの実行
- 外部へのHttpRequest送受信

しかし、実際のアプリケーションにおいては外部のリソースのHTTPによる呼び出しや、SQLの実行以外にも複雑なビジネスロジックがあったりなど、特定のメソッドの処理時間も取りたい！と思うときがありますね。

そんなときにも対応できるよう、Spanについては独自に定義することができます。
今回はそれをやってみましょう。

結論の図

論より証拠、やってみた結果の画面を貼ってみます。

f:id:tsgkdt:20191008214050p:plain

最初のHTTPGetのところと、一番下にある外部へのGetリクエスト送信は標準で出力される内容です。
注目いただきたいところは、その間に複数の処理が入っているところです。これが独自に定義したSpanで出力した内容の部分です。
メソッドのコールの様子、処理時間が可視化されている様子が分かります。

実践

用意するもの

VisualStudioで作成できるWebAPIのプロジェクト(ValuesControllerがあるやつです）
AspectInjector (APMの処理を書くために便宜的に使用)

参照するドキュメント

こちらにSpanの書き方が書いてあったのでこれを参考にします。

www.elastic.co

Span定義部分

Spanの定義を、各クラス、各メソッドに全部埋めていくのはちょっと手間がかかりそうでしたので、AspectInjectorを使って、アノテーションを付与することでメソッドに対してAPMの処理をかけられるようにしました。

そのアノテーション用のクラスの中で、Spanの定義を書きます。

using AspectInjector.Broker;
using Elastic.Apm.Api;
using System;
using System.Collections.Generic;
using System.Linq;
using System.Linq.Expressions;
using System.Reflection;
using System.Threading.Tasks;

namespace WebApplication3.Filter
{
    [Aspect(Scope.Global)]
    [Injection(typeof(TraceAspectAttribute))]
    public sealed class TraceAspectAttribute : Attribute
    {
        [Advice(Kind.Around, Targets = Target.Method)]
        public object TraceDuration([Argument(Source.Type)] Type type,
                                    [Argument(Source.Name)] string name,
                                    [Argument(Source.Target)] Func<object[], object> target,
                                    [Argument(Source.Metadata)] MethodBase methodBase,
                                    [Argument(Source.Arguments)] object[] arguments)
        {
            //現在のトランザクションの取得
            ITransaction transaction = Elastic.Apm.Agent.Tracer.CurrentTransaction;

            //トランザクション用のラベルの設定
            var label = transaction.Labels;
            if (!label.ContainsKey("target")) transaction.Labels.Add("target", "ElasticTest");

            //Spanの定義　名前をクラスのFullNameとメソッド名とし、処理のタイプをExecにする
            var result = transaction.CaptureSpan($"{type.FullName}-{name}",
                ApiConstants.ActionExec, (s) =>
            {
                //トランザクションではなく、Spanにもラベルを定義できる
                s.Labels.Add("MethodName", name);
                //メソッドの引数と中身をラベルに渡してみる
                methodBase.GetParameters().ToList().ForEach(x =>
                {
                    s.Labels.Add(x.Name, arguments[x.Position].ToString());
                });
                //実際のメソッドの呼び出し
                return target(arguments);

            });
            return result;
        }
    }
}

[Advice(Kind.Around, Targets = Target.Method)]

この部分、Kind.Aroundとすることでメソッドの開始と終了の周り（Around）に処理を書くことにします。

実際の本体の処理の呼び出し部分は、target(arguments);の部分です。他の部分はAPMに関する処理です。

コントローラ部分

VisualStudioが最初に作ってくれるコントローラの部分を流用して処理を追加しました。本当は、DIしてインスタンスを持ってくるべきところですがそこはご容赦を。

        // GET api/values/5
        [HttpGet("{id}")]
        public ActionResult<string> Get(int id)
        {
            var function = new ValueFunction();
            var waitFunction = new WaitFunction();
            var httpRequestFunction = new HttpRequestFunction();

            var result = function.FunctionFirst(id).ToString();
            waitFunction.Wait(id);
            httpRequestFunction.Request();

            return result;
        }

Span処理をかけたいロジック部分

何の重要な処理もなクラスとメソッドですが、クラスに先ほど作成したTraceAspectを指定しておきます。こうすることで、FunctionFirst, FunctionSecond, FunctionThirdといった各種メソッドがSpanとして処理されるようになります。

FunctionFirst -> FunctionSecond -> FunctionThirdとそれぞれ内部で呼び出すような順序としました。

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using WebApplication3.Filter;

namespace WebApplication3.Functions
{
    [TraceAspect] //AspectInjectorの対象にする
    public class ValueFunction
    {
        public int FunctionFirst(int val)
        {
            return FunctionSecond(val, DateTime.Now);
        }

        public int FunctionSecond(int val, DateTime date)
        {
            try
            {
                return FunctionThird(val, 2, "偶数のときはエラーにしたい");
            } catch 
            {
                return 0;
            }
        }

        public int FunctionThird(int val, int powNumber, string message = "")
        {
            if (val > 0 && val % 2 == 0)
            {
                throw new ElasticApmTestException($"与えられたメッセセージは「{message}」です");
            }
            return (int)Math.Pow(val, 2);
        }
    }

    public class ElasticApmTestException : Exception
    {
        public ElasticApmTestException(string message) : base(message)
        {
        }
    }
}

画面の見え方

トランザクションのラベル

Transaction画面でMetadataのリンクを押すか、トランザクションのところをクリックすることでDetail画面が表示されます。
そこで、指定したラベルが設定されていることが確認できます。

f:id:tsgkdt:20191008215319p:plain

Spanのラベル

出力した引数と、引数の中身がラベルとして表示されています。
もちろんパスワード文字列などを表示するのは良くないですが、特定の処理が遅いときなどの場合、どんな引数でそれが実行されたのか知りたい、と思うことはありそうです。
そんな用途に使えそうです。

f:id:tsgkdt:20191008215745p:plain

Exceptionの処理

先に示したValueFunctionでは、0でない偶数を渡すと例外が発生する実装が含まれていました。
でも、処理としてはcatchで握りつぶされ、0が返る実装となっています。

そんなときに、Elastic APMでは画面上どう見えるかというと、こうなります。　catchで握りつぶしているのに！

f:id:tsgkdt:20191008220804p:plain

トランザクション部分にある赤字で１の部分がリンクになっていて、そこからエラー確認画面に遷移できます。

f:id:tsgkdt:20191008221001p:plain

発生した例外メッセージが表示されていて、この部分をクリックするとさらに詳細画面に遷移します。

f:id:tsgkdt:20191008221239p:plain

ここではスタックトレースが確認できるので、どのソースでエラーが起きていたかを確認することができますね。

Exceptionの処理おまけ

catchしない例外がスローされたら、どうなるんでしょうか。

        public int FunctionSecond(int val, DateTime date)
        {
            //try
            //{
              return FunctionThird(val, 2, "偶数のときはエラーにしたい try-catchもしない");
            //} catch 
            //{
            //    return 0;
            //}
        }

このようにしてみて、同じようにエラー画面を見てみます。

f:id:tsgkdt:20191008221907p:plain