接続パフォーマンス
久しぶりのMySQLネタ．訳あってMySQLのJDBCドライバ（Type4）であるConnector/Jのソースを少し読んだ．
最近は「データアクセスの監査」というのも必要らしく，いつ誰が接続してどんなクエリを実行したのかのログを取る必要があるらしいのだ．結論から言うと，このための必要な情報出力機能をGeneral Log（一般クエリログ）が持っている．だが，このことに最初気づかなかったため，JDBCドライバにログを吐かせるのはどうだろうかと考えてConnector/Jのソースを眺めていたのだ．Connector/Jにログを吐かせるのは簡単．JDBCドライバとしての機能そのものを弄るわけじゃないんでね．ただ，一般クエリログがあるので別にログを吐かせる必要性は無い．DB接続ユーザ名じゃなくて，WEBアプリへのログインユーザ名が欲しいなら，その部分については別途アプリに吐かせる必要はある．
さて，話が脱線してしまったが，掲題の通りやってみた．実のところ，C言語でのMySQL接続パフォーマンス測定実験はやっていたのだけれども，Javaでの接続パフォーマンス測定実験はやっていなかった．諸事情があったのでね．
ただ，休日に自分で勝手に遊んでいただけなので制約が無かったのと，環境を作ったのでもったいないのでついでにやってみた．
環境
J2SE 1.4.2_04
MySQL 4.0.18 for Linux バイナリ配布版
JDBC Connector/J 3.0.14
ソースはこんな感じ．
package sample; import java.sql.DriverManager; import java.sql.Connection; public class MySQLJDBC { public static void main(String args) throws Exception { Class.forName("com.mysql.jdbc.Driver").newInstance(); String url = "jdbc:mysql://miracle.fam.cx/test"; String username = "ikeda"; String password = "password"; Connection con = null; int size = 50; long time= new long[size][2]; for (int i = 0; i < size; i++) { time[i][0] = System.currentTimeMillis(); con = DriverManager.getConnection(url, username, password); System.out.println(con); con.close(); time[i][1] = System.currentTimeMillis(); } long delta = new long[size]; long sum = 0; for (int i = 0; i < size; i++) { delta[i] = time[i][1] - time[i][0]; sum += delta[i]; System.out.println((i + 1) + " 回目 " + delta[i] + " ミリ秒"); } System.out.println("平均 " + sum/size + " ミリ秒"); } }
テストプログラム実行用クライアントとは別の筐体にあるMySQLサーバ（LAN内）に対して「接続→切断」を繰り返すだけ．その都度，時間計測を行ってとりあえず配列に突っ込んでおき，後で結果を出す．以前Cで書いたのもこれと似たような構造．
以前やったときはシングルスレッドの反復だけじゃなくて，マルチスレッド同時アクセス（バースト）のテストもやったので「よーいどん」で開始するように書いたりもしたけど，とりあえず今回は単純な繰り返し．（ちなみに，マルチスレッド同時アクセスの方が，合計時間は短いです．）
結果は以下．
1 回目 240 ミリ秒 2 回目 10 ミリ秒 3 回目 10 ミリ秒 4 回目 0 ミリ秒 5 回目 10 ミリ秒 6 回目 20 ミリ秒 7 回目 0 ミリ秒 8 回目 10 ミリ秒 9 回目 10 ミリ秒 10 回目 0 ミリ秒 11 回目 20 ミリ秒 12 回目 10 ミリ秒 13 回目 10 ミリ秒 14 回目 0 ミリ秒 15 回目 10 ミリ秒 16 回目 10 ミリ秒 17 回目 10 ミリ秒 18 回目 0 ミリ秒 19 回目 10 ミリ秒 20 回目 0 ミリ秒 21 回目 10 ミリ秒 22 回目 0 ミリ秒 23 回目 10 ミリ秒 24 回目 0 ミリ秒 25 回目 10 ミリ秒 26 回目 0 ミリ秒 27 回目 10 ミリ秒 28 回目 0 ミリ秒 29 回目 10 ミリ秒 30 回目 0 ミリ秒 31 回目 10 ミリ秒 32 回目 0 ミリ秒 33 回目 10 ミリ秒 34 回目 0 ミリ秒 35 回目 10 ミリ秒 36 回目 0 ミリ秒 37 回目 10 ミリ秒 38 回目 0 ミリ秒 39 回目 11 ミリ秒 40 回目 0 ミリ秒 41 回目 10 ミリ秒 42 回目 0 ミリ秒 43 回目 10 ミリ秒 44 回目 0 ミリ秒 45 回目 10 ミリ秒 46 回目 0 ミリ秒 47 回目 10 ミリ秒 48 回目 10 ミリ秒 49 回目 0 ミリ秒 50 回目 0 ミリ秒 平均 10 ミリ秒
初回呼出しが240ミリ秒かかってる．さすがJava．Connector/Jのソースを見ればわかると思うけど，初回呼出しは処理が重い．
驚くべきはその後．System.currentTimeMillis()の精度があまり良くないので0ミリ秒とかも出てるけど，最後の平均値を見れば大体分かる．50回の試行だと平均10ミリ秒と出ている．
ただ初回を除いて考えると大体平均5ミリ秒だと思う．試行回数を200回に上げたら平均7ミリ秒，1000回に上げたら平均5ミリ秒と出た．
ちなみに，C言語で直接呼び出した時は1ミリ秒だった．同じくC言語で某商用（プロプラエタリ）DBへ接続させたときは170ミリ秒だっけな．どちらもコネクションプーリングを使わない場合の数値ね．MySQLにコネクションプーリングは不要というわけで．
今回のConnector/Jによる実験もコネクションプーリングは使っていない．初回が240ミリ秒でそれ以降が5ミリ秒なのは，オブジェクトの生成コストがでかいというのと2回目以降はそのオブジェクトが再利用されているということであって，コネクションプーリングとは関係無し．
一般クエリログを見ると，ちゃんと50回接続に来ている．ちなみに，Javaで1回の接続あたり5ミリ秒かかった（C言語の5倍）というのには明快な理由がある．まず以下をご覧アレ．
Time Id Command Argument
040906 23:20:52 1 Connect ikeda@192.168.11.31 on test
1 Init DB test
1 Query select round('inf'), round('-inf'), round('nan')
1 Query SHOW VARIABLES
1 Query SET autocommit=1
1 Quit
2 Connect ikeda@192.168.11.31 on test
2 Init DB test
2 Query select round('inf'), round('-inf'), round('nan')
2 Query SHOW VARIABLES
2 Query SET autocommit=1
2 Quit
これは一般クエリログの一部だけど，ConnectしてからQuitするまでの間で，合計6つもコマンドを実行している．C言語での実験のときはコマンドはConnectのみ行うようにして計測していたのでその分計測結果が短くなる．切断するときはQuitだけなんだけど，接続するときにコマンドを5つも飛ばすのは，Connector/Jの仕様のようである．
まあ要するに，JDBC（Type4)でのMySQL接続も，凄く早いということで結論にして良いかなと思う．
実はConnectionオブジェクトを再利用しているんじゃないの？とか思われる方もいるかもしれない．というか自分もその線を勘ぐったので，getConnection()で取得したConnectionオブジェクトのハッシュコードを調べてみたけど，ハッシュ値は毎回異なっていた．
JDBC接続が重いという印象（先入観）があるのは，Connectionオブジェクトの生成コストがでかいから，という理由からだったと認識しているのだけど，Connector/Jの開発者はそこを上手く作ったみたいだね．以前dev.mysql.comに掲載されていたConnector/Jの開発者による記事に，プーリングやってるよ，と書いてあったのはもしかしてこのことだったのかな?
最後に感想．何ていうか，人に頼らずに，自分の手で直接調べてみると，毎回意外な発見があったりして楽しい．MySQLにしろJBossにしろ，オープンソースはこれだから面白い．
そんなわけで，久々のMySQLネタでした．
