JDBC中语句超时与事务



在JAVA使用JDBC连接数据库进行操作时，有可能为了避免语句运行超时，而设置超时时长。

这里有一个问题是，假设一个事务有两条DML SQL语句，会话在执行第一条SQL成功后，执行第二条SQL超时而中止时，事务处于什么样的状态？通常来说，一个SQL报错，只会进行语句级回滚，整个事务不会进行回滚。我们来进行一下测试。

测试环境：Oracle 11.2.0.2 for Windows。
首先在TEST用户下生成测试表和数据。

view plaincopy to clipboardprint?
01.TEST@xj11g> create table t1 ( id number primary key,name varchar2(20));  
02.  
03.表已创建。  
04.  
05.TEST@xj11g> create table t2 ( id number primary key,name varchar2(20));  
06.  
07.表已创建。  
08.  
09.TEST@xj11g> insert into t2 values (1,'a');  
10.  
11.已创建 1 行。  
12.  
13.TEST@xj11g> commit;  
14.  
15.提交完成。  

编译如下的JAVA代码(TestTimeout.java)：

view plaincopy to clipboardprint?
01.import java.sql.*;  
02.  
03.public class TestTimeout {  
04.    public static Connection getConnection() throws Exception {  
05.        String driver = "oracle.jdbc.driver.OracleDriver";  
06.        String url = "jdbc:oracle:thin:@localhost:1521:xj11g";  
07.        Class.forName(driver);  
08.        return DriverManager.getConnection(url, "test", "test");  
09.    }  
10.  
11.    public static void main(String args[]) {  
12.        test1();  
13.    }  
14.    public static void test1() {  
15.        Connection conn = null;  
16.        Statement pstmt = null;  
17.        try {  
18.            conn = getConnection();  
19.            conn.setAutoCommit(false);  
20.            pstmt = conn.createStatement();  
21.            pstmt.setQueryTimeout(60);  
22.            pstmt.execute("insert into t1 values (1,'xx')");  
23.            pstmt.execute("update t2 set name='x' where id=1");  
24.            conn.commit();  
25.        } catch (Exception e) {  
26.            e.printStackTrace();  
27.            try {  
28.                Thread.sleep(300000);  
29.            } catch (Exception f) {  
30.            }  
31.        } finally {  
32.            try {  
33.                pstmt.close();  
34.                conn.close();  
35.            } catch (SQLException e) {  
36.                e.printStackTrace();  
37.            }  
38.        }  
39.    }  
40.}  


编译JAVA代码：



view plaincopy to clipboardprint?
01.E:\JavaCode>d:\works\java\jdk1.5.0_21\bin\javac TestTimeout.java  


在一个会话里面将T2表中ID=1的行进行UPDATE操作，但是不提交。



view plaincopy to clipboardprint?
01.TEST@xj11g> update t2 set name='y' where id=1;  
02.  
03.已更新 1 行。  


然后运行测试用JAVA程序：



view plaincopy to clipboardprint?
01.E:\JavaCode>set CLASSPATH=ojdbc14.jar;.  
02.  
03.E:\JavaCode>d:\works\java\jdk1.5.0_21\jre\bin\java TestTimeout  


可以预见的是，在执行update表T2时会被锁住：



view plaincopy to clipboardprint?
01.SYS@xj11g> select sid,event,sql_id from v$session where sid=206;  
02.  
03.        SID EVENT                         SQL_ID  
04.----------- ----------------------------- -------------  
05.        206 enq: TX - row lock contention 3b3b7s22dv13t  


一会儿后JAVA程序报如下的错误：



view plaincopy to clipboardprint?
01.java.sql.SQLException: ORA-01013: 用户请求取消当前的操作  
02.  
03.        at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112)  
04.        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:331)  
05.        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:288)  
06.        at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:743)  
07.        at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:207)  
08.        at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:946)  
09.        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1160)  
10.        at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1679)  
11.        at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1645)  
12.        at TestTimeout.test1(TestTimeout.java:23)  
13.        at TestTimeout.main(TestTimeout.java:12)  


可以看到，JAVA程序自己CANCEL掉了SQL的执行。
 在JAVA代码中长时间的SLEEP是为了便于观察SQL报错后，事务的状态。



view plaincopy to clipboardprint?
01.SYS@xj11g> select xidusn,xidslot,xidsqn,status from v$transaction where ses_addr=(select saddr from v$session where sid=206);  
02.  
03.     XIDUSN     XIDSLOT      XIDSQN STATUS  
04.----------- ----------- ----------- ----------------  
05.          4          28        4117 ACTIVE  
06.  
07.SYS@xj11g> select * from v$lock where sid=206;  
08.  
09.  SID TY         ID1         ID2       LMODE     REQUEST       CTIME       BLOCK  
10.----- -- ----------- ----------- ----------- ----------- ----------- -----------  
11.  206 AE         100           0           4           0         203           0  
12.  206 TM       63075           0           3           0         203           0  
13.  206 TX      262172        4117           6           0         203           0  
14.SYS@xj11g> select owner,object_name,object_type from dba_objects where object_id=63075;  
15.  
16.OWNER    OBJECT_NAME  OBJECT_TYPE  
17.-------- ------------ ------------  
18.TEST     T1           TABLE  


可以看到JAVA程序的会话（此时还没断开连接），仍然是在事务中，并且在表T1上加了锁。
 此时如果向T1表插入ID值为1的数据，会被锁阻塞。



view plaincopy to clipboardprint?
01.SYS@xj11g> insert into test.t1 values (1,'xx');  


不过奇怪的是，过几分钟后（JAVA中的SLEEP 300000表示休眠300秒，即5分钟），上述的INSERT语句报错了。查询发现JAVA代码中的INSERT的数据提交了：



view plaincopy to clipboardprint?
01.insert into test.t1 values (1,'xx')  
02.*  
03.第 1 行出现错误:  
04.ORA-00001: 违反唯一约束条件 (TEST.SYS_C0011027)  
05.  
06.SYS@xj11g> select * from test.t1;  
07.  
08.         ID NAME  
09.----------- --------------------  
10.          1 xx  


其实想想就能明白，这个并不奇怪，因为JAVA代码的最后正常断开了数据库连接，在默认情况下，正常断开的数据库连接会自动提交没有提交的事务。这也是一种很难排查的产生数据不一致的原因之一。

小结：这个测试JAVA程序，可以表明，JDBC中的语句超时，只会使当前的SQL中止运行，但如果是在一个事务中，之前运行的DML语句并没有提交。这造成的后果有两种：
1. 如果是连接池，那么超时之前更新的数据可能会被其他请求重用时得以提交，或者是在连接释放时得以提交，这造成数据的不一致，因为不是一个逻辑上有效的事务。
2. 由于数据被更新而没有及时回滚，可能会导致应用重新发起相同的事务时被锁住。如果被锁住的会话仍然有超时中止的机制，那么这种情况就会越来越严重。

为了避免以上的两种问题，在超时后，应该主动发起一次ROLLBACK操作。

最后是JAVA程序测试时数据库会话的SQL TRACE记录：



view plaincopy to clipboardprint?
01.PARSING IN CURSOR #356760536 len=33 dep=0 uid=52 oct=6 lid=52 tim=36160405140 hv=2229109881 ad='7ff55ce8608' sqlid='3b3b7s22dv13t'  
02.update t2 set name='x' where id=1  
03.END OF STMT  
04.PARSE #356760536:c=0,e=675,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2789547903,tim=36160405139  
05.  
06.*** 2013-09-09 00:51:01.836  
07.WAIT #356760536: nam='enq: TX - row lock contention' ela= 63181195 name|mode=1415053318 usn<<16 | slot=589851 sequence=4123 obj#=63077 tim=36223613008  
08.EXEC #356760536:c=0,e=63208180,p=0,cr=2,cu=1,mis=0,r=0,dep=0,og=1,plh=2789547903,tim=36223613365  
09.ERROR #3:err=1013 tim=36223613426  
10.STAT #356760536 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE  T2 (cr=0 pr=0 pw=0 time=4 us)'  
11.STAT #356760536 id=2 cnt=1 pid=1 pos=1 obj=63078 op='INDEX UNIQUE SCAN SYS_C0011028 (cr=1 pr=0 pw=0 time=10 us cost=1 size=25 card=1)'  
12.WAIT #356760536: nam='SQL*Net break/reset to client' ela= 3586 driver id=1952673792 break?=0 p3=0 obj#=63077 tim=36223617262  
13.WAIT #356760536: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=63077 tim=36223617407  
14.  
15.*** 2013-09-09 00:56:01.903  
16.WAIT #356760536: nam='SQL*Net message from client' ela= 300048871 driver id=1952673792 #bytes=1 p3=0 obj#=63077 tim=36523666376  
17.CLOSE #356760536:c=0,e=62,dep=0,type=0,tim=36523666818  
18.XCTEND rlbk=0, rd_only=0, tim=36523666956  


在上面可以看到，在最后的确有一个事务事交（XCTEND rlbk=0, rd_only=0）。