2011年11月20日日曜日

MongoDBにASP.NETのSessionを格納する - 完結編

前回のあらすじ

不思議な光る石のペンダントをつけた少女が空から降りてきた。天使が舞い降りたと思い走って近づく少年。その少女は伝説となった天空の城の王の末裔。少年もまた亡き父の言葉を信じ、天空の城の存在を信じていた。悪意を持った別の王の末裔が少女をさらい、城を悪用しようとすることから、少年は少女と城を守るため、海賊とともに空に旅立った。

ドキドキするストーリーですね!

...。

続きです。最終的に接続エラーが出て、処理が継続できない状態に陥るっていうところでした。問題解決する前に、現時点でのパフォーマンスを確認してみます。

前回同様Apache Benchで実行しますが、10000回だとエラーになってしまって計測に失敗してしまうので、桁を下げて1000回(-n 1000 –c 8)としてましょう。

計測方法はabを3回実行してRequest per secondの平均を取ります。

InProc

ms1

1回目:538.39
2回目:588.10
3回目:660.41

平均:595.63

StateServer

ms11

1回目:525.43
2回目:567.28
3回目:599.09

平均:563.93

SQLServer

ms2

1回目:282.39
2回目:370.53
3回目:352.21

平均:335.04

MongoDB

ms3

1回目:129.71
2回目:146.35
3回目:145.03

平均:140.36

うん。早くない。ちなみに無印UniversalProviderだと 30.15 とドンマイな感じ。

Universal Provider

ms4

ちなみに、5回で平均を取りたかったけど、MongoDB版が5回目で接続エラーになって取れなかったので3回にしました。これは良くない!まずはちゃんと10000回普通に動かせるようにしないと。

と、いうわけで、MongoDB C# Official Driverのドキュメントに目を通してみると、内部でConnection Poolingを利用していると書かれています。が、挙動からはPoolがちゃんと利用されてないんじゃないかと、疑ってみました。 だって、接続エラーって...。使いまわしてるならそんなことにならないはず、という根拠のない診断。うさんくさいドクターハウス。

CSharp Driver Tutorial – MongoDB

MongoDB C# Driver API Documentation - Table of Content

詳細はドキュメントから判断出来なかったので、ソースを追いかけてみました。オープンソースだといろいろ調べれていいですねー。

mongodb/mongo-csharp-driver – GitHub

チラチラ見た結果からいうと、MongoServerクラスに保持しているMongoServerInstanceがConnectionPoolを管理していて、MongoServer.Disconnectを呼ぶとすべてのPoolをクローズして回る仕組みのようです。なんでだろ。理由はいいとして、そういう作りなんだということは、finallyで必ずDisconnectを呼び出すのはよろしくないかなー。そんな事しなくても、Poolに保持しているものは10秒ごとにMaxConnectionLifeTime/MaxConnectionIdleTimeを確認して破棄されるようになってるみたいなので、ほっといてもいいんじゃね?みたいな。

と、いうわけで、ソース中のすべてのDisconnectを削除します。

その状態で、abで確認します。

3回実行した結果は525.43 / 599.09 / 572.34。平均:565.62。ワォ!一気に上がりました。せっかくなので10000回出来るかどうかもチェック。

ms5

行けるようになりましたー。ちゃんと接続を使い回してくれてるようです。パフォーマンスも接続を使いまわすことで一気に改善しました。んじゃ、なんで、そういう作りにしてなかったのか?っていうのが気になります。

理由はありました。どういうことかというと、Poolが保持しているMongoConnectionは生成された時点でReplicaSetのPrimaryを判定して保持しています。つまり、Failoverした直後、Poolが破棄されない限り接続エラーがおきて、正しくデータの書き込みができなくなるということでしょう。

abを実行し、その最中にstepDownでFailoverしてみます。

ms6ms7

Safemode detected an error 'not master'. (Response was { "err" : "not master", "code" : 10056, "n" : 0, "lastOp" : NumberLong("5676991341247070789"), "connectionId" : 13356, "ok" : 1.0 }).

masterじゃないダニ!と言われ、書き込みできないエラーが発生しました。SafeModeじゃなくても同じようにエラーになることは確認済み。

と、得意げにドヤ顔したところで、それはつまりDisconnectしなくなったからでしょ?と、おっしゃるとおりな理由でのエラーなんですけどね。つまり、Failoverした後もちゃんと接続が継続できるようにするために毎回Disconnectしてたわけですね。

あちゃー、これはどうしたものか。なんて、あたかも今、解決策を思いつくような振りになってますけど、事前に調査してわかってることを書いてるだけなんで...。てへ!

つまり今回のエラーの原因はPoolから取り出したMongoConnectionがPrimary(Master)を指してないから例外が起きるわけです。そして、MongoServer.Disconnectを呼ぶことでPoolのすべてのコネクションが破棄されるというのはソース見て確認済み。つまりMongoDBに対する処理で例外が発生したらMongoServer.Disconnectを呼び出し、処理をリトライすることで、Failover後に決定したNodeに接続するようにしてあげればよい、という方法が取れましょう。MaxConnectionLifeTimeを短くしてみては?っていうのもあるでしょうが短すぎると接続エラーになりそうだし。

で、用意したのが以下のようなリトライ実行するヘルパー。

public class MongoDbInvokeSetting
{
  public string ServerName { get; set; }
  public string DatabaseName { get; set; }
  public int RetryCount { get; set; }
  public int RetrySeconds { get; set; }
}

public class MongoDbHelper
{
  /// <summary>
  /// リトライを繰り返すInvoker
  /// </summary>
  /// <param name="setting"></param>
  /// <param name="functor"></param>
  public static void RetryInvoker(MongoDbInvokeSetting setting, Action<MongoServer> functor)
  {
    var retry = setting.RetryCount;
    Exception exception = null;
    while (retry > 0)
    {
      var server = MongoServer.Create(setting.ServerName);
      try
      {
        functor(server);
        break;
      }
      catch (MongoException ex)
      {
        exception = ex;
        // ↓こいつでPool内の全コネクションクリアが走るはず。
        server.Disconnect();
      }
      retry--;

      // とりあえずn秒待ってみる。
      Thread.Sleep(setting.RetrySeconds * 1000);
    }

    // ここでイベントログに書き出すか、Exceptionを出力する必要がある。
    // 後続の処理に進んだら困るならException。
    // ログなら進んでもいいかもねー。
  }
}

ダサくない!ダサくないよ!これでいいんだもん!

このコードを書いてる途中、さすがに心配になったんですけど(これでいいのかっていうね)、そんなおり以下のページを見つけました。

File: REPLICA_SETS — MongoRuby-1.4.1

似たようなリトライさせてますね。だもんで、いいってことで。

これを使って実行する書き方は↓こう。

MongoDbHelper.RetryInvoker(GetSetting(), server =>
{
  // serverを使ってCollection検索したり、
  // データ追加したり...
});

GetSettingは設定を入れたものを返しましょう。サーバー名とかリトライ回数とか。

これつかって丸っとしたもので、実行しつつFailoverさせてみます(abでエラーが出ないことを確認しました)。

ms8

大成功!エラーも起きずFailover成功しました。データも欠落なくいけてます。

で、この状態でのパフォーマスンスを測定してみます。

3回実行したのが485.62 / 496.92 / 552.61 平均:511.72

遅くなったじゃん!っていう感じしますけど、あったまって無かったみたい。実質Disconnect削除のパフォーマンスと同じ数値でした。

でも~、これだと~、なんていうかパンチが弱い。十分いいとは思うんだけど~。どこか早くできそうなところないかなー、とMongoSessionStateStoreのソースを見ているとありましたねー。

private string Serialize(SessionStateItemCollection items)
{
  using (MemoryStream ms = new MemoryStream())
  using (BinaryWriter writer = new BinaryWriter(ms))
  {
    ...
    return Convert.ToBase64String(ms.ToArray());
  }
}

private SessionStateStoreData Deserialize(HttpContext context,
string serializedItems, int timeout)
{
  using (MemoryStream ms =
    new MemoryStream(Convert.FromBase64String(serializedItems)))
  {
    ...
  }
}

ほら、ここ。Base64に変換してstringにしてるじゃないですか。コレいらなくない?BsonBinaryArray使えばbyte[]をそのまま入れることが出来るんじゃないのー?と、気になったので試した結果が↓こちら。

3回実行したのが 542.95 / 538.68 / 534.19、 平均:538.61。微妙...。まぁ、いいか。

ms9

ちなみにこのままだと、Expireしたセッション削除が残り続けるので、SetAndReleaseItemExclusiveの中で2000回に一回くらいクリーンアップするように仕込んでみました。その状態で10000回実行。

ms10

10000回中5回クリーンアップしてるけど、まぁまぁ。外部タスクにしてしまえば影響はでないものなので、ここはいいでしょう。

ち・な・み・に、SQLServerだと平均335.04ですからね。いいじゃないですか。ねぇ。Shardingしてみても同じマシンだとあまり変化でなかったです。と、いうのもCPUを最も使ってるのがIISExpressのプロセスだったので、アプリケーションが遅いってことですから。あとは、マシン分けて計測しかないですが、少なくとも同一環境内ではMongoDBでのSessionStateStoreがStateServerに負けないくらいの速度を実現しました(何度か試したらStateServerはもっと早かったけどー、そこは情報操作!)。