Http, SQL, Redisのロギングと分析・可視化について
- 2013-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#といったらグラニ、となれるよう頑張ります。
ASP.NETでの定期的なモニタリング手法
- 2013-07-20
cron的な定期実行といったら、タスクスケジューラ使え。完。なわけですが、それとは別にして、アプリケーションサーバー内部からしか分からない情報を定期的に吐き出したいようなシチュエーションにどうしましょうか？例えばスレッドプールの情報！かなり古いのですがHow To 情報: カスタム カウンタを使った ASP.NET スレッド プールの監視方法なんて、まずレジストリに登録して、そこから定期的に無限ループ＋Thread.Sleep（ダセぇ）で出力という、なんともトホホな感じ。いや、これトホホでしょう。というわけで、もっとモダンにいきましょう。
IHttpModuleとInit, Dispose
カスタム HTTP モジュールを作成および登録するということで、IHttpModuleを作成することで、ASP.NETパイプライン上での各イベント時に実行されるものを追加していくことができます。Global.asax.csに直書きでもいいですが、こっちのほうが分離されてる感はありますにぇ。さて、通常はapplication.BeginRequest+=とか、イベント登録するんですが、Application_Startイベントに相当するものは……ありません。はい。ただしかわりにInitメソッドがあります。普段はイベント登録しますが、ここでメソッド実行すれば、それApplication_Startに等しいよねー、と思っていた時もありました。
public class CountModule : IHttpModule
{
public static int Count = 0;
public void Init(HttpApplication context)
{
Interlocked.Increment(ref Count);
}
}
これ、ブレークポイントを張って様子みたり、Countの値を表示して見たりするとわかりますが、何度も呼ばれます。何度も何度も。どーいうことかというと、Application_StartとInitは等しくないです。ASP.NET Runtimeは複数のアプリケーションプールを作り、それごとにInitは呼ばれてるんですね。じゃあ、どうするか、というと……
public class CallOnceModule : IHttpModule
{
static int initializedModuleCount;
public void Init(HttpApplication context)
{
var count = Interlocked.Increment(ref initializedModuleCount);
if (count != 1) return;
// ここに本体書く
}
public void Dispose()
{
var count = Interlocked.Decrement(ref initializedModuleCount);
if (count == 0)
{
// ここに本体書く
}
}
}
Initが呼ばれた回数を取れば、正しく1回になります。ちなみに属性を張るだけで、Application_Startっぽく呼び出されるメソッドを作れるWebActivatorも、似たような感じの仕組みです。
Timer
IHttpModuleの話はこのぐらいにして、本体の話にいきましょう。定期的に、例えば1分間隔に、とかは、Timer使えばいいんですよ、Timer。あ、Timerは幾つかありますが、System.Threading.Timerのほうね。
/// <summary>
/// 1分間隔でThreadInfoをログ取りするモジュール
/// </summary>
public class ThreadInfoLoggingModule : IHttpModule
{
static NLog.Logger logger = NLog.LogManager.GetLogger("ThreadInfo");
static NLog.Logger classLogger = NLog.LogManager.GetCurrentClassLogger();
static int initializedModuleCount;
static Timer timer;
public void Init(HttpApplication context)
{
var count = Interlocked.Increment(ref initializedModuleCount);
if (count != 1) return;
timer = new Timer(_ =>
{
try
{
var date = DateTime.Now;
int availableWorkerThreads, availableCompletionPortThreads;
ThreadPool.GetAvailableThreads(out availableWorkerThreads, out availableCompletionPortThreads);
int maxWorkerThreads, maxCompletionPortThreads;
ThreadPool.GetMaxThreads(out maxWorkerThreads, out maxCompletionPortThreads);
using (var sw = new System.IO.StringWriter())
using (var jw = new Newtonsoft.Json.JsonTextWriter(sw))
{
jw.Formatting = Newtonsoft.Json.Formatting.None;
jw.WriteStartObject(); // {
jw.WritePropertyName("date");
jw.WriteValue(date);
jw.WritePropertyName("availableWorkerThreads");
jw.WriteValue(availableWorkerThreads);
jw.WritePropertyName("availableCompletionPortThreads");
jw.WriteValue(availableCompletionPortThreads);
jw.WritePropertyName("maxWorkerThreads");
jw.WriteValue(maxWorkerThreads);
jw.WritePropertyName("maxCompletionPortThreads");
jw.WriteValue(maxCompletionPortThreads);
jw.WriteEndObject(); // }
jw.Flush();
var message = sw.ToString();
logger.Trace(message);
}
}
catch (Exception ex)
{
classLogger.ErrorException("ThreadInfoLogging encounts error", ex);
}
}, null, TimeSpan.FromMinutes(1), TimeSpan.FromMinutes(1));
}
public void Dispose()
{
var count = Interlocked.Decrement(ref initializedModuleCount);
if (count == 0)
{
var target = Interlocked.Exchange(ref timer, null);
if (target != null)
{
target.Dispose();
}
}
}
}
なにをやっているか。よーするに、Timerで1分置きにロガーでJSONを吐き出してます。ロガーは謎社ではNLogを使ってます。というかこのModuleでは謎社のプロダクション環境で動いてるものです。なお、JsonTextWriter使ってるところは、別に普通にSerializeで構いませんですよ、なんとなく手書きしちゃっただけなので。
というわけで、これでThreadPoolの情報が取れました。やったね！あとはJSONなので好きな様にゴリゴリすればいいんですが、賢く解析したいなら、とりあえず謎社ではSumo Logicを使っています。Next Generation Log Management & Analyticsということで、集計ツールと解析ウェブアプリをワンセットで提供してくれてます。
独自のクエリ言語でガッと解析してグラフ化できてる、ってのは伝わるでしょうか？ふいんきね。便利そう、とか思ってもらえれば。クエリと可視化、更に閾値による通知など、色々できちゃいます。こいつぁイイね？←ちなみに、私はまだ全然クエリ書けないので、これは謎社の誇るPowerShellマスターが用意してくれました。
（ここではparseが手書きチックですが、実際にJSONをSumoでパースする際はJsonコマンドが用意されているので、それを使えばもっと綺麗にparseできます）
BookSleeveのMonitor
ついでに、謎社ではRedisを多用しているんですが、RedisライブラリであるBookSleeveは、GetCountersというメソッドで、それぞれのRedisConnectionの情報を吐き出すことができます。これを1分置きに、ThreadInfoと同様に吐き出すようにしてます。
/// <summary>
/// 1分間隔でRedis(BookSleeve)のCounterをログ取りするモジュール
/// </summary>
public class RedisCounterLoggingModule : IHttpModule
{
static NLog.Logger logger = NLog.LogManager.GetLogger("RedisCounter");
static NLog.Logger classLogger = NLog.LogManager.GetCurrentClassLogger();
static int initializedModuleCount;
static Timer timer;
public void Init(HttpApplication context)
{
var count = Interlocked.Increment(ref initializedModuleCount);
if (count != 1) return;
timer = new Timer(_ =>
{
try
{
var date = DateTime.Now;
// ここは謎社Internalな部分なのでテキトーにスルーしてくださいな
var query = Grani.Core.GlobalConfig.RedisGroupDictionary
.SelectMany(x => x.Value.Settings, (x, settings) => new { x.Value.GroupName, settings });
foreach (var item in query)
{
var connection = item.settings.GetConnection();
var counters = connection.GetCounters();
using (var sw = new System.IO.StringWriter())
using (var jw = new Newtonsoft.Json.JsonTextWriter(sw))
{
jw.Formatting = Newtonsoft.Json.Formatting.None;
jw.WriteStartObject(); // {
jw.WritePropertyName("date");
jw.WriteValue(date);
jw.WritePropertyName("GroupName");
jw.WriteValue(item.GroupName);
jw.WritePropertyName("Host");
jw.WriteValue(item.settings.Host + ":" + item.settings.Port);
jw.WritePropertyName("Db");
jw.WriteValue(item.settings.Db);
jw.WritePropertyName("MessagesSent");
jw.WriteValue(counters.MessagesSent);
jw.WritePropertyName("MessagesReceived");
jw.WriteValue(counters.MessagesReceived);
jw.WritePropertyName("MessagesCancelled");
jw.WriteValue(counters.MessagesCancelled);
jw.WritePropertyName("Timeouts");
jw.WriteValue(counters.Timeouts);
jw.WritePropertyName("QueueJumpers");
jw.WriteValue(counters.QueueJumpers);
jw.WritePropertyName("Ping");
jw.WriteValue(counters.Ping);
jw.WritePropertyName("SentQueue");
jw.WriteValue(counters.SentQueue);
jw.WritePropertyName("UnsentQueue");
jw.WriteValue(counters.UnsentQueue);
jw.WritePropertyName("ErrorMessages");
jw.WriteValue(counters.ErrorMessages);
jw.WritePropertyName("SyncCallbacks");
jw.WriteValue(counters.SyncCallbacks);
jw.WritePropertyName("AsyncCallbacks");
jw.WriteValue(counters.AsyncCallbacks);
jw.WritePropertyName("SyncCallbacksInProgress");
jw.WriteValue(counters.SyncCallbacksInProgress);
jw.WritePropertyName("AsyncCallbacksInProgress");
jw.WriteValue(counters.AsyncCallbacksInProgress);
jw.WritePropertyName("LastSentMillisecondsAgo");
jw.WriteValue(counters.LastSentMillisecondsAgo);
jw.WritePropertyName("LastKeepAliveMillisecondsAgo");
jw.WriteValue(counters.LastKeepAliveMillisecondsAgo);
jw.WritePropertyName("KeepAliveSeconds");
jw.WriteValue(counters.KeepAliveSeconds);
jw.WritePropertyName("State");
jw.WriteValue(counters.State.ToString());
jw.WriteEndObject(); // }
jw.Flush();
var message = sw.ToString();
logger.Trace(message);
}
}
}
catch (Exception ex)
{
classLogger.ErrorException("RedisCounterLogging encounts error", ex);
}
}, null, TimeSpan.FromMinutes(1), TimeSpan.FromMinutes(1));
}
public void Dispose()
{
var count = Interlocked.Decrement(ref initializedModuleCount);
if (count == 0)
{
var target = Interlocked.Exchange(ref timer, null);
if (target != null)
{
target.Dispose();
}
}
}
}
RedisGroupとかコネクション管理はBookSleeveの上に被せてるCloudStructuresによるものです（プロダクション環境でヘヴィに使ってますよ！）。CloudStructuresの使い方とかもまたそのうち。
まとめ
とまぁ、そんなふうにして色々データ取ってます。改善の基本はデータ取りから。色々なところからデータ取ってチェック取れるような体制を整えています。次回は、SQLやHttp、Redisの実行時間をどう取得するかについてお話しましょふ。たぶんね。きっと。
ところで、プロダクション環境下で――と書いているように、謎社のアプリケーションは完全にC#に移行しました。結果ですが、最先端環境で練り上げたC#によるウェブアプリケーションは、超絶速い。しかも、完全にAWSクラウドに乗っけての話ですからね、オンプレミスでのスペシャルなマシンやFusion-ioなDBでやってるわけじゃなく、成果出せてる。
Sumo LogicやNew Relicなど外部サービスの活用やRedisの使い倒しかた、非同期処理の塊、などなど、次世代のC#ウェブアプリケーションのスタンダードというものを示せたのではないかな、と思っています。詳しい話はそのうちまたどこかで発表したいとは思うので待っててください。
C#で扱うRedisのLuaスクリプティング
- 2013-07-10
Redis 2.6からLuaスクリプティングが使えるようになりました。コマンドはEVALです。というわけでC#のRedisライブラリ、BookSleeveで、試してみましょう。RedisやBookSleeveに関しては、以前に私がBuildInsiderで書いたC#のRedisライブラリ「BookSleeve」の利用法を参照ください。
BookSleeveは当然NuGet経由で入れるとして、Windows版のRedisバイナリもNuGetで配布されています。手軽に試してみるなら、Install-Package Redis-64が良いのではないでしょーか。現在の最新は2.6.12.1ということで、Evalにも対応しています。インストールするとpackages\Redis-64.2.6.12.1\toolsにredis-server.exeが転がっているので、それを起動すれば、とりあえず127.0.0.1:6379で動きます。
多重アクセスの検出
HelloWorld!ということで、多重アクセス検知のスクリプトでも書いてみます。ルールとしては、X秒以内にY回アクセスしてきた人間はZ秒アク禁にする。という感じですね。DOSアタック対策的な。LUAスクリプティングを使わないと、キーを2つ用意したりしなけりゃいけなかったり複数コマンド打ったりしたりとか、若干面倒だったり効率悪いのですが、スクリプティング使えば一発で済ませられます。
public static class RedisExtensions
{
public static async Task<bool> DetectAttack(this RedisConnection redis, int db, string key, int limitCount = 10, int durationSecond = 1, int bannedSecond = 300)
{
var result = await redis.Scripting.Eval(db, @"
local key = KEYS[1]
local limit = tonumber(ARGV[1])
local count = redis.call('incr', key)
if(count >= limit) then
local banSec = tonumber(ARGV[3])
redis.call('EXPIRE', key, banSec)
return true
else
local expireSec = tonumber(ARGV[2])
redis.call('EXPIRE', key, expireSec)
return false
end", new[] { key }, new object[] { limitCount, durationSecond, bannedSecond }).ConfigureAwait(false);
// Lua->Redisはtrueの時に1を、falseの時にnullを返す
return (result == null) ? false
: ((long)result == 1) ? true
: false;
}
}
こんな感じですね。基本的にはEvalメソッドでスクリプトを渡すだけです、あとKEYS配列とARGV配列を必要ならば。戻り値の扱いなどに若干のクセがありますので、その辺はRedisのEVALのドキュメントを読んでおくといいでしょう。
スクリプトは、まずincrを呼んでカウントを取る。そのカウントが指定数を超えてたらExpireの時間をBanの時間（デフォは300秒=5分）引き伸ばす。超えてなければ、Expireの時間を指定間隔(デフォは1秒)だけ伸ばす。もし1秒以内に連続でアクセスがあれば、Incrのカウントが増えていく。1秒以上経過すればExpireされているので、countは0スタートになる。といった感じです。
利用する場合はこんな具合。
var redis = new RedisConnection("127.0.0.1");
await redis.Open();
var v = await redis.DetectAttack(0, "hogehoge");
Console.WriteLine(v); // false
for (int i = 0; i < 15; i++)
{
var v2 = await redis.DetectAttack(0, "hogehoge");
Console.WriteLine(v2); // false,false,...,true,true
}
いい具合ですにぇ？
EVALSHA
BookSleeveのEvalは、正確にはEVALSHAです（更に正しくはデフォルトの、引数のuseCacheがtrueの場合）。
EVALSHAは、事前にスクリプトのSHA1を算出し、初回に登録しておくことで、コマンドの転送をSHA1の転送だけで済ませます。スクリプトを毎回投げていたらコマンド転送に時間がかかるので、それの節約です。この辺をBookSleeveは何も意識しなくても、やってくれるのが非常に楽ちん。素晴らしい。
Increment/DecrementLimit
せっかくなので、もう一つ例を。RedisのIncrementやDecrementはアトミックな操作で非常に使いやすいのですが、上限や下限を設けたい場合があります。例えば、HPは0以下になって欲しくないし、最大HPを超えて回復されても困る、みたいな。それも当然、Luaスクリプティングを使えば簡単に実現可能です。
public static async Task<long> IncrementWithLimit(this RedisConnection redis, int db, string key, long value, long maxLimit)
{
var result = await redis.Scripting.Eval(db, @"
local inc = tonumber(ARGV[1])
local max = tonumber(ARGV[2])
local x = redis.call('incrby', KEYS[1], inc)
if(x > max) then
redis.call('set', KEYS[1], max)
x = max
end
return x", new[] { key }, new object[] { value, maxLimit }).ConfigureAwait(false);
return (long)result;
}
incrbyの結果が指定の値を超えていたら、setで固定する、といった感じです、単純単純。使うときはこんな具合。
var redis = new RedisConnection("127.0.0.1");
await redis.Open();
var v1 = await redis.IncrementWithLimit(0, "hoge", 40, maxLimit: 100);
var v2 = await redis.IncrementWithLimit(0, "hoge", 40, maxLimit: 100);
var v3 = await redis.IncrementWithLimit(0, "hoge", 40, maxLimit: 100);
// 40->80->100
Console.WriteLine(v1 + "->" + v2 + "->" + v3);
楽ちん、これは捗る。
まとめ
というわけで、RedisいいよRedis。いやほんと色々な面で使ってて嬉しいことが多いです。RDBMSだけで頑張ると非常に辛ぽよ、Redisがあるだけで何かと楽になれますので、一家に一台は置いておきたい。
Luaスクリプティングは複数コマンド間で戻り値が扱えるため、利用範囲がグッと広がります。そしてスクリプティング中の動作もまたアトミックである、というのが嬉しい点です（C#コード上で複数コマンドを扱うと、そこの保証がないというのが大きな違い）。と同時に注意しなければならないのは、アトミックなので、スクリプト実行中は完全にブロックされてます。ので、あまりヘヴィなことをLuaスクリプティングでやるのは避けたほうがいいのではないかなー、と思われます。
asyncの落とし穴Part2, SynchronizationContextの向こう側
- 2013-07-02
非同期QUIZの時間がやってきました！前回はデッドロックについてでしたが、今回はヌルポについて扱いましょう。まずは以下のコードの何が問題なのかを当ててください。ASP.NET MVCです。あ、.NET 4.5ね。
public class HomeController : Controller
{
async Task DoAsync()
{
await Task.Delay(TimeSpan.FromSeconds(3));
}
public ActionResult Index()
{
DoAsync();
return View();
}
}
どこがダメで、どうすれば改善されるのかはすぐ分かると思います。「なにが起こるのか」「なぜ起こるのか」について、考えてみてください。おわり。
さて、で、Ctrl+F5で実行すると、このコードは何の問題もなくふとぅーに動きます。一見何の問題もない。実際何の問題もない。オシマイ。
というのもアレなので、何が起こっているのか観測します。まず、Global.asax.csに以下のコードを。
protected void Application_Start()
{
// ルーターの登録とか標準のものがこの辺に
Trace.Listeners.Add(new TextWriterTraceListener(@"D:\log.txt"));
Trace.AutoFlush = true;
System.Threading.Tasks.TaskScheduler.UnobservedTaskException += (sender, e) =>
{
Trace.WriteLine(e.Exception);
};
}
で、本体はこんな風に。
public class HomeController : Controller
{
async Task DoAsync()
{
Trace.WriteLine("start"); // 何か開始処理があるのだとする
await Task.Delay(TimeSpan.FromSeconds(3)); // 何か非同期処理してるとする
Trace.WriteLine("end"); // 何か後処理があるのだとする
}
public ActionResult Index()
{
GC.Collect(); // GC自然発生待ちダルいので発動しちゃう
var _ = DoAsync(); // 非同期処理を"待たない"
return View();
}
}
D:\log.txtは、まぁどこに吐いてもいいんですが、ちゃんと書き込み権限があるところに。んでは、実行しましょう。log.txtは、初回はまず、「start」と書かれます。つまり、endまで到達してないことが確認できます。二回目のアクセスではGC.Collectが走り、それによりUnobservedTaskExceptionが実行されます。で、log.txtには以下のものが書き込まれます。
System.AggregateException: タスクの例外が、タスクの待機によっても、タスクの Exception プロパティへのアクセスによっても監視されませんでした。その結果、監視されていない例外がファイナライザー スレッドによって再スローされました。 ---> System.NullReferenceException: オブジェクト参照がオブジェクト インスタンスに設定されていません。
場所 System.Web.ThreadContext.AssociateWithCurrentThread(Boolean setImpersonationContext)
場所 System.Web.HttpApplication.OnThreadEnterPrivate(Boolean setImpersonationContext)
場所 System.Web.HttpApplication.System.Web.Util.ISyncContext.Enter()
場所 System.Web.Util.SynchronizationHelper.SafeWrapCallback(Action action)
場所 System.Web.Util.SynchronizationHelper.<>c__DisplayClass9.<QueueAsynchronous>b__7(Task _)
場所 System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
場所 System.Threading.Tasks.Task.Execute()
--- 内部例外スタック トレースの終わり ---
---> (内部例外 #0) System.NullReferenceException: オブジェクト参照がオブジェクト インスタンスに設定されていません。
場所 System.Web.ThreadContext.AssociateWithCurrentThread(Boolean setImpersonationContext)
場所 System.Web.HttpApplication.OnThreadEnterPrivate(Boolean setImpersonationContext)
場所 System.Web.HttpApplication.System.Web.Util.ISyncContext.Enter()
場所 System.Web.Util.SynchronizationHelper.SafeWrapCallback(Action action)
場所 System.Web.Util.SynchronizationHelper.<>c__DisplayClass9.<QueueAsynchronous>b__7(Task _)
場所 System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
場所 System.Threading.Tasks.Task.Execute()<---
おぅ！例外が発生していた！ぬるり！ぬるり！
GC.Collectを実行している理由は、Taskに溜まった未処理例外は、GCが走ったタイミングでUnobservedTaskExceptionに渡されるので、それを待つ時間を短縮しているだけです。GC.Collectを明示的に実行しなくても、長く動かしてればそのうち発生します。
というわけで、何が起こるのか、というと、await Task.Delayのところでヌルリが発生します。↑の例外情報からは、どこで発生していたのかの情報が一切出てこないので(さすがにこれなんとかして欲しいですけどねぇ……)、いざ発生するとなると場所を突き止めるのに割と苦労します、というか虱潰ししかないので結構大変です。そもそもUnobservedTaskExceptionをモニタしてなければ、発生していたことにすら気づけません。
なぜ起こるのか、というと、awaitによってPOSTする先のContextが消滅しているからです。非同期処理を待たなかったことによって、Viewの表示まで全て完了してContextが消滅する。その後で、DoAsync内のawaitが完了し、続行しようとPOSTを開始する、と、しかしContextは消滅していてなにもなーい。ので、ぬるり。
では、解決方法は、というと、例によってasyncで統一するか
public class HomeController : Controller
{
async Task DoAsync()
{
Trace.WriteLine("start"); // 何か開始処理があるのだとする
await Task.Delay(TimeSpan.FromSeconds(3)); // 何か非同期処理してるとする
Trace.WriteLine("end"); // 何か後処理があるのだとする
}
public async Task<ActionResult> Index()
{
GC.Collect();
await DoAsync(); // awaitする
return View();
}
}
もしくはConfigureAwait(false)でContextを維持しないこと。
public class HomeController : Controller
{
async Task DoAsync()
{
Trace.WriteLine("start"); // 何か開始処理があるのだとする
await Task.Delay(TimeSpan.FromSeconds(3)).ConfigureAwait(false); // ConfigureAwait(false)する
Trace.WriteLine("end"); // 何か後処理があるのだとする
}
public ActionResult Index()
{
GC.Collect();
var _ = DoAsync(); // 非同期処理を"待たない"
return View();
}
}
です。
そもそも、何故非同期処理を"待たない"のか。例えば、アクセスログを取るために記録するだけだとか、別に完了を待つ必要がないものだったりするなら、待たないことでレスポンスは速くなる。待つ必要ないのなら、待たなくてもいいぢゃない。それはそうです。
なので、待たないなら待たないでいいのですが、中身について用心しないと、ヌルりで死んでしまいます。これは、同期的に待つ時もそうですね。待つなら待つでいいですけれど、中身について用心しないと、デッドロックで死んでしまいます。待っても死亡、待たなくても死亡、ホント非同期は地獄だぜ！
まあ、変数で受けたりしない限りは警告は出してくれますので（ウザいと思っていたアナタ！実に有益な警告ではないですか！）、不注意による死亡はある程度は避けられはします。
.NET 4.0 vs .NET 4.5
.NET 4.5だと、↑のような挙動ですが、.NET 4.0だとちょっと事情が違ったりします。async/awaitは利用したままで、ターゲットフレームワークのバージョンだけ4.0にしましょう。
<system.web>
<httpRuntime targetFramework="4.0" />
<compilation debug="true" targetFramework="4.0" />
</system.web>
で、Ctrl+F5で実行して、何度かブラウザをリロードしましょう。死んでます。IIS Expressが。完全に無反応になります。何故？Windowsのイベントビューアーを見ましょう。
ハンドルされない例外のため、プロセスが中止されました。というわけで、未処理例外が突き抜けてアプリケーションエラーとして記録されていくためです。プロダクション環境でもIISのラピッドフェール保護が発動して、デフォルトでは5分以内に5エラーでアプリケーションは停止します。これは実にクリティカル。
なんで.NET 4.0と4.5で挙動が違うのか、というと、Taskの未処理例外の扱いが4.0と4.5で変わったためです。この辺はPfxTeamのTask Exception Handling in .NET 4.5を参照にどーぞ。4.5のほうが安全っちゃー安全ですね。いずれにせよ、UnobservedTaskExceptionの例外ロギングは欠かさずやっておきましょう。
まとめ
非同期もいいんですけど、実際にマジでフルに使い出すと結構なんだかんだでハマりどころは多いですねぇ。幸い、デバッガビリティに関してはWindows 8.1 + Visual Studio 2013である程度改善するようで、待ち遠しいです。とはいえデッドロックだったりコンテキスト場外でヌルりだとかは、注意するしかない。
ASP.NET MVCのフィルターはやく非同期に対応してくださいー。ASP.NET MVC 5でも予定に入ってないようでどうなってんだゴルァ。Resultで待つしかなくて非常にヒヤヒヤします。EF6も非同期対応とか、そもそもMVC 5では.NET 4.5からのみだとか、どんどん非同期使われてくにつれ、死亡率も間違いなく上がってきますにゃ。