Need help with hung transactions in JBoss 5.1.0.GA
We are running JBoss 5.1.0.GA, jBPM3, EJB3/JPA and HornetQ 2.2.5. We have problems with hung transactions. It looks to us that they are caused by rollbacks, but we don't know for sure. The symptoms are the the running transcation count, and the inUse count of a data source is increased by one. Sometimes, but not always, the number of running MVCC locks in the JBoss cache is increates as well. The transaction is hung in ABORTING. After the transaction timeout, the following is seen in the log file
2012-01-18 22:08:37,855 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [Thread-13] [com.arjuna.ats.arjuna.coordinator.TransactionReaper_18] - TransactionReaper::check timeout for TX -53efe292:d2cb:4f17283a:4c1917 in state RUN
but there is no follwoing lines about aborting the transaction. The transaction above was last in rollback due to a dead lock in MySQL (given below). By far, not all rollbacks causes hanged transactions. Our feeling is that concurrent rollbacks (the test servers are 2 x 12 core AMD) is more likely to cause hanged TX, DS and in worts case hanged MVCC cache locks.
Please advice me on how I can go further with this.
From InnoDB:
LATEST DETECTED DEADLOCK
------------------------
120118 22:03:38
*** (1) TRANSACTION:
TRANSACTION 0 257124310, ACTIVE 1 sec, process no 20496, OS thread id 139792550012688 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 6 lock struct(s), heap size 1216, 4 row lock(s), undo log entries 3
MySQL thread id 61734, query id 204654180 mysql 10.1.1.4 ib Updating
update examination set bodyPart='Leg', code_booked_id=null, code_examination_id=null, code_patient_arrived_id=null, code_requested_id=null, code_result_id='2c909dee326735e00132675e66330392', extraCodes=x'1F8B0800000000000000AD904D0A02310C46F79E222768D175E946BC8117886DC4427F8626EA787B1B0664562388CBE47B098FCF3189DF01B8D08A29F8A49C4DBA988882F29A88CDB1455260200FCC77F2A7194BAA28A955CD0ECE2EFB8589C4A1A749537FBE1130855623D02C1D210C1E5A1DD3E785B3EB0B15B1DF4C7E56DD6FAB5E5367F9A3A9B3DAED1B552D367961010000', externalId='', generatedStudyUid=null, image_sync_finished=0, patientAgeInDays=0, property_ids=x'1F8B0800000000000000B3C9C92C2ED1B703007D20B4E007000000', queriedPacs='2c909cf5215d56e301215d9b970a0b93', receivedFromTransfer=1, request_id='2c909dee34f2753b0134f2a1714848c7', external_user_id=null, risId='flow-in-b-1', scheduledAt=null, sentWithTransfer=0, structuredCode_id=null, transferTriggeredByAgreement_id=null, waitingProcesses=null where id='2c
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 432 page no 50050 n bits 96 index `PRIMARY` of table `ibcs`.`examination` trx id 0 257124310 lock_mode X locks rec but not gap waiting
Record lock, heap no 24 PHYSICAL RECORD: n_fields 25; compact format; info bits 0
0: len 30; hex 326339303964656533346632373533623031333466326131373135343438; asc 2c909dee34f2753b0134f2a1715448;...(truncated); 1: len 6; hex 00000f5360aa; asc S` ;; 2: len 7; hex 00000300021866; asc f;; 3: len 4; hex 80000000; asc ;; 4: len 30; hex 326339303964656533323637333565303031333236373565363633333033; asc 2c909dee326735e00132675e663303;...(truncated); 5: len 11; hex 666c6f772d696e2d622d31; asc flow-in-b-1;; 6: len 30; hex 326339303964656533346632373533623031333466326131373134383438; asc 2c909dee34f2753b0134f2a1714848;...(truncated); 7: SQL NULL; 8: len 0; hex ; asc ;; 9: SQL NULL; 10: SQL NULL; 11: SQL NULL; 12: SQL NULL; 13: len 0; hex ; asc ;; 14: SQL NULL; 15: SQL NULL; 16: len 1; hex 80; asc ;; 17: len 1; hex 80; asc ;; 18: len 1; hex 81; asc ;; 19: SQL NULL; 20: len 27; hex 1f8b0800000000000000b3c9c92c2ed1b703007d20b4e007000000; asc ,. } ;; 21: SQL NULL; 22: len 30; hex 1f8b0800000000000000ad904d0a02310c46f79e222768d175e946bc8117; asc M 1 F "'h u F ;...(truncated); 23: len 3; hex 4c6567; asc Leg;; 24: SQL NULL;
*** (2) TRANSACTION:
TRANSACTION 0 257124318, ACTIVE 0 sec, process no 20496, OS thread id 139792589498128 starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
11 lock struct(s), heap size 1216, 3 row lock(s), undo log entries 8
MySQL thread id 61918, query id 204654189 mysql 10.1.1.4 ib Updating
update from_document set created=1326920593736, version=3 where id='2c909dee34f2753b0134f2a1714848c7' and version=2
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 432 page no 50050 n bits 96 index `PRIMARY` of table `ibcs`.`examination` trx id 0 257124318 lock mode S locks rec but not gap
Record lock, heap no 24 PHYSICAL RECORD: n_fields 25; compact format; info bits 0
0: len 30; hex 326339303964656533346632373533623031333466326131373135343438; asc 2c909dee34f2753b0134f2a1715448;...(truncated); 1: len 6; hex 00000f5360aa; asc S` ;; 2: len 7; hex 00000300021866; asc f;; 3: len 4; hex 80000000; asc ;; 4: len 30; hex 326339303964656533323637333565303031333236373565363633333033; asc 2c909dee326735e00132675e663303;...(truncated); 5: len 11; hex 666c6f772d696e2d622d31; asc flow-in-b-1;; 6: len 30; hex 326339303964656533346632373533623031333466326131373134383438; asc 2c909dee34f2753b0134f2a1714848;...(truncated); 7: SQL NULL; 8: len 0; hex ; asc ;; 9: SQL NULL; 10: SQL NULL; 11: SQL NULL; 12: SQL NULL; 13: len 0; hex ; asc ;; 14: SQL NULL; 15: SQL NULL; 16: len 1; hex 80; asc ;; 17: len 1; hex 80; asc ;; 18: len 1; hex 81; asc ;; 19: SQL NULL; 20: len 27; hex 1f8b0800000000000000b3c9c92c2ed1b703007d20b4e007000000; asc ,. } ;; 21: SQL NULL; 22: len 30; hex 1f8b0800000000000000ad904d0a02310c46f79e222768d175e946bc8117; asc M 1 F "'h u F ;...(truncated); 23: len 3; hex 4c6567; asc Leg;; 24: SQL NULL;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 258 page no 34464 n bits 224 index `PRIMARY` of table `ibcs`.`from_document` trx id 0 257124318 lock_mode X locks rec but not gap waiting
Record lock, heap no 149 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
0: len 30; hex 326339303964656533346632373533623031333466326131373134383438; asc 2c909dee34f2753b0134f2a1714848;...(truncated); 1: len 6; hex 00000f5367d6; asc Sg ;; 2: len 7; hex 00000300081417; asc ;; 3: len 4; hex 80000003; asc ;; 4: len 8; hex 80000134f2a17148; asc 4 qH;; 5: SQL NULL;
*** WE ROLL BACK TRANSACTION (1)