ActionFilter属性を利用した簡易時間計測

One ASP.NET Advent Calendar 2013の19日目担当、今年4度目の登場@xin9leです。そろそろ完全に大顰蹙のような気がしていますが、気にしないことにして...。今回は大好きなSignalRのお話ではなく、ASP.NET MVCやWeb APIにあるAction Filterを使った処理時間の計測についてです。

ノーマルな方法

例えば、リクエストを投げたのにレスポンスがヤケに遅いとします。アクセス過多でないとすればアクションメソッドの処理に時間が掛かっていると思われます。「チューニングは計測から」ということで処理時間の計測をしてみましょう。ここでは計測結果はデバッグ出力に表示するとします。

public class HomeController : Controller
{
    public ActionResult Index()
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            //--- ここでDBアクセスとかしてみたり
            return View();
        }
        finally
        {
            stopwatch.Stop();
            Debug.WriteLine(stopwatch.Elapsed);
        }
    }
}

実処理を囲むようにtry-finallyを入れることになって大変にメンドクサイです。キチンとコントローラーを薄く作っている方からすれば実処理よりもデバッグ用の計測の方がコードが長くなったりして気持ち悪さ満点です。

usingスコープの利用

「そのtry-finallyはお決まりなのでもっと楽できるでしょう」と考えた方、正解です。IDisposableを利用すれば次のように計測範囲をusingスコープで明示した形で書くことができます。

public class ElapsedTimeWatch : IDisposable
{
    private readonly Stopwatch stopwatch = null;

    public ElapsedTimeWatch()
    {
        this.stopwatch = Stopwatch.StartNew();
    }

    public void Dispose()
    {
        this.stopwatch.Stop();
        Debug.WriteLine(this.stopwatch.Elapsed);
    }
}

public class HomeController : Controller
{
    public ActionResult Index()
    {
        using (new ElapsedTimeWatch())
        {
            //--- ここでDBアクセスとかしてみたり
            return View();
        }
    }
}

この方法はかなりお手軽なので、WPFとかバッチのようなクライアントアプリを作るときによく使っています。しかし、まだ以下のような不満があります。

デバッグ実行時にも計測処理が走る (結果の表示はされない)
usingスコープで囲うだけとはいえ、実処理に手を入れているのがイヤ
ビューのレンダリング計測ができていない

ここで颯爽と登場するActionFilter属性！

ActionFilter属性の利用

ActionFilter属性はコントローラーやアクションに付与することができる属性で、アクションメソッドの実行前/実行後とアクション結果の実行前/実行後に対する独自処理を差し込むことができます。先の方法ではusingスコープなどで計測の前後のタイミングを自分で作り出していましたが、ActionFilter属性を利用すればフレームワークが提供してくれるタイミングに乗っかることができて非常に楽です。以下はその作成例です。

[Conditional("DEBUG")]  //--- デバッグ実行時のみ有効
[AttributeUsage(AttributeTargets.Class | AttributeTargets.Method)]
public class ElapsedTimeAttribute : ActionFilterAttribute
{
    private readonly Stopwatch actionWatch = null;
    private readonly Stopwatch resultWatch = null;

    public ElapsedTimeAttribute()
    {
        this.actionWatch = new Stopwatch();
        this.resultWatch = new Stopwatch();
    }

    //--- アクションメソッド実行前に呼び出されます
    public override void OnActionExecuting(ActionExecutingContext filterContext)
    {
        this.actionWatch.Restart();
        base.OnActionExecuting(filterContext);
    }

    //--- アクションメソッド実行後に呼び出されます
    public override void OnActionExecuted(ActionExecutedContext filterContext)
    {
        base.OnActionExecuted(filterContext);
        this.actionWatch.Stop();

        if (!filterContext.Canceled)
        if (filterContext.Exception == null)
            return;

        ElapsedTimeAttribute.Output
        (
            filterContext.HttpContext.Request.Url,
            filterContext.HttpContext.Request.HttpMethod,
            filterContext.ActionDescriptor.ControllerDescriptor.ControllerName,
            filterContext.ActionDescriptor.ActionName,
            (HttpStatusCode)filterContext.HttpContext.Response.StatusCode,
            this.actionWatch.Elapsed,
            null
        );
    }

    //--- アクション結果実行前に呼び出されます
    public override void OnResultExecuting(ResultExecutingContext filterContext)
    {
        this.resultWatch.Restart();
        base.OnResultExecuting(filterContext);
    }

    //--- アクション結果実行後に呼び出されます
    public override void OnResultExecuted(ResultExecutedContext filterContext)
    {
        base.OnResultExecuted(filterContext);
        this.resultWatch.Stop();
        ElapsedTimeAttribute.Output
        (
            filterContext.HttpContext.Request.Url,
            filterContext.HttpContext.Request.HttpMethod,
            filterContext.RouteData.Values["controller"].ToString(),
            filterContext.RouteData.Values["action"].ToString(),
            (HttpStatusCode)filterContext.HttpContext.Response.StatusCode,
            this.actionWatch.Elapsed,
            this.resultWatch.Elapsed
        );
    }

    //--- デバッグ出力に表示
    private static void Output(Uri uri, string method, string controller, string action, HttpStatusCode statusCode, TimeSpan actionElapsed, TimeSpan? resultElapsed)
    {
        var totalElapsed = resultElapsed.HasValue ? actionElapsed + resultElapsed.Value : actionElapsed;
        var builder      = new StringBuilder();
        builder.AppendLine  ("----------------------------------------");
        builder.AppendFormat("Request Uri      : {0}&yen;n", uri);
        builder.AppendFormat("Http Method      : {0}&yen;n", method);
        builder.AppendFormat("Controller       : {0}&yen;n", controller);
        builder.AppendFormat("Action           : {0}&yen;n", action);
        builder.AppendFormat("Status Code      : {0}&yen;n", statusCode);
        builder.AppendFormat("Elapsed [Action] : {0}&yen;n", actionElapsed);
        builder.AppendFormat("Elapsed [Result] : {0}&yen;n", resultElapsed);
        builder.AppendFormat("Elapsed [Total]  : {0}&yen;n", totalElapsed);
        builder.AppendLine  ("----------------------------------------");
        Debug.Write(builder.ToString());
    }
}

これを利用すると以下のようになります。実処理に何の影響も与えない記述ができているのが分かります。超エレガント！

[ElapsedTime]  //--- コントローラーに含まれるすべてのアクションを計測したい場合
public class HomeController : Controller
{
    [ElapsedTime]  //--- 付与したアクションでのみ計測したい場合
    public ActionResult Index()
    {
        //--- ここでDBアクセスとかしてみたり
        return View();
    }
}

Output

Web APIでもやってみる

ASP.NET Web APIはASP.NET MVCと似ているので、同様にActionFilter属性が存在します。「じゃあ」ということでやってみました。ほとんど同じですね！

[Conditional("DEBUG")]
[AttributeUsage(AttributeTargets.Class | AttributeTargets.Method)]
public class ElapsedTimeAttribute : ActionFilterAttribute
{
    private readonly Stopwatch actionWatch = null;

    public ElapsedTimeAttribute()
    {
        this.actionWatch = new Stopwatch();
    }

    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        this.actionWatch.Restart();
        base.OnActionExecuting(actionContext);
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);
        this.actionWatch.Stop();
        var builder = new StringBuilder();
        builder.AppendLine  ("----------------------------------------");
        builder.AppendFormat("Request Uri : {0}&yen;n", actionExecutedContext.Request.RequestUri);
        builder.AppendFormat("Method      : {0}&yen;n", actionExecutedContext.Request.Method);
        builder.AppendFormat("Controller  : {0}&yen;n", actionExecutedContext.ActionContext.ActionDescriptor.ControllerDescriptor.ControllerName);
        builder.AppendFormat("Action      : {0}&yen;n", actionExecutedContext.ActionContext.ActionDescriptor.ActionName);
        builder.AppendFormat("Status Code : {0}&yen;n", actionExecutedContext.Response.StatusCode);
        builder.AppendFormat("Elapsed     : {0}&yen;n", this.actionWatch.Elapsed);
        builder.AppendLine  ("----------------------------------------");
        Debug.Write(builder.ToString());
    }
}