今日もまた踏みました

非定期更新:主に何とも言えない事態にあった際に更新しています

C# から SSH を使って MySQL を使う時に MySQL への再接続が遅いという事案が発生

とりあえず結論を知りたいという技術者の方へ

ConnectionString に下記を加えて変化が無ければここに答えはありません
頑張って次を探してください

Pooling=False

これで解決したものの上司への説明が欲しい場合は…

MySQL Connector / Net は IIS などで利用する事を前提にしているのか、Connection Pool  の機能が標準で ON になっている。そのため、MySQL をクローズしたのみでは切断されておらず、再接続の時にポートの解放待ちが発生するため、結果として再接続が遅くなる

とダメ元で言ってみてください…

 

開発ツールと利用ライブラリ

今回は下記を利用して問題が発生しました
Visual Studio 2010
SSH : SSH.NET Library - Home
MySQL : MySQL :: Download Connector/Net

 

本題はここから

お客様より、こちらで作成したアプリが「お昼休みに手を放してると午後に登録しようとするとエラーで落ちるんだよね」と言われた

MySQL を利用している WEB システムのメンテナンスプログラムを C# で拵えて利用して頂いていたのだが、お客様より上記のような話があがってきた
仕方ないので修正を加える事となったのだが、今回は SSH を利用して MySQL へ接続するという仕組みとなっていた。落ちているのは SSH なのか MySQLなのか…そこから考えなければならないのだが、そんなに頻繁にアクセスする類でもないので、検索や登録などのボタンアクションの開始で接続し、終了で切断する様に修正を加えた

結果、検索を 2 回連続でクリックしたら 2 回目が異常に遅いという現象が発生した

ちょっとトレースしてみたところ、再接続のタイミングで謎のウェイトが発生している事がわかった。そう言えば誰かがそんな現象が出るって言ってた気がする…
という事で追跡の旅は始まる

切断したのに切断されないという現象

MySqlConnection にて作成された connection に対して Close() と Dispose() を呼び出したが MySQL 側でウォッチしている限り切断されていない
何か切断手順が間違っているのかなとリファレンスをなめるが、それらしき答えは発見できなかった

今回は SSH 経由で接続してる事もあり、何か意外な事実があるのではと、SSH 側も調査を開始、まずはポートフォワードを行うための ForwardedPortLocal の切断処理をチェック Stop() を呼べている。だが MySQL は切断されない

それではと、SSH の切断も確認する。 Disconnect() と Dispose() を呼べている。だが MySQL は切断されない

Dispose してるから普通に考えたらありえないけど、オブジェクト生きてたりするのかなと、接続と切断の部分を中心に、ソースコードを洗い直してみたが、それらしき場所は見つからなかった

諦めて実証実験用のソースコードを作成

プログラム本体では、想定外の事があってもわかりにくいので、SSH 経由で MySQL へ接続するだけのサンプルを作成し、それを使って再現するかの実験を開始した

こんな感じで作成した

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using Renci.SshNet;
using MySql.Data.MySqlClient;

namespace SSHTest
{
    class Program
    {
        static void Main(string[] args)
        {
            SshClient client = null;
            try
            {
                string host = "192.168.xxx.yyy";
                int port = 22;
                string user = "user";
                string sshPasswd = "password";
                string keyFile = @"keyfile.idrsa";

                PrivateKeyFile pkfile = new PrivateKeyFile(keyFile, sshPasswd);
                client = new SshClient(host, port, user, pkfile);
                client.Connect();

                uint dbPort = 3306;
                string server = "127.0.0.1";
                uint localPort = 13306;
                string dbUser = "dbuser";
                string dbPassword = "dbpassword";
                string dbName = "dbname";

                ForwardedPortLocal forward = new ForwardedPortLocal(server, localPort, "127.0.0.1", dbPort);
                client.AddForwardedPort(forward);
                forward.Start();  // ①

                var connectStr = "server=" + server + ";";
                connectStr += "port=" + localPort.ToString() + ";";
                connectStr += "user=" + dbUser + ";";
                connectStr += "password=" + dbPassword + ";";
                connectStr += "database=" + dbName + ";";

                var connection = new MySqlConnection(connectStr);
                connection.Open();  // ②

                connection.Close();  // ③
                connection.Dispose();  // ④
                forward.Stop();  // ⑤
                client.Disconnect();  // ⑥
                client.Dispose();  // ⑦
                Environment.Exit(0);  // ⑧
            }
            catch (Exception e)
            {
                Console.WriteLine(e.Message);
            }
        }
    }
}

結果… MySQL は切断されなかった
何か根本的な所に原因があるらしい

実際はこんな感じに動く

この仕組みの特徴的な所だが、SSH の接続完了後に ForwardedPortLocal がポートフォワードするために Listen する
今回は、127.0.0.1:13306 となる。MySQL Connector は、そのサーバー及びポートに対して接続を実施する。そのため接続先は 127.0.0.1:13306 となる

①の部分、「forward.Start(); 」を通ると、Forwardの準備が開始され
TCP 127.0.0.1:13306 0.0.0.0:0 LISTENING
となり、Listen される

②の部分、「connection.Open();」を通ると、MySQL へ接続され
TCP 127.0.0.1:13306 0.0.0.0:0 LISTENING
TCP 127.0.0.1:13306 127.0.0.1:zzzzz ESTABLISHED
となり、MySQLへの通信が開始される

③、④の MySQL に対する終了処理を実施しても変化なし
TCP 127.0.0.1:13306 0.0.0.0:0 LISTENING
TCP 127.0.0.1:13306 127.0.0.1:zzzzz ESTABLISHED

⑤の ForwardedPortLocal に対する停止処理を実施すると、Listenが終了し、
TCP 127.0.0.1:13306 0.0.0.0:0 LISTENING
TCP 127.0.0.1:13306 127.0.0.1:zzzzz FIN_WAIT_2
となる
この状態から⑥に移るまで、こちらの環境では30秒ほど必要だった

⑥の時点ではもうポートは閉じていた
TCP 127.0.0.1:13306 0.0.0.0:0 LISTENING
TCP 127.0.0.1:13306 127.0.0.1:zzzzz FIN_WAIT_2

⑦の Disconnect だが、ForwardedPortLocal を Dispose してしまうと落ちてしまうので、ForwardedPortLocal のDisposeを行わずに SSH Client を Disconnect した

ここで再確認できたのは、ForwardedPortLocal の Stop は Listen の終了だったらしく、それまでの接続を強制的に切断する事ではなかったらしい
また、時間がかかるポイントは、MySQLの切断ではなく、SSH で利用してる Forward ポートの解放だったようだ。切断の処理などを雑に作成していると再接続を行った際に待ち時間が発生するという理屈のようだ

本体のプログラムで感じた挙動と違うのは、本体側に接続ポートを転がす仕組みを入れていたためだった(ポートが握りっぱなしになる話を聞いて、この処理を入れたのだった…時間無かったんだよ…)。やはり再現確認用プログラムを作る習慣は大事だ

MySQL だけの再接続は実は早かった

今回の問題が発生した理由は、SSH までクローズしてしまっていた事だろう。ForwardedPortLocal を Stop せずに、そのまま MySQL を再接続する分には問題無く再接続できた
なら MySQL の再接続で問題無いじゃないとなる所なのだが、そうもいかない
切断されたのが SSH なのか MySQL なのかのハンドリングができなかったからだ
できなかった(方法が見つからなかった)ので、ボタンアクションで再接続という方向にシフトした。けど SSH ごと切断→再接続すると遅い。まだ何も解決していなかった

MySQL 側の設定を再確認

そもそもの所に頭を戻す。そう、そもそも③(Close)か④(Dispose)の時点で MySQL が切断されていないのが気持ち悪い。Dipose してるのに消えないとか何者よ…と思いながらリファレンスを参照し、設定項目の漏れを探す
ない、全然見つからない。そもそも設定できる項目少ないんだよね。この子
他に何か無かったっけと思い、Connection String にも設定項目がある事を思い出して、MySQL Connector で利用できる設定項目を眺める

MySQL connection strings - ConnectionStrings.com

ここのサイトを眺めていたら、とても気になる一文を発見
「Recycle connections in pool」
ようやく攻略の糸口を見つけた。クライアントアプリケーションとして作成していたので、完全に頭から離れていたが、そんな人居たよね Connection Pool さん
もしかしてデフォルトで ON になってるの?と思い、OFFにする設定を探す

有りました「Pooling=False」試しに入れてみるとようやく狙った通りに動いた

ありがた迷惑な感じではあるけれど、サーバーで利用する事を考えれば、接続を再利用する設定がデフォルトなのは当たり前と言えば当たり前なのか
SSH 経由の場合に、Forward ポートを握りっぱなしにされて困るとか、レアケースよね。けどまあ、実例のサイトも多いので、それなりに使ってる人居ると思うけど

とりあえず MySQL Connector をサーバーで使わない時は、Pooling=False を入れると頭に刻んだ