Http, SQL, Redisのロギングと分析・可視化について

改善は計測から。何がどれだけの回数通信されているか、どれだけ時間がかかっているのか、というのは言うまでもなく重要な情報です。障害対策でも大事ですしね。が、じゃあどうやって取るの、というとパッとでてくるでしょうか？そして、それ、実際に取っていますか？存外、困った話なのですねー。TraceをONにすると内部情報が沢山出てきますが、それはそれで情報過多すぎるし、欲しいのはそれじゃないんだよ、みたいな。

Grani←「謎社」で検索一位取ったので、ちょっと英語表記の検索ランキングをあげようとしている――では自前で中間を乗っ取ってやる形で統一していて、使用している通信周り、Http, RDBMS, Redisは全てログ取りして分析可能な状態にしています。

HTTP

HttpClient(HttpClientについてはHttpClient詳解を読んでね)には、DelegatingHandlerが用意されているので、その前後でStopwatchを動かしてやるだけで済みます。

public class TraceHandler : DelegatingHandler
{
    static readonly Logger httpLogger = NLog.LogManager.GetLogger("Http");

    public TraceHandler()
        : base(new HttpClientHandler())
    {

    }

    public TraceHandler(HttpMessageHandler innerHandler)
        : base(innerHandler)
    {

    }

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
    {
        var sw = Stopwatch.StartNew();

        // SendAsyncの前後を挟むだけ
        var result = await base.SendAsync(request, cancellationToken);

        sw.Stop();
        httpLogger.Trace(Newtonsoft.Json.JsonConvert.SerializeObject(new
        {
            date = DateTime.Now,
            command = request.Method,
            key = request.RequestUri,
            ms = sw.ElapsedMilliseconds
        }, Newtonsoft.Json.Formatting.None));

        return result;
    }
}

// 使う時はこんな感じにコンストラクタへ突っ込む
var client = new HttpClient(new TraceHandler());

// {"date":"2013-07-30T21:29:03.2314858+09:00","command":{"Method":"GET"},"key":"http://www.google.co.jp/","ms":129}
client.GetAsync("http://google.co.jp/").Wait();

なお、StreamをReadする時間は含まれていないので、あくまで向こうが反応を返した速度だけの記録になりますが、それでも十分でしょう。 Loggerは別にConsole.WriteLineでもTraceでも何でもいいのですが、弊社では基本的にNLogを使っています。フォーマットは、Http, Sql, Redisと統一するためにdate, command, key, msにしていますが、この辺もお好みで。

なお、DelegatingHandlerは連鎖して多段に組み合わせることが可能です。実際AsyncOAuthと合わせて使うと

var client = new HttpClient(
    new TraceHandler(
        new OAuthMessageHandler("key", "secret")));

といった感じになります。AsyncOAuthはHttpClientの拡張性がそのまま活かせるのが強い。

SQL

全てのデータベース通信は最終的にはADO.NETのDbCommandを通ります、というわけで、そこをフックしてしまえばいいのです。というのがMiniProfilerで、以下のように使います。

var conn = new ProfiledDbConnection(new SqlConnection("connectionString"), MiniProfiler.Current);

MiniProfilerはASP.NET MVCでの開発に超絶必須な拡張なわけで、当然、弊社でも使っています。さて、これはこれでいいのですけれど、MiniProfiler.Currentは割とヘヴィなので、そのまま本番に投入するわけもいかずで、単純にトレースするだけのがあるといいんだよねー。なので、ここは、MiniProfiler.Current = IDbProfilerを作りましょう。

なお、DbCommandをフックするProfiledDbConnectionに関してはそのまま使わせてもらいます。ただたんに移譲してるだけなんですが、DbCommandやDbTransactionや、とか、関連するもの全てを作って回らなければならなくて、自作するのカッタルイですから。ありものがあるならありものを使おう。ちなみに、MiniProfilerにはSimpleProfiledConnectionという、もっとシンプルな、本当に本当に移譲しただけのものもあるのですけれど、これはIDbConnectionがベースになってるので実質使えません。ProfiledDbConnectionのベースはDbConnection。IDbConnectionとDbConnectionの差異はかなり大きいので(*AsyncもDb...のほうだし)、実用的にはDbConnectionが基底と考えてしまっていいかな。

public class TraceDbProfiler : IDbProfiler
{
    static readonly Logger sqlLogger = NLog.LogManager.GetLogger("Sql");

    public bool IsActive
    {
        get { return true; }
    }

    public void OnError(System.Data.IDbCommand profiledDbCommand, ExecuteType executeType, System.Exception exception)
    {
        // 何も記録しない
    }

    // 大事なのは↓の3つ

    Stopwatch stopwatch;
    string commandText;

    // コマンドが開始された時に呼ばれる(ExecuteReaderとかExecuteNonQueryとか)
    public void ExecuteStart(System.Data.IDbCommand profiledDbCommand, ExecuteType executeType)
    {
        stopwatch = Stopwatch.StartNew();
    }

    // コマンドが完了された時に呼ばれる
    public void ExecuteFinish(System.Data.IDbCommand profiledDbCommand, ExecuteType executeType, System.Data.Common.DbDataReader reader)
    {
        commandText = profiledDbCommand.CommandText;
        if (executeType != ExecuteType.Reader)
        {
            stopwatch.Stop();
            sqlLogger.Trace(Newtonsoft.Json.JsonConvert.SerializeObject(new
            {
                date = DateTime.Now,
                command = executeType,
                key = commandText,
                ms = stopwatch.ElapsedMilliseconds
            }, Newtonsoft.Json.Formatting.None));
        }
    }

    // Readerが完了した時に呼ばれる
    public void ReaderFinish(System.Data.IDataReader reader)
    {
        stopwatch.Stop();
        sqlLogger.Trace(Newtonsoft.Json.JsonConvert.SerializeObject(new
        {
            date = DateTime.Now,
            command = ExecuteType.Reader,
            key = commandText,
            ms = stopwatch.ElapsedMilliseconds
        }, Newtonsoft.Json.Formatting.None));
    }
}

これで、

{"date":"2013-07-15T18:24:17.4465207+09:00","command":"Reader","key":"select * from hogemoge where id = @id","ms":6}

のようなデータが取れます。パラメータの値も展開したい！とかいう場合は自由にcommandのとこから引っ張れば良いでしょう。更に、MiniProfiler.Currentと共存したいような場合は、合成するIDbProfilerを用意すればなんとかなる。Time的には若干ずれますが、そこまで問題でもないかしらん。

public class CompositeDbProfiler : IDbProfiler
{
    readonly IDbProfiler[] profilers;

    public CompositeDbProfiler(params IDbProfiler[] dbProfilers)
    {
        this.profilers = dbProfilers;
    }

    public void ExecuteFinish(IDbCommand profiledDbCommand, ExecuteType executeType, DbDataReader reader)
    {
        foreach (var item in profilers)
        {
            if (item != null && item.IsActive)
            {
                item.ExecuteFinish(profiledDbCommand, executeType, reader);
            }
        }
    }

    public void ExecuteStart(IDbCommand profiledDbCommand, ExecuteType executeType)
    {
        foreach (var item in profilers)
        {
            if (item != null && item.IsActive)
            {
                item.ExecuteStart(profiledDbCommand, executeType);
            }
        }
    }

    public bool IsActive
    {
        get
        {
            return true;
        }
    }

    public void OnError(IDbCommand profiledDbCommand, ExecuteType executeType, Exception exception)
    {
        foreach (var item in profilers)
        {
            if (item != null && item.IsActive)
            {
                item.OnError(profiledDbCommand, executeType, exception);
            }
        }
    }

    public void ReaderFinish(IDataReader reader)
    {
        foreach (var item in profilers)
        {
            if (item != null && item.IsActive)
            {
                item.ReaderFinish(reader);
            }
        }
    }
}

といったものを用意しておけば、

var profiler = new CompositeDbProfiler(
    StackExchange.Profiling.MiniProfiler.Current,
    new TraceDbProfiler());

var conn = new ProfiledDbConnection(new SqlConnection("connectionString"), profiler); 

と、書けます。

SumoLogicによる分析

データ取るのはいいんだけど、それどーすんのー？って話なわけですが、以前にASP.NETでの定期的なモニタリング手法に少し出しましたけれど、弊社ではSumo Logicを利用しています。例えば、SQLで採取したログに以下のようクエリが発行できます。

これは10ミリ秒よりかかったDELETE文を集計、ですね。Sumoは結構柔軟なクエリで、ログのパースもできるんですが、最初からJSONで吐き出しておけばjsonコマンドだけでパースできるので非常に楽ちん。で、パース後は10msより上なら ms > 10 といった形でクエリ書けます。

問題があった時の分析に使ってもいいし、別途グラフ化も可能(棒でも円でも色々)されるので、幾つか作成してダッシュボードに置いてもいいし、閾値を設定してアラートメールを飛ばしてもいい。slow_logも良いし当然併用しますが、それとは別に持っておくと、柔軟に処理できて素敵かと思われます。

Redis

弊社ではキャッシュ層もMemcachedではなく、全てRedisを用いています。Redisに関しては、C#のRedisライブラリ「BookSleeve」の利用法を読んでもらいたいのですが、ともあれ、BookSleeveと、その上に被せているお手製ライブラリのCloudStructuresを使用しています。

実質的に開発者が触るのはCloudStructuresだけです。というわけで、CloudStructuresに用意してあるモニター用のものを使いましょう。というかそのために用意しました。まず、ICommandTracerを実装します。

public class RedisProfiler : ICommandTracer
{
    static readonly Logger redisLogger = NLog.LogManager.GetLogger("Redis");

    Stopwatch stopwatch;
    string command;
    string key;

    public void CommandStart(string command, string key)
    {
        this.command = command;
        this.key = key;
        stopwatch = Stopwatch.StartNew();
    }

    public void CommandFinish()
    {
        stopwatch.Stop();

        redisLogger.Trace(Newtonsoft.Json.JsonConvert.SerializeObject(new
        {
            date = DateTime.Now,
            command = command,
            key = key,
            ms = stopwatch.ElapsedMilliseconds
        }, Newtonsoft.Json.Formatting.None));

        // NewRelic使うなら以下のも。後で解説します。
        var ms = (long)System.Math.Round(stopwatch.Elapsed.TotalMilliseconds);
        NewRelic.Api.Agent.NewRelic.RecordResponseTimeMetric("Custom/Redis", ms);
    }
}

何らかのRedisへの通信が走る際にCommandStartとCommandFinishが呼ばれるようになってます。そして、RedisSettingsに渡してあげれば

// tracerFactoryにFuncを渡すか、.configに書くかのどちらかで指定できます
var settings = new RedisSettings("127.0.0.1", tracerFactory: () => new RedisProfiler());
            
// {"date":"2013-07-30T22:41:34.2669518+09:00","command":"RedisString.TryGet","key":"hogekey","ms":18}
var value = await new RedisString<string>(settings, "hogekey").GetValueOrDefault();

みたいになります。

CloudStructuresは、既に実アプリケーションに投下していて、凄まじい数のメッセージを捌いているので、割と安心して使っていいと思いますですよ。ServiceStack.Redisはショッパイけど、BookSleeveはプリミティブすぎて辛ぽよ、な方々にフィットするはずです。実際、C# 5.0と合わせた際のBookSleeveの破壊力は凄まじいので、是非試してみて欲しいですね。

New Relicによるグラフ化

Sumo Logicはいいんですけど、しかし、もう少し身近なところにも観測データを置いておきたい。そして見やすく。弊社ではモニタリングにNew Relicを採用していますが、そこに、そもそもSQLやHttpのカジュアルな監視は置いてあるんですね。なので、Redis情報も統合してあげればいい、というのが↑のNewRelicのAPIを叩いているものです。ただたんにNuGetからNewRelicのライブラリを持ってきて呼ぶだけの簡単さ。それだけで、以下の様なグラフが！

これはCall Countですが、他にAverageのResponse Timeなどもグラフ化してカスタムダッシュボードに置いています。

線が6本ありますが、これは用途によってRedisの台を分けているからです。例えばRedis.Cache, Redis.Session、のように。NewRelicのAPIを叩く際に、Custom/Redis/Cache、Custon/Redis/Sessionのようなキーのつけ方をすることで、個別に記録されます(それぞれのSettingsに個別のICommandTracerを渡しています)。ダッシュボードの表示時にCustom/Redis/*にするだけでひとまとめに表示できるから便利。

今のところ、Redisは全台平等に分散ではなく、グループ分け＋負荷の高いものは複数台で構成しています。キャッシュ用途の台はファイルへのセーブなしで、完全インメモリ(Memcachedに近い)にしているなど、個別チューニングも入っています。

一番カジュアルに確認できるNew Relic、詳細な情報や解析クエリはSumo Logic。見る口が複数あるのは全然いいことです。

レスポンスタイム

HttpContextのTimestampに最初の時間が入っているので、Application_EndRequestで捕まえて差分を取ればかかった時間がサクッと。

protected void Application_EndRequest()
{
    var context = HttpContext.Current;
    if (context != null)
    {
        var responseTime = (DateTime.Now - context.Timestamp);
  
        // 解析するにあたってクエリストリングは邪魔なのでkeyには含めずの形で
        logger.Trace(Newtonsoft.Json.JsonConvert.SerializeObject(new
        {
            date = DateTime.Now,
            command = this.Request.Url.GetComponents(UriComponents.Path, UriFormat.Unescaped),
            key = this.Request.Url.GetComponents(UriComponents.Query, UriFormat.Unescaped),
            ms = (long)responseTime.TotalMilliseconds
        }, Newtonsoft.Json.Formatting.None));
    }
}

取れますね。

まとめ

改善は計測から！足元を疎かにして改善もクソもないのです。そして、存外、当たり前のようで、当たり前にはできないのね。また、データは取るだけじゃなく、大事なのは開発メンバーの誰もが見れる場所にあるということ。いつでも。常に。そうじゃないと数字って相対的に比較するものだし、肌感覚が養えないから。

弊社では、簡易なリアルタイムな表示はMiniProfilerとビュー統合のログ表示。実アプリケーションでは片っ端から収集し、NewRelicとSumoLogicに流しこんで簡単に集計・可視化できる体制を整えています。実際、C#移行を果たしてからの弊社のアプリケーションは業界最速、といってよいほどの速度を叩きだしています。基礎設計からガチガチにパフォーマンスを意識しているから、というのはもちろんあるのですが(そしてC# 5.0の非同期がそれを可能にした！)、現在自分が作っているものがどのぐらいのパフォーマンスなのか、を常に意識できる状態に置けたことも一因ではないかな、と考えています。(ただし、.NET最先端技術によるハイパフォーマンスウェブアプリケーションで述べましたが、そのためには開発環境も本番と等しいぐらいのネットワーク環境にしてないとダメですよ！)

私は今年は、言語や設計などの小さな優劣の話よりも、実際に現実に成功させることに重きを置いてます。C#で素晴らしい成果が出せる、その証明を果たしていくフェーズにある。成果は出せるに決まってるでしょ、と、仮に理屈では分かっていても、しかしモデルケースがなければ誰もついてこない。だから、そのための先陣を切っていきたい。勿論、同時に、成果物はどんどん公開していきます。C#が皆さんのこれからの選択肢の一番に上がってくれるといいし、また、C#といったらグラニ、となれるよう頑張ります。