Http, SQL, Redisのロギングと分析・可視化について
- C# - 13.07/30
改善は計測から。何がどれだけの回数通信されているか、どれだけ時間がかかっているのか、というのは言うまでもなく重要な情報です。障害対策でも大事ですしね。が、じゃあどうやって取るの、というとパッとでてくるでしょうか?そして、それ、実際に取っていますか?存外、困った話なのですねー。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#といったらグラニ、となれるよう頑張ります。
Comment (0)
Trackback(1) | http://neue.cc/2013/07/30_420.html/trackback
- SumoLogic の紹介と LocalFile の日本語対応 | guitarrapc.wordpress.com : (08/03 19:56)
[…] 具体的な使い方はまた機会があれば挙げますが、以下のページで紹介がされています。 ログブラウズ、解析サービスSumologicの紹介 neuecc – Http, SQL, Redisのロギングと分析・可視化について […]