JDBCRunnerメモ

2012.04.15追記
　id:sh2さんよりコメントいただきまして、Solaris版Javaの場合のお話とのことでした。
　-XX:-UseVMInterruptibleIO を起動引数につけることで他OSと同様の割り込み挙動にできるそうで、
　実際に設定したところ回避することができるようになりました。
　まだまだ勉強が足りない…。

DB性能測定するためにsh2さん（http://d.hatena.ne.jp/sh2/）作のJDBCRunnerを最近使おうとしています。
いろんなDBに対応してますし、elapsや度数分布データが出るとかとっても使い勝手が良いです。

Oracle向けに試していたら実行終了時のAgentスレッド停止時に
　「java.sql.SQLRecoverableException: IO Error: Socket read timed out」
が稀に発生する事象に出くわしたのでメモです。
※Agents数を増やせば増やすほど起きやすくなります。（当然ですが）

なお、Agentスレッドを停止させる際に運悪く通信 read 中だった場合に発生するようです。
マニュアルにはない、PL/SQLプロシージャをcallするシナリオの為に起きるのか、
OS・Java環境依存で起きるのかといった切り分けまでは行っていません。
悪い対処ですが Script.java で SQLRecoverableException を throw させずに無視させてとりあえず動かしています。

■動作環境

　OS：x86 Solaris10 update7（JDBCRunner/Oracleともに）
　java：jdk1.6.0_31（update31）
　JDBCドライバ：OracleDatabase 11.2.0.3.0版

■DB側定義

 CREATE USER hoge
 IDENTIFIED BY hoge
 DEFAULT TABLESPACE USERS
 TEMPORARY TABLESPACE TEMP
 QUOTA UNLIMITED ON USERS ;

 grant execute on sys.dbms_crypto to hoge ;
 grant SELECT ANY DICTIONARY TO hoge;
 GRANT CREATE SESSION TO hoge;
 GRANT CREATE VIEW TO hoge;
 GRANT CREATE TABLE TO hoge;
 GRANT CREATE SYNONYM TO hoge;
 GRANT CREATE SEQUENCE TO hoge;
 GRANT CREATE PROCEDURE TO hoge;
 GRANT CREATE TYPE TO hoge;

 connect hoge/hoge
 create table elaps (ses varchar(20), key number, ins timestamp , upd timestamp ,shinario varchar(30));
 alter table elaps add constraint pk_elaps primary key(ses,key) using index ;
 create or replace PROCEDURE hoge.LoggingElaps (
  in_ses in varchar2,
  in_key in number,
  in_shinario in varchar2
 ) IS
 BEGIN
  insert into elaps values(in_ses,in_key,systimestamp,systimestamp,in_shinario) ;
  update elaps set upd = systimestamp where ses=in_ses and key = in_key and shinario = in_shinario ;
 END;
 /

■JDBCRunnerテストスクリプト

 var jdbcUrl = "jdbc:oracle:thin://@xxx.xxx.xxx.xxx:xxxx/xxxx";

 var jdbcDriver = "";
 var jdbcUser = "hoge";
 var jdbcPass = "hoge";
 var isLoad = false;
 var warmupTime = 3;
 var measurementTime = 3;
 var nTxTypes = 1;
 var nAgents = 10;
 var connPoolSize = nAgents;
 var stmtCacheSize = 10;
 var isAutoCommit = false;
 var sleepTime = 0;
 var throttle = 0;
 var isDebug = false;
 var isTrace = false;
 var logDir = ".";

 // Application settings ----------------------------------------------
 var counter = 0;
 var agentnum ;


 function init() {
  if (getId() == 0) {
    // This block is performed only by Agent 0.
  }
 }

 function run() {
  agentnum = getId();
  ++counter;
  execute("call LOGGINGELAPS($int,$int,'test')",agentnum,counter);
  commit();
 }

 function fin() {
  if (getId() == 0) {
      // This block is performed only by Agent 0.
  }
 }

 22:21:05 [ERROR] An exception occurred at agent 0
 jdbcrunner.ApplicationException: An exception occurred while accessing the database
 java.sql.SQLRecoverableException: IO Error: Socket read timed out
        at helper.js:37 (commit)
        at testfile.js:46 (run)

        at jdbcrunner.Script.call(Script.java:290)
        at jdbcrunner.Script.callRun(Script.java:218)
        at jdbcrunner.Helper.callRun(Helper.java:107)
        at jdbcrunner.Agent.callRun(Agent.java:246)
        at jdbcrunner.Agent.run(Agent.java:108)
        at java.lang.Thread.run(Unknown Source)

 Caused by: java.sql.SQLRecoverableException: IO Error: Socket read timed out
        at oracle.jdbc.driver.T4CConnection.doCommit(T4CConnection.java:665)
        at oracle.jdbc.driver.PhysicalConnection.commit(PhysicalConnection.java:3901)
        at oracle.jdbc.driver.PhysicalConnection.commit(PhysicalConnection.java:3907)
        at org.apache.commons.dbcp.DelegatingConnection.commit(DelegatingConnection.java:334)
        at org.apache.commons.dbcp.DelegatingConnection.commit(DelegatingConnection.java:334)
        at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.commit(PoolingDataSource.java:211)
        at jdbcrunner.Helper.commit(Helper.java:196)
        at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at org.mozilla.javascript.MemberBox.invoke(MemberBox.java:161)
        at org.mozilla.javascript.NativeJavaMethod.call(NativeJavaMethod.java:247)
        at org.mozilla.javascript.gen.helper_js_3._c_commit_9(helper.js:37)
        at org.mozilla.javascript.gen.helper_js_3.call(helper.js)
        at org.mozilla.javascript.optimizer.OptRuntime.callName0(OptRuntime.java:108)
        at org.mozilla.javascript.gen.testfile_js_4._c_run_2(testfile.js:46)
        at org.mozilla.javascript.gen.testfile_js_4.call(testfile.js)
        at org.mozilla.javascript.ContextFactory.doTopCall(ContextFactory.java:426)
        at org.mozilla.javascript.ScriptRuntime.doTopCall(ScriptRuntime.java:3178)
        at org.mozilla.javascript.gen.testfile_js_4.call(testfile.js)
        at jdbcrunner.Script.call(Script.java:279)
        ... 5 more
 Caused by: oracle.net.ns.NetException: Socket read timed out
        at oracle.net.ns.Packet.receive(Packet.java:339)
        at oracle.net.ns.DataPacket.receive(DataPacket.java:106)
        at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
        at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
        at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
        at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
        at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
        at oracle.jdbc.driver.T4C7Ocommoncall.doOCOMMIT(T4C7Ocommoncall.java:75)
        at oracle.jdbc.driver.T4CConnection.doCommit(T4CConnection.java:610)
        ... 25 more
 22:21:05 [INFO ] < JdbcRunner ERROR

■余談：trussで捕まえた発生箇所（と思われるところ）

 ========
 15094/2:        lwp_kill(20, SIGJVM1)                           = 0
 15094/20:           Received signal #39, SIGJVM1, in read() [caught]
 15094/20:             siginfo: SIGJVM1 pid=15094 uid=0 code=-1
 15094/21:       mprotect(0xB5DEF000, 12288, PROT_READ|PROT_WRITE) = 0
 15094/20:       read(5, 0xB5FAC1C0, 8192)                       Err#4 EINTR
 ========