Intermittently getting null row using bitronix transaction manager even row is there in database

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Intermittently getting null row using bitronix transaction manager even row is there in database

jayantvaish5
Hello,

I am using btm 2.1.3 and hibernate 3.6.9 with mysql-5.5.
I am having a table where one row exists with some ID let's say 1. Multiple threads are accessing the table at the same time, sometimes It finds null row even the entry is there.

Firstly I thought it's an issue with hibernate or mysql, but I was wrong with the following analysis:

1. If i don't use hibernate and by using the connection which btm provides and executing the query by that connection also I get same problem.
2. If I don't use btm and using transaction manager which comes with jboss. I don't see this issue coming even I use same version of hibernate and mysql.
3. When the rows are coming null just after that I am executing a simple jdbc program which creates a new connection with that I am executing the same query I get the result.

So, with above point's  seems it's an issue with btm rather than issue with our code, mysql, hibernate, btm configuration (As it works fine other time it appears very intermittent and hard to reproduce with sample program).

I have taken some debug logs of bitronix and hibernate when this problem are coming and it's mentioned below. Please help me as it's really a very big problem and questions on integrity. I am really stuck.

I suspect it's a problem with connection which btm is providing.

Here are the logs:

2013-10-24 16:54:23,361 78011 DEBUG [MyClass1] (MyThread-7:) fetching row id 1
2013-10-24 16:54:23,361 78011 DEBUG [org.hibernate.loader.Loader] (MyThread-7:) loading entity: [CustomTable#1]
2013-10-24 16:54:23,363 78013 DEBUG [org.hibernate.jdbc.AbstractBatcher] (MyThread-7:) about to open PreparedStatement (open PreparedStatements: 0, globally: 231)
2013-10-24 16:54:23,363 78013 DEBUG [org.hibernate.jdbc.ConnectionManager] (MyThread-7:) opening JDBC connection
2013-10-24 16:54:26,274 80924 DEBUG [bitronix.tm.resource.jdbc.PoolingDataSource] (MyThread-7:) acquiring connection from a PoolingDataSource containing an XAPool of resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,274 80924 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) trying to recycle a NOT_ACCESSIBLE connection of an XAPool of resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,274 80924 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) current transaction GTRID is [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049]
2013-10-24 16:54:26,274 80924 DEBUG [bitronix.tm.resource.jdbc.PoolingDataSource] (http-8080-Processor542:) acquiring connection from a PoolingDataSource containing an XAPool of resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@2d97d09f
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@2d97d09f
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@19f9e414
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@19f9e414
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@1385c219
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@1385c219
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@b4f06f0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@b4f06f0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@5835b0c9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@5835b0c9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@ff224ab
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@ff224ab
2013-10-24 16:54:26,275 80925 DEBUG [org.hibernate.SQL] (http-8080-Processor522:) insert into LARGE_DATA (BIN_DATA, INSERT_TIME, MLOCK) values (?, ?, ?)
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@66edbcf8
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (http-8080-Processor522:) enlisting a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@68275748 into a Bitronix Transaction with GTRID [746F6D6361742D62746D2D6E6F64653000000000017CD59500000102], status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:58 IST 1970)
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@66edbcf8
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (http-8080-Processor522:) avoiding re-enlistment of already enlisted but not ended resource an XAResourceHolderState with uniqueName=jdbc/MYDB XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [746F6D6361742D62746D2D6E6F64653000000000017CD59500000102 : 746F6D6361742D62746D2D6E6F64653000000000017CE64C0000021F]
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@5b20d371
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@5b20d371
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@3ffcc16d
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@3ffcc16d
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@21bcda55
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@21bcda55
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@485266e0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@485266e0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@57e302c2
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@57e302c2
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@6571340b
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@6571340b
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@66cf56f9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@66cf56f9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@4dde0d8f
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@4dde0d8f
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found a connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE state: a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) NOT_ACCESSIBLE xa resource GTRID: 746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) NOT_ACCESSIBLE xa resource's GTRID matched this transaction's GTRID, recycling it
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool] (MyThread-7:) found NOT_ACCESSIBLE connection a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 from an XAPool of resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) getting connection handle from a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) notifying 2 stateChangeEventListener(s) about state changing from NOT_ACCESSIBLE to ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) state changing from NOT_ACCESSIBLE to ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) notifying 2 stateChangeEventListener(s) about state changed from NOT_ACCESSIBLE to ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) marking a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 as recycled in a Bitronix Transaction with GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 has been recycled, unregistering deferred release from a Bitronix Transaction with GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) connection a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 was in state NOT_ACCESSIBLE, no need to test it
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) got connection handle from a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.jdbc.PoolingDataSource] (MyThread-7:) acquired connection from a PoolingDataSource containing an XAPool of resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,277 80927 DEBUG [org.hibernate.SQL] (MyThread-7:) select hmessageex0_.ID as ID6_1_, hmessageex0_.PORT_TYPE as PORT2_6_1_, hmessageex0_.CHANNEL_NAME as CHANNEL3_6_1_, hmessageex0_.CLIENTKEY as CLIENTKEY6_1_, hmessageex0_.LDATA_EPR_ID as LDATA5_6_1_, hmessageex0_.LDATA_CEPR_ID as LDATA6_6_1_, hmessageex0_.REQUEST as REQUEST6_1_, hmessageex0_.RESPONSE as RESPONSE6_1_, hmessageex0_.INSERT_DT as INSERT9_6_1_, hmessageex0_.OPERATION as OPERATION6_1_, hmessageex0_.STATE as STATE6_1_, hmessageex0_.PROCESS as PROCESS6_1_, hmessageex0_.PIID as PIID6_1_, hmessageex0_.DIR as DIR6_1_, hmessageex0_.PLINK_MODELID as PLINK15_6_1_, hmessageex0_.PATTERN as PATTERN6_1_, hmessageex0_.CORR_STATUS as CORR17_6_1_, hmessageex0_.FAULT_TYPE as FAULT18_6_1_, hmessageex0_.FAULT_EXPL as FAULT19_6_1_, hmessageex0_.CALLEE as CALLEE6_1_, hmessageex0_.PARTNERLINK as PARTNER21_6_1_, hmessageex0_.PIPED_ID as PIPED22_6_1_, hmessageex0_.SUBSCRIBER_COUNT as SUBSCRIBER23_6_1_, hmessageex0_.INSERT_TIME as INSERT24_6_1_, hmessageex0_.MLOCK as MLOCK6_1_, hprocess1_.ID as ID0_0_, hprocess1_.PROCID as PROCID0_0_, hprocess1_.deployer as deployer0_0_, hprocess1_.deploydate as deploydate0_0_, hprocess1_.type_name as type5_0_0_, hprocess1_.type_ns as type6_0_0_, hprocess1_.version as version0_0_, hprocess1_.ACTIVE_ as ACTIVE8_0_0_, hprocess1_.guid as guid0_0_, hprocess1_.INSERT_TIME as INSERT10_0_0_, hprocess1_.MLOCK as MLOCK0_0_ from BPEL_MESSAGE_EXCHANGE hmessageex0_ left outer join BPEL_PROCESS hprocess1_ on hmessageex0_.PROCESS=hprocess1_.ID where hmessageex0_.ID=?
2013-10-24 16:54:26,277 80927 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) enlisting a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 into a Bitronix Transaction with GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,277 80927 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) avoiding re-enlistment of already enlisted but not ended resource an XAResourceHolderState with uniqueName=jdbc/MYDB XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a Bitronix XID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049 : 746F6D6361742D62746D2D6E6F64653000000000017CCF7C00000098]
2013-10-24 16:54:26,278 80928 DEBUG [org.hibernate.jdbc.AbstractBatcher] (MyThread-7:) about to open ResultSet (open ResultSets: 0, globally: 0)
2013-10-24 16:54:26,278 80928 DEBUG [org.hibernate.jdbc.AbstractBatcher] (MyThread-7:) about to open ResultSet (open ResultSets: 0, globally: 0)
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.AbstractBatcher] (MyThread-7:) about to close ResultSet (open ResultSets: 1, globally: 1)
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.AbstractBatcher] (MyThread-7:) about to close PreparedStatement (open PreparedStatements: 1, globally: 214)
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.ConnectionManager] (MyThread-7:) aggressively releasing JDBC connection
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.ConnectionManager] (MyThread-7:) releasing JDBC connection [ (open PreparedStatements: 0, globally: 213) (open ResultSets: 0, globally: 0)]
2013-10-24 16:54:26,279 80929 DEBUG [bitronix.tm.resource.jdbc.JdbcConnectionHandle] (MyThread-7:) closing a JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 on a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state STARTED
2013-10-24 16:54:26,279 80929 DEBUG [bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) releasing to pool a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,279 80929 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) delisting a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 from a Bitronix Transaction with GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,279 80929 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) resource is in enlisting global transaction context: a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,279 80929 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) requeuing a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 from a Bitronix Transaction with GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,279 80929 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) resource is in enlisting global transaction context: a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) deferring release to pool of a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 is not already registered for deferred release in a Bitronix Transaction with GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) registering DeferredReleaseSynchronization for a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) notifying 2 stateChangeEventListener(s) about state changing from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) closing 0 dangling uncached statement(s)
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) clearing warnings of a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state STARTED
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) state changing from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) notifying 2 stateChangeEventListener(s) about state changed from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG [bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) released to pool a JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG [org.hibernate.engine.StatefulPersistenceContext] (MyThread-7:) initializing non-lazy collections
2013-10-24 16:54:26,280 80930 DEBUG [org.hibernate.loader.Loader] (MyThread-7:) done entity load
2013-10-24 16:54:26,280 80930 WARN  [MyClass1] (MyThread-7:) Row is null for the expected id: 1


Thanks in advance !!


Jayant
Reply | Threaded
Open this post in threaded view
|

Re: Intermittently getting null row using bitronix transaction manager even row is there in database

Anil Hemnani

Are all these threads only  reading the record or they are modifying the record as well.

How are you retrieving the record by primay key or some other criteria? 

It seems concurrency issue and nothing to do with bitronix.

If possible share your query which is bringing null result and write statements etc.  I am guessing your one thread is trying to search a record with one set of values but other thread has modified the record with different set of values concurrently hence you get 0/null records back.

On 26 Oct 2013 20:36, "jayantvaish5" <[hidden email]> wrote:
Hello,

I am using btm 2.1.3 and hibernate 3.6.9 with mysql-5.5.
I am having a table where one row exists with some ID let's say 1. Multiple
threads are accessing the table at the same time, sometimes It finds null
row even the entry is there.

Firstly I thought it's an issue with hibernate or mysql, but I was wrong
with the following analysis:

1. If i don't use hibernate and by using the connection which btm provides
and executing the query by that connection also I get same problem.
2. If I don't use btm and using transaction manager which comes with jboss.
I don't see this issue coming even I use same version of hibernate and
mysql.
3. When the rows are coming null just after that I am executing a simple
jdbc program which creates a new connection with that I am executing the
same query I get the result.

So, with above point's  seems it's an issue with btm rather than issue with
our code, mysql, hibernate, btm configuration (As it works fine other time
it appears very intermittent and hard to reproduce with sample program).

I have taken some debug logs of bitronix and hibernate when this problem are
coming and it's mentioned below. Please help me as it's really a very big
problem and questions on integrity. I am really stuck.

I suspect it's a problem with connection which btm is providing.

Here are the logs:

2013-10-24 16:54:23,361 78011 DEBUG [MyClass1] (MyThread-7:) fetching row id
1
2013-10-24 16:54:23,361 78011 DEBUG [org.hibernate.loader.Loader]
(MyThread-7:) loading entity: [CustomTable#1]
2013-10-24 16:54:23,363 78013 DEBUG [org.hibernate.jdbc.AbstractBatcher]
(MyThread-7:) about to open PreparedStatement (open PreparedStatements: 0,
globally: 231)
2013-10-24 16:54:23,363 78013 DEBUG [org.hibernate.jdbc.ConnectionManager]
(MyThread-7:) opening JDBC connection
2013-10-24 16:54:26,274 80924 DEBUG
[bitronix.tm.resource.jdbc.PoolingDataSource] (MyThread-7:) acquiring
connection from a PoolingDataSource containing an XAPool of resource
jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,274 80924 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) trying to recycle a NOT_ACCESSIBLE connection of an XAPool of
resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,274 80924 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) current transaction GTRID is
[746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049]
2013-10-24 16:54:26,274 80924 DEBUG
[bitronix.tm.resource.jdbc.PoolingDataSource] (http-8080-Processor542:)
acquiring connection from a PoolingDataSource containing an XAPool of
resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@2d97d09f
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@2d97d09f
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@19f9e414
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@19f9e414
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@1385c219
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@1385c219
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@b4f06f0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@b4f06f0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@5835b0c9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@5835b0c9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@ff224ab
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@ff224ab
2013-10-24 16:54:26,275 80925 DEBUG [org.hibernate.SQL]
(http-8080-Processor522:) insert into LARGE_DATA (BIN_DATA, INSERT_TIME,
MLOCK) values (?, ?, ?)
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@66edbcf8
2013-10-24 16:54:26,275 80925 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper]
(http-8080-Processor522:) enlisting a JdbcPooledConnection from datasource
jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC
LrcXAConnection on com.mysql.jdbc.JDBC4Connection@68275748 into a Bitronix
Transaction with GTRID
[746F6D6361742D62746D2D6E6F64653000000000017CD59500000102], status=ACTIVE, 1
resource(s) enlisted (started Thu Jan 01 12:25:58 IST 1970)
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@66edbcf8
2013-10-24 16:54:26,275 80925 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper]
(http-8080-Processor522:) avoiding re-enlistment of already enlisted but not
ended resource an XAResourceHolderState with uniqueName=jdbc/MYDB
XAResource=a JDBC LrcXAResource in state STARTED (started) with XID a
Bitronix XID [746F6D6361742D62746D2D6E6F64653000000000017CD59500000102 :
746F6D6361742D62746D2D6E6F64653000000000017CE64C0000021F]
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@5b20d371
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@5b20d371
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@3ffcc16d
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@3ffcc16d
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@21bcda55
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@21bcda55
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@485266e0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@485266e0
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@57e302c2
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@57e302c2
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@6571340b
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@6571340b
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@66cf56f9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@66cf56f9
2013-10-24 16:54:26,275 80925 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@4dde0d8f
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@4dde0d8f
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found a connection in NOT_ACCESSIBLE state: a
JdbcPooledConnection from datasource jdbc/MYDB in state NOT_ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) 1 xa resource(s) created by connection in NOT_ACCESSIBLE
state: a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) NOT_ACCESSIBLE xa resource GTRID:
746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) NOT_ACCESSIBLE xa resource's GTRID matched this transaction's
GTRID, recycling it
2013-10-24 16:54:26,276 80926 DEBUG [bitronix.tm.resource.common.XAPool]
(MyThread-7:) found NOT_ACCESSIBLE connection a JdbcPooledConnection from
datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 0 wrapping a
JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 from an
XAPool of resource jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) getting
connection handle from a JdbcPooledConnection from datasource jdbc/MYDB in
state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:)
notifying 2 stateChangeEventListener(s) about state changing from
NOT_ACCESSIBLE to ACCESSIBLE in a JdbcPooledConnection from datasource
jdbc/MYDB in state NOT_ACCESSIBLE with usage count 1 wrapping a JDBC
LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) state
changing from NOT_ACCESSIBLE to ACCESSIBLE in a JdbcPooledConnection from
datasource jdbc/MYDB in state NOT_ACCESSIBLE with usage count 1 wrapping a
JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:)
notifying 2 stateChangeEventListener(s) about state changed from
NOT_ACCESSIBLE to ACCESSIBLE in a JdbcPooledConnection from datasource
jdbc/MYDB in state ACCESSIBLE with usage count 1 wrapping a JDBC
LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) marking
a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with
usage count 1 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8 as recycled in a Bitronix
Transaction with GTRID
[746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1
resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) a
JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with
usage count 1 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8 has been recycled, unregistering
deferred release from a Bitronix Transaction with GTRID
[746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1
resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) connection a
JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8 was in state
NOT_ACCESSIBLE, no need to test it
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) got
connection handle from a JdbcPooledConnection from datasource jdbc/MYDB in
state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,276 80926 DEBUG
[bitronix.tm.resource.jdbc.PoolingDataSource] (MyThread-7:) acquired
connection from a PoolingDataSource containing an XAPool of resource
jdbc/MYDB with 500 connection(s) (178 still available)
2013-10-24 16:54:26,277 80927 DEBUG [org.hibernate.SQL] (MyThread-7:) select
hmessageex0_.ID as ID6_1_, hmessageex0_.PORT_TYPE as PORT2_6_1_,
hmessageex0_.CHANNEL_NAME as CHANNEL3_6_1_, hmessageex0_.CLIENTKEY as
CLIENTKEY6_1_, hmessageex0_.LDATA_EPR_ID as LDATA5_6_1_,
hmessageex0_.LDATA_CEPR_ID as LDATA6_6_1_, hmessageex0_.REQUEST as
REQUEST6_1_, hmessageex0_.RESPONSE as RESPONSE6_1_, hmessageex0_.INSERT_DT
as INSERT9_6_1_, hmessageex0_.OPERATION as OPERATION6_1_, hmessageex0_.STATE
as STATE6_1_, hmessageex0_.PROCESS as PROCESS6_1_, hmessageex0_.PIID as
PIID6_1_, hmessageex0_.DIR as DIR6_1_, hmessageex0_.PLINK_MODELID as
PLINK15_6_1_, hmessageex0_.PATTERN as PATTERN6_1_, hmessageex0_.CORR_STATUS
as CORR17_6_1_, hmessageex0_.FAULT_TYPE as FAULT18_6_1_,
hmessageex0_.FAULT_EXPL as FAULT19_6_1_, hmessageex0_.CALLEE as CALLEE6_1_,
hmessageex0_.PARTNERLINK as PARTNER21_6_1_, hmessageex0_.PIPED_ID as
PIPED22_6_1_, hmessageex0_.SUBSCRIBER_COUNT as SUBSCRIBER23_6_1_,
hmessageex0_.INSERT_TIME as INSERT24_6_1_, hmessageex0_.MLOCK as MLOCK6_1_,
hprocess1_.ID as ID0_0_, hprocess1_.PROCID as PROCID0_0_,
hprocess1_.deployer as deployer0_0_, hprocess1_.deploydate as
deploydate0_0_, hprocess1_.type_name as type5_0_0_, hprocess1_.type_ns as
type6_0_0_, hprocess1_.version as version0_0_, hprocess1_.ACTIVE_ as
ACTIVE8_0_0_, hprocess1_.guid as guid0_0_, hprocess1_.INSERT_TIME as
INSERT10_0_0_, hprocess1_.MLOCK as MLOCK0_0_ from BPEL_MESSAGE_EXCHANGE
hmessageex0_ left outer join BPEL_PROCESS hprocess1_ on
hmessageex0_.PROCESS=hprocess1_.ID where hmessageex0_.ID=?
2013-10-24 16:54:26,277 80927 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
enlisting a JdbcPooledConnection from datasource jdbc/MYDB in state
ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8 into a Bitronix Transaction with
GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049],
status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,277 80927 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
avoiding re-enlistment of already enlisted but not ended resource an
XAResourceHolderState with uniqueName=jdbc/MYDB XAResource=a JDBC
LrcXAResource in state STARTED (started) with XID a Bitronix XID
[746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049 :
746F6D6361742D62746D2D6E6F64653000000000017CCF7C00000098]
2013-10-24 16:54:26,278 80928 DEBUG [org.hibernate.jdbc.AbstractBatcher]
(MyThread-7:) about to open ResultSet (open ResultSets: 0, globally: 0)
2013-10-24 16:54:26,278 80928 DEBUG [org.hibernate.jdbc.AbstractBatcher]
(MyThread-7:) about to open ResultSet (open ResultSets: 0, globally: 0)
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.AbstractBatcher]
(MyThread-7:) about to close ResultSet (open ResultSets: 1, globally: 1)
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.AbstractBatcher]
(MyThread-7:) about to close PreparedStatement (open PreparedStatements: 1,
globally: 214)
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.ConnectionManager]
(MyThread-7:) aggressively releasing JDBC connection
2013-10-24 16:54:26,279 80929 DEBUG [org.hibernate.jdbc.ConnectionManager]
(MyThread-7:) releasing JDBC connection [ (open PreparedStatements: 0,
globally: 213) (open ResultSets: 0, globally: 0)]
2013-10-24 16:54:26,279 80929 DEBUG
[bitronix.tm.resource.jdbc.JdbcConnectionHandle] (MyThread-7:) closing a
JdbcConnectionHandle of a JdbcPooledConnection from datasource jdbc/MYDB in
state ACCESSIBLE with usage count 1 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8 on a JDBC LrcConnectionHandle on a
JDBC LrcXAResource in state STARTED
2013-10-24 16:54:26,279 80929 DEBUG
[bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) releasing to
pool a JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE
with usage count 1 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,279 80929 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
delisting a JdbcPooledConnection from datasource jdbc/MYDB in state
ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8 from a Bitronix Transaction with
GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049],
status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,279 80929 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
resource is in enlisting global transaction context: a JdbcPooledConnection
from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a
JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,279 80929 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
requeuing a JdbcPooledConnection from datasource jdbc/MYDB in state
ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8 from a Bitronix Transaction with
GTRID [746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049],
status=ACTIVE, 1 resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,279 80929 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
resource is in enlisting global transaction context: a JdbcPooledConnection
from datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a
JDBC LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
deferring release to pool of a JdbcPooledConnection from datasource
jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC
LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:) a
JdbcPooledConnection from datasource jdbc/MYDB in state ACCESSIBLE with
usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8 is not already registered for
deferred release in a Bitronix Transaction with GTRID
[746F6D6361742D62746D2D6E6F64653000000000017CC6AB00000049], status=ACTIVE, 1
resource(s) enlisted (started Thu Jan 01 12:25:54 IST 1970)
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.common.TransactionContextHelper] (MyThread-7:)
registering DeferredReleaseSynchronization for a JdbcPooledConnection from
datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC
LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:)
notifying 2 stateChangeEventListener(s) about state changing from ACCESSIBLE
to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in
state ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) closing 0
dangling uncached statement(s)
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) clearing
warnings of a JDBC LrcConnectionHandle on a JDBC LrcXAResource in state
STARTED
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:) state
changing from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from
datasource jdbc/MYDB in state ACCESSIBLE with usage count 0 wrapping a JDBC
LrcXAConnection on com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.common.AbstractXAStatefulHolder] (MyThread-7:)
notifying 2 stateChangeEventListener(s) about state changed from ACCESSIBLE
to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource jdbc/MYDB in
state NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG
[bitronix.tm.resource.jdbc.JdbcPooledConnection] (MyThread-7:) released to
pool a JdbcPooledConnection from datasource jdbc/MYDB in state
NOT_ACCESSIBLE with usage count 0 wrapping a JDBC LrcXAConnection on
com.mysql.jdbc.JDBC4Connection@74b65fb8
2013-10-24 16:54:26,280 80930 DEBUG
[org.hibernate.engine.StatefulPersistenceContext] (MyThread-7:) initializing
non-lazy collections
2013-10-24 16:54:26,280 80930 DEBUG [org.hibernate.loader.Loader]
(MyThread-7:) done entity load
2013-10-24 16:54:26,280 80930 WARN  [MyClass1] (MyThread-7:) Row is null for
the expected id: 1


Thanks in advance !!


Jayant



--
View this message in context: http://bitronix-transaction-manager.10986.n7.nabble.com/Intermittently-getting-null-row-using-bitronix-transaction-manager-even-row-is-there-in-database-tp1564.html
Sent from the Bitronix Transaction Manager mailing list archive at Nabble.com.

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: Intermittently getting null row using bitronix transaction manager even row is there in database

jayantvaish5
Hello Anil,

There are threads which also update the row but for any particular row simultaneous modification and retrieval won't be done.
We are fetching row through primary key in where clause.

Even if there is concurrency issue, but at all point of time data exists in table. So, why it's bringing 0/null row?
Why it's able fetch data from plain jdbc program just called after when row comes 0/null?
Why it works with other transaction manager?

Thanks,
Jayant
Reply | Threaded
Open this post in threaded view
|

Re: Intermittently getting null row using bitronix transaction manager even row is there in database

jayantvaish5
This post was updated on .
I found one more thing:

If I set resource.ds2.IsolationLevel=READ_COMMITTED in resources.properties I do not get into issue.

Earlier I was already setting the Isolation level on connection level like following:

private DataSource _ds;
//ds is initialized
Connection conn = _ds.getConnection();
conn.setTransactionIsolation(2);

And When the issues comes I am printing the isolation level:
__log.debug("Isolation level for Id: " + id + " is: " + session.connection().getTransactionIsolation());

Which prints 2 i.e. Isolation level is set to READ_COMMITTED.

But it behaves like REPEATABLE_READ which is default isolation level of mysql 5.5


And if this is the problem it shouldn't work with mysql 5.1 also which works fine in case of mysql 5.1

Also other transaction manager like jboss it works fine.


Does it throws any light?