java - 为什么 myBatis+postgresql 9.3 即使查询成功也会发出 ROLLBACK ？

Question

我有一段使用 myBatis、postgresql 9.3 服务器和 postgresql-9.3-1100-jdbc41 JDBC 驱动程序的 Java 代码。我们还使用 mybatis-guice 来支持 @Transactional。到目前为止，我们仅使用可序列化事务，现在我们希望将仅从数据库读取的查询置于不太严格的隔离级别，例如“读已提交”。因此，一些@Transactional注释使用SERIALIZABLE，一些使用READ_COMMITTED。还有嵌套调用。

所以，我在 postgresql 服务器日志中有这个:

2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1268 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager LOG:  execute : BEGIN2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SELECT                *            FROM                customer.accounts            WHERE--2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager LOG:  execute : UPDATE                customer.cities            SET                name = $1,                ledger_id = $2,--2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: ......2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute : SELECT                l.*                 ,                cc.id as cost_center_id,                cc.description as cost_center_description,--2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = .....2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute : UPDATE                customer.ledgers            SET                internal_ledger_number = $1                 ,--2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ...........2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute : SELECT DISTINCT                role            FROM customer.user_roles ur INNER JOIN customer.user_to_accounts_to_user_roles uur ON (ur.id=uur.role_id)            WHERE                user_id=$12016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = .......2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1269 txnId=1726978 pid=1949 appName=entity_manager LOG:  execute S_2: ROLLBACK2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager LOG:  execute : BEGIN2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SELECT                 id            FROM            customer.user_roles            WHERE role=$12016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ......2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager LOG:  execute : INSERT INTO customer.user_to_accounts_to_user_roles             (user_id, account_id, role_id)             values             ($1, $2, $3)2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ........2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1270 txnId=1726979 pid=1949 appName=entity_manager LOG:  execute S_1: COMMIT2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1271 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager LOG:  execute : BEGIN2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager LOG:  execute : SELECT                *            FROM                customer.cities            WHERE--2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager DETAIL:  parameters: $1 = ......2016-02-09 15:27:47 CET sessionId=56b9f455.79d sessionStart=2016-02-09 15:14:45 CET vTxnId=12/1272 txnId=0 pid=1949 appName=entity_manager LOG:  execute S_1: COMMIT

(这是一个片段，通过 grep 查找 sessionId 并使用 --after-context 进行过滤 - 这就是为什么有些查询似乎未终止，但相信我，它们是有效的查询)。所以我有一个成功查询的列表，并且在某个时候会发出回滚。然后代码继续执行其余查询。所以我的代码中似乎没有任何异常。看起来 ROLLBACK 是突然发出的。

怎么会发生这种事？
这种情况发生的概率为十分之一，十分之九，一切正常(使用相同的数据)。该代码是多线程的。

我可以提供其他详细信息，没问题。

Answer 1

我已经找到原因了。

事实证明，在一个用@Transactional注释的方法(我们称之为方法A)中，还有另一个用@Transactional注释的方法(我们称之为方法B)。这个内部方法(methodB)抛出了一个异常，该异常在 methodA 中被清除，代码愉快地继续执行。然而，一旦 myBatis 看到异常，它就会回滚整个事务。

类似这样的事情:

methodA (@Transactional)
begin
select * ....
update .....
methodB: select .... 
methodB: throw exception -> myBatis calls rollback
methodA: catch exception, go on
methodA: other code