MySQL + Dapperによる高負荷時のバグで死んだ話

今回はMySQLとDapperを組み合わせると死ぬ、という超極少数にしか該当しない話ですよ！というわけで、まぁ読み物としてどーぞ。ちなみに割とクリティカルなので、その組み合わせで何かやろうという人は気をつけたほうがいいです。

観測

何が起こるかの観測からはじめましょう。まず、NuGetからMySQL.DataとDapperをインストールして、以下の簡単なコードを走らせ、ません。コード書いて待機で。

using Dapper;
using MySql.Data.MySqlClient;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
 
class Program
{
    static void Main(string[] args)
    {
        // スレッドプールを先に伸びるように
        ThreadPool.SetMinThreads(200, 200);
        var count = 0;
 
        // とりあえず200並列で実行する
        Parallel.For(0, 10000, new ParallelOptions { MaxDegreeOfParallelism = 200 }, () =>
        {
            var conn = new MySqlConnection("せつぞくもじれーつ,Max Pool Size=1000");
            conn.Open();
            return conn;
        }, (x, state, conn) =>
        {
            System.Console.WriteLine(Interlocked.Increment(ref count));
 
            // ↑や↓にグチャグチャありますが、実態はこの一行だけです
            conn.Query<long>("select 1", buffered: false).First();
 
            return conn;
        }, conn =>
        {
            conn.Dispose();
        });
    }
}

Parallelなのは高負荷じゃないとイマイチ分からないので、そのシミュレートね。これも別にそこまで高負荷ってわけでもないですが、まぁこんなんでいいのです（原因分かってて逆算して書いてるので）。接続文字列は、とりあえず200並列に耐えられるようにMaxPoolSizeだけ大きめに設定しておきます。さて、そしてPowerShellを立ち上げ、とりあえず以下のスクリプトを走らせておきます。

 while ($true) {Get-NetTCPConnection | group state -NoElement; sleep 1}

で、上のC#コードを実行。すると、実行は、遅いです。Parallelなので速いのか遅いのかわからないかもですが、まあぶっちけ凄く遅いです。正常状態ならサクッと終わるのですが、↑のはかなりもたついてます。で、運が良ければ以下の例外にも遭遇するでしょう。時には完走するかもしれませんが。

ハンドルされていない例外: System.AggregateException: 1 つ以上のエラーが発生しました。
---> MySql.Data.MySqlClient.MySqlException: Unable to connect to any of the specified MySQL hosts.
---> System.Net.Sockets.SocketException: そのようなホストは不明です。

よくわからないけどSocketExceptionで死にますね！！！さて、PowerShellのほうはどうなっていたか、というと、

ぎゃー、TIME_WAIT祭だー。って、Parallelだからそうなったんじゃないかって？いえいえ、所詮200並列ですし、ある程度はOpen/Close繰り返されるとはいえ、4000個もコネクション作ったりなんてしないです。ていうかそもそもコネクションプールあるんだから、そんなに繋ぐわけないでしょーが。

つまり、どういうことだってばよ？シンプルな例にしましょうか。

using (var conn = new MySqlConnection("せつぞくもじれーつ"))
{
    conn.Open();
    for (int i = 0; i < 100; i++)
    {
        conn.Query<long>("select 1", buffered: false).First();
    }
}

はい。100のループで100のTIME_WAITが発生しています。つまり、1クエリにつき1TIME_WAITです。ほへ……？ということは、低負荷時はそれでも生きてられるかもですが、高負荷時は、最初の例で見たように、山のようなTIME_WAITに見舞われます。そしてsocketは枯渇する。そして死ぬ。

何故こうなるのか

何故、の前にどの組み合わせでなるか、というと、現時点での最新のDapper(1.13)で、Queryをbuffered:falseで、FirstなどReaderの列挙を完了させないもの(ToListとかなら大丈夫)で確定させると詰みます。じゃあまあ、原因にDeepDive。

キーになるコードは、Dapperのこのメソッドです。

private static IEnumerable<T> QueryInternal<T>(this IDbConnection cnn, string sql, object param, IDbTransaction transaction, int? commandTimeout, CommandType? commandType)
{
    var identity = new Identity(sql, commandType, cnn, typeof(T), param == null ? null : param.GetType(), null);
    var info = GetCacheInfo(identity);
 
    IDbCommand cmd = null;
    IDataReader reader = null;
 
    bool wasClosed = cnn.State == ConnectionState.Closed;
    try
    {
        cmd = SetupCommand(cnn, transaction, sql, info.ParamReader, param, commandTimeout, commandType);
 
        if (wasClosed) cnn.Open();
        reader = cmd.ExecuteReader(wasClosed ? CommandBehavior.CloseConnection : CommandBehavior.Default);
        wasClosed = false; // *if* the connection was closed and we got this far, then we now have a reader
        // with the CloseConnection flag, so the reader will deal with the connection; we
        // still need something in the "finally" to ensure that broken SQL still results
        // in the connection closing itself
        var tuple = info.Deserializer;
        int hash = GetColumnHash(reader);
        if (tuple.Func == null || tuple.Hash != hash)
        {
            tuple = info.Deserializer = new DeserializerState(hash, GetDeserializer(typeof(T), reader, 0, -1, false));
            SetQueryCache(identity, info);
        }
 
        var func = tuple.Func;
 
        while (reader.Read())
        {
            yield return (T)func(reader);
        }
        // happy path; close the reader cleanly - no
        // need for "Cancel" etc
        reader.Dispose();
        reader = null;
    }
    finally
    {
        if (reader != null)
        {
            if (!reader.IsClosed) try { cmd.Cancel(); }
                catch { /* don't spoil the existing exception */ }
            reader.Dispose();
        }
        if (wasClosed) cnn.Close();
        if (cmd != null) cmd.Dispose();
    }
}

色々ありますが、while(reader.Read())以下の部分だけを見ればOKです。ToListなら大丈夫でFirstだとダメな理由もここにあります。ToListの場合、Readerが全て読むので、コード上にコメントでhappy pathと書いてある、reader.Disposeが呼ばれます、そしてfinallyでは何もしない。逆にFirstの場合は、最初のyield returnで打ち切られてfinallyへ向かうので、cmd.Cancel()が呼ばれた後に、reader.Disposeが呼ばれます。

そう、ここです。reader.Disposeの前にcmd.Cancelが呼ばれる、というのが、非常にマズい。少なくともMySQL Connectorにおいては。MySQL ConnectorのCommmand.Cancelの実装を見てみましょう。あ、MySQL Connectorのソースコードはちゃんと公開されています、Download Connector/NetのSelect PlatformでSource Codeを選べば落とせます。zipで。リポジトリは、多分公開されてない、残念ながら……。

さて、Command.Cancelは以下のメソッドを呼び出します。

public void CancelQuery(int timeout)
{
    MySqlConnectionStringBuilder cb = new MySqlConnectionStringBuilder(Settings.ConnectionString);
    cb.Pooling = false;
    cb.AutoEnlist = false;
    cb.ConnectionTimeout = (uint)timeout;
 
    using (MySqlConnection c = new MySqlConnection(cb.ConnectionString))
    {
        c.isKillQueryConnection = true;
        c.Open();
        string commandText = "KILL QUERY " + ServerThread;
        MySqlCommand cmd = new MySqlCommand(commandText, c);
        cmd.CommandTimeout = timeout;
        cmd.ExecuteNonQuery();
    }
}

どういうことか。「新しいコネクションをコネクションプーリングなしで新規生成して」「KILL QUERY実行して」「コネクションを閉じる」。KILL QUERYはどうでもいいんですが、新しいコネクションをプーリングなしで作って閉じるということがどういう結果をもたらすか。一回のクエリ毎に↑のが実行されるとどうなるか。まず、遅くなる。そりゃ遅いわな、1クエリ毎に1接続＆切断してるんだもの。そして、1クエリ = 1TIME_WAIT。完全にコードは書かれたとおりに動いて書かれるとおりの結果しか出てこない。素晴らしい。泣ける。

どうすればいいのか

これ、1.12 ~ 1.13の間に加えられた変更が原因です。具体的にはIssue 106で、SQL ServerだとTimeoutException出るから、reader閉じる前にcommandのCancel呼んで欲しいんだよねー、というパッチが受け入れられたのでした。その結果、MySQLだと死ぬことに。

なので、1.12を使えば問題は起こりません。もしくは1.13だったら、手動でソースコードに修正を加えればいいでしょう。もともとDapperはソースコードが1ファイルなので、NuGet経由ではなく、最新のコードをファイルで持ってくれば、編集は楽です。

ちなみに、この件はDapperのForumでは報告済みです。一ヶ月前に。そして返事はありません。みょーん。まあ、あと究極的にはSQL ServerをとるかMySQLをとるか、になるので、どうなんでしょうね、あんま期待は持たないほうがいい気もします。

おまけ、MySQL Connectorのコネクションプールについて

MySQL Connectorのコードは結構素朴なので、読みやすいです(MSのSqlServerのに比べると遥かに！)。というわけで、つらつら読んでみるといいんじゃないでしょーか。参考になったりゲッソリしたり色々です。

というわけでコネクションプールとかがどうなってるかの説明しませう。そしてそれぞれが接続文字列のオプションでどう弄れるのかについて。接続文字列でのオプションの設定は結構重要ですからね、失敗してると死にますから。何度か死にましたから……。接続文字列のリファレンスはこちらConnector/Net Connection String Options Reference。古いもの（日本語訳されてる！）だけを参照すると時々痛い目に会うので適度に注意。

さて、まず、MySqlConnectionをnewすること自体は全然軽くて（ただの入れ物なので）じゅーよーなメソッドはOpenとCloseです。OpenするとコネクションプールからDriver（これが本当の実態でプールするもの）を取り出します。CloseするとコネクションプールにDriverを戻します。これが基本的なこと。ちなみにプールはQueueです、なのでDriverは先入れ先出しで循環してます。

プールということは、一度生成したコネクションはいつ消えるの？というと、Closeする時です。Close時にExpireしているかチェックし、してれば消滅、してなければプールへ。基準時間は 「接続が最初に作られた時」です。そのExpireの時間はどこで設定するの？というと接続文字列のConnection Lifetime。ちなみにデフォルトは0で、Close時には消滅しません。 なお、コネクションの最大プール数も接続文字列で指定できて、そのMax Pool Sizeのデフォは100です。

実際のところ、Close時以外にもコネクションが消える時があります。3分に一回、アイドル状態の接続がチェックされて(Timerで別スレッドで常に巡回されてる)、その時に、3分以上、プールに溜まったままのコネクションはお掃除されます。基準時間は「接続がプールに戻された時」です。Connection Lifetimeと基準が違うんですね。

Open/Closeを繰り返すことのロスは、上記のようにプールから取り出したり戻したり程度なので、かなり小さいです（一応、取り出したりする際にプールをlockしますが、全然小さいので無視できるでしょう）。あと、一応Open時にサーバーが生きてるかPingを飛ばします(この動作はビミョーだと思うんですけどねえ)。プールのlockよりも、コスト的にはこっちのほうが大きいかもですね。

あと他に接続文字列だと、Connection TimeoutとDefaultCommandTimeoutを弄っておくと幸せになれるでしょふ。

DefaultCommandTimeoutで設定できるコマンドタイムアウトはExecuteNonQueryやExecuteReaderで最初のレスポンスが戻ってくるまでの時間ではかられます。だから、ExecuteReaderでも、例えば数億件のデータがあって凄く時間がかかるものでも、反応はかえって来てるのでそこでのTimeout判定は入りません。レコード数よりも、純粋なSQLの内容(馬鹿でかいデータにlikeで検索とかは引っかかりますよね)のためのものです。

Connection Timeoutは、実はコネクションをOpenにする時、だけに関連してるわけじゃあなかったりします。streamからReadする際の時間でもConnectionStringsのConnect Timeoutで判定があります。この値を流用されるのイマイチ納得いかない気がしなくもないですが、まあそんなもんですかねえ。なので結果セットを読み込んでる最中でもネットワークの調子が悪くて止まると、タイムアウト判定が来ます。Raedの単位はデータセット全て、ではなく1行分とか、そういう特定バイト数ごとになるので、巨大データを読み取るのに時間がかかるので死ぬ、とかにはなりません。一応参考までにってとこですかね。

まとめ

このDapperで死ぬ問題、プロダクション環境化で発覚したんですよね！！！分かってみると割と単純なのですが、しかし条件が変則的で突き止めるのに手間取って泣きたかった……。低負荷だと割と動いちゃうというか、そこそこの負荷でも割と耐え切れちゃう(IIS偉い)ので、全然気づかず。なんか分からないけど超高負荷の時に落ちる！とか、ね。ワケワカラナカッタ。まず疑うのは自分のコードのほうだしねえ。

まぁ、解決してほんと良かったです、はい。解決しなかったら首吊るしかなかったですもの、思い出すだけでハイパーお通夜。冗談抜きに今までの人生で一番精神的に苦しかった……。そんな感じで若干トラブルもありましたが、それを除けばDapperはパワフルでかなり満足しています。少々、上モノを被せているので、その辺のものはそのうち紹介しましょうかしらん。