Spring＋HibernateEntityManager（DBCPのvalidationQuery編）

今回は、Spring＋HibernateEntityManager（AspectJ AOP with Load-Time-Weaver編）の続きです。

コネクションタイムアウトのハンドリング忘れてた(^^;

以前、beans.xml に DBCP の設定は行いましたが、コネクションタイムアウト対策を忘れていました。

おいらは DB に MySQL を使用しているのですが、MySQL はデフォルトでは 8 時間でコネクションがタイムアウトするようになっています。そうすると、コネクションプールからコネクションを取得しても、それがタイムアウトしているという悲しいことになります。(´･ω･`)

Connector/J の autoReconnect は、おいら的には非推奨。

Connector/Jのマニュアルには、非推奨と書かれてます。

おいら的にも、めんどくさいことこのうえないので、使わないほうが良いと思う今日この頃。

そもそも、コネクション切れたらリコネクトよりも、切れてないものを使おうよ。

タイムアウト実験

ということで、実験してみます。

以下のようにテストしてみました。

デバッガで、コネクションを使う直前でとめる。
時計を８時間進める。
プログラムを再開する。

validationQuery 設定なしの場合

７時間時計を進めるテスト。

８時間という数字の妥当性を確認するために、ひとまず７時間時計を進めてテストしてみた。

．．．問題なくテストは動作しました。

８時間時計を進めるテスト。

こんなエラーが出ました。

Exception in thread "main" javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: could not insert: [domain.entity.UserImpl]
	at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:637)
	at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:226)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:194)
	at $Proxy17.persist(Unknown Source)
	at domain.service.UserServiceImpl.doRegisterUser(UserServiceImpl.java:45)
	at domain.service.UserServiceImpl.registerUser(UserServiceImpl.java:22)
	at application.Main.main(Main.java:40)
Caused by: org.hibernate.exception.JDBCConnectionException: could not insert: [domain.entity.UserImpl]
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:74)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
	at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:40)
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2163)
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2643)
	at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:51)
	at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
	at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:298)
	at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:181)
	at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:107)
	at org.hibernate.ejb.event.EJB3PersistEventListener.saveWithGeneratedId(EJB3PersistEventListener.java:49)
	at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:131)
	at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:87)
	at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:38)
	at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:618)
	at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:592)
	at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:596)
	at org.hibernate.ejb.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:220)
	... 9 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

Last packet sent to the server was 0 ms ago.
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
	at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1074)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2985)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2871)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3414)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1936)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2536)
	at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4874)
	at org.apache.commons.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:331)
	at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:317)
	at org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy$LazyConnectionInvocationHandler.getTargetConnection(LazyConnectionDataSourceProxy.java:405)
	at org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy$LazyConnectionInvocationHandler.invoke(LazyConnectionDataSourceProxy.java:364)
	at $Proxy15.prepareStatement(Unknown Source)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.hibernate.util.GetGeneratedKeysHelper.prepareStatement(GetGeneratedKeysHelper.java:49)
	at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:495)
	at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:94)
	at org.hibernate.id.IdentityGenerator$GetGeneratedKeysDelegate.prepare(IdentityGenerator.java:69)
	at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:30)
	... 24 more
Caused by: java.net.SocketException: Software caused connection abort: recv failed
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
	at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
	at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2428)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2882)
	... 44 more

やはり、８時間の監視をしてるっぽいですね。
（めんどいので、今はソースレベルでの確認はしないことにするｗ）

validationQuery 設定ありの場合

８時間進めても、問題なく動作しました。（さらに１日進めても問題なく動作しました）

以下、SQL ログ。

SELECT 1
SET autocommit=0
insert into User (name) values ('Kumapiyo_0')
commit
SET autocommit=1

以下、beans.xmlの設定抜粋

<!-- Actual DataSource -->
<bean id="rawDataSource" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close">
  <property name="driverClassName" value="com.mysql.jdbc.Driver" />
  <property name="url" value="jdbc:mysql://localhost:3306/test" />
  <property name="username" value="root" />
  <property name="password" value="" />
  <property name="validationQuery" value="SELECT 1" />

  <!-- for optimization
  <property name="initialSize" value="10" />
  <property name="maxIdle" value="10" />
  <property name="minIdle" value="10" />
  <property name="maxActive" value="20" />
  <property name="maxWait" value="100" />
  -->

  <!-- Don't use the following properties because of introducing extra complexity
  <property name="testWhileIdle" value="true" />    
  <property name="timeBetweenEvictionRunsMillis" value="60000" />
  -->
</bean>

性能テスト

validationQuery を用いた場合、DataSource から取得したコネクションを安心して使えるようになる反面、コネクションとるたびに、毎回 "SELECT 1" のようなクエリを吐くというのも、結構性能的にキビシイかもしれないと思う今日この頃。

ということで、validationQuery あり版となし版の性能比較をしてみました。

テスト環境

テスト環境は、以下のような感じです。（スゲーやる気なさそーな環境ｗ）

おいらのノートPC(ThinkPad X60s)
Eclipse上からテストを実行
テストのベースは、前回までの環境。
MySQLは同一PC上。
MySQLのクエリログはON。

テストプログラムの抜粋

long startTime = System.currentTimeMillis();
for (int i = 0; i < 10000; i++) {
    
    // User を新規作成
    User user = userService.newUser();
    user.setName("Kumapiyo_" + i);
    
    // User を DB に保存。
    userService.registerUser(user);
    
}
System.out.println("Time : " + (System.currentTimeMillis() - startTime));

validationQuery なし版

１回目のトランザクションの SQL

SET autocommit=0
insert into User (name) values ('Kumapiyo_0')
commit
SET autocommit=1

３回実行した結果
Time : 46656 ms
Time : 46344 ms
Time : 47125 ms

- - - - -

avg. : 46708 ms

validationQuery あり版

１回目のトランザクションの SQL

SELECT 1
SET autocommit=0
insert into User (name) values ('Kumapiyo_0')
commit
SET autocommit=1

３回実行した結果
Time : 52610 ms
Time : 52031 ms
Time : 51297 ms

- - - - -

avg. : 51979 ms

考察

ということで、validationQuery で 'SELECT 1' を発行するオーバーヘッドは、上記のサンプルでは約11%です。

この設定を行うことにより、DBが正常に動作しているかつDBの負荷が飽和していない状態である限り、コネクションタイムアウトの例外はほぼ防げるといってよいと思います。

性能的には、11%のオーバーヘッドは結構大きいと考える人が多いかもしれません。しかし、おいら的には、「少し高いハードウェア買えばいいじゃん」と思います。

これしきのオーバーヘッドを嫌って validationQuery を使わないという選択肢をとると、結局、テストフェーズや運用フェーズで、割に合わないコスト（金額や社会的信用等）を支払うことになりますカラ。

同様の理由から、timeBetweenEvictionRunsMillis 等のオプションも、おいら的には推奨しません。効率はよいと思いますが、システムとしての複雑さの増加に見合う価値があるとは考えられません。（と、おいらは思う。）

メモ

spring-hibernateentitymanager-test-007.zip

links