JBossTS recovery: look inside

10:40:44,801 (Thread-18) PeriodicRecovery: background thread Status <== SCANNING
10:40:44,801 (Thread-18) PeriodicRecovery: background thread scanning
10:40:44,802 (Thread-18) Periodic recovery - first pass <Wt, 30 wrz 2014 10:40:44>
10:40:44,802 (Thread-18) InputObjectState::InputObjectState()
10:40:44,802 (Thread-18) StatusModule: first pass
10:40:44,802 (Thread-18) HashedStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:40:44,802 (Thread-18) OutputObjectState::OutputObjectState()
10:40:44,890 (Thread-18) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ecce:542a6c31:53b
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ebbb:542a6bef:a98
10:40:44,890 (Thread-18) found transaction -3f57c7ff:ed72:542a6c5e:50c
...

10:40:44,891 (Thread-18) [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
10:40:44,891 (Thread-18) InputObjectState::InputObjectState()
10:40:44,891 (Thread-18) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
10:40:44,892 (Thread-18) OutputObjectState::OutputObjectState()
10:40:44,892 (Thread-18)
10:40:44,896 (Thread-18) PERIODIC 1. PASS ON STORE  WITH TYPE /StateManager/AbstractRecord/XAResourceRecord
10:40:44,896 (Thread-18) [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
10:40:44,896 (Thread-18) InputObjectState::InputObjectState()
10:40:44,897 (Thread-18) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:40:44,897 (Thread-18) OutputObjectState::OutputObjectState()
10:45:42,120 (Thread-18) Periodic recovery - second pass <Wt, 30 wrz 2014 10:45:42>
10:45:42,120 (Thread-18) AtomicActionRecoveryModule: Second pass
10:45:42,136 (Thread-18) +---- RESOURCE INITIATED RECOVERY
10:45:42,136 (Thread-18) +--- RES RECOVERER: org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d
10:45:42,136 (Thread-18) org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d hasMoreResources
10:45:42,136 (Thread-18) org.jboss.jms.server.recovery.MessagingXAResourceRecovery@7c9a899d getXAResource
10:45:42,136 (Thread-18)  +-- CALLING XARECOVERY
10:45:42,136 (Thread-18) xarecovery of org.jboss.jms.server.recovery.MessagingXAResourceWrapper@53673666
10:45:42,136 (Thread-18) Recover java:DefaultEMSProvider
10:45:43,728 (Thread-18) [EMS] XA Recovery #15 sees 58 XIDs: [{formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:858-3f57c7ff:efbe:542a6d09:9aa}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:53b-3f57c7ff:ecce:542a6c31:693}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dad-3f57c7ff:f885:542a6d79:1efb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:537-3f57c7ff:ecce:542a6c31:688}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:514-3f57c7ff:ed72:542a6c5e:66d}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dd0-3f57c7ff:f885:542a6d79:1f13}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:26a-3f57c7ff:ef42:542a6ce0:3e1}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4f5-3f57c7ff:ed72:542a6c5e:63c}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:16b-3f57c7ff:eb5c:542a6bc7:2c3}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dbe-3f57c7ff:f885:542a6d79:1f14}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:333-3f57c7ff:ee22:542a6c8c:48d}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:166-3f57c7ff:eb5c:542a6bc7:2b8}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:aaf-3f57c7ff:ebbb:542a6bef:bfc}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:160-3f57c7ff:eafe:542a6b9a:2c8}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:2a1-3f57c7ff:ef42:542a6ce0:3ec}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:863-3f57c7ff:efbe:542a6d09:9bd}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1d93-3f57c7ff:f885:542a6d79:1ee5}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:47e-3f57c7ff:eeb2:542a6cb6:5cc}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:52c-3f57c7ff:ed72:542a6c5e:67e}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:1ad-3f57c7ff:eb5c:542a6bc7:2ef}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:879-3f57c7ff:efbe:542a6d09:9cb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:558-3f57c7ff:ecce:542a6c31:6a9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4ce-3f57c7ff:ed72:542a6c5e:626}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:304-3f57c7ff:ee22:542a6c8c:456}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:289-3f57c7ff:ef42:542a6ce0:3d6}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:183-3f57c7ff:eafe:542a6b9a:2d3}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:187-3f57c7ff:eb5c:542a6bc7:2d9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:18c-3f57c7ff:eafe:542a6b9a:2e9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:310-3f57c7ff:ee22:542a6c8c:461}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:31a-3f57c7ff:ee22:542a6c8c:471}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4df-3f57c7ff:ed72:542a6c5e:647}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:a98-3f57c7ff:ebbb:542a6bef:be6}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:16a-3f57c7ff:eb5c:542a6bc7:2ce}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:196-3f57c7ff:eb5c:542a6bc7:2e4}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:503-3f57c7ff:ed72:542a6c5e:652}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ecce:542a6c31:54c-3f57c7ff:ecce:542a6c31:69e}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4e7-3f57c7ff:ed72:542a6c5e:631}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1dd4-3f57c7ff:f885:542a6d79:1f27}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:176-3f57c7ff:eafe:542a6b9a:2bd}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1d9d-3f57c7ff:f885:542a6d79:1ef0}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:325-3f57c7ff:ee22:542a6c8c:477}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:46d-3f57c7ff:eeb2:542a6cb6:5c1}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:4cd-3f57c7ff:ed72:542a6c5e:61b}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:464-3f57c7ff:eeb2:542a6cb6:5b6}, {formatID=131075 gtrid_length=30 bqual_length=28 data=1--3f57c7ff:f885:542a6d79:1db2-3f57c7ff:f885:542a6d79:1f1c}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:28a-3f57c7ff:ef42:542a6ce0:3cb}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ee22:542a6c8c:33c-3f57c7ff:ee22:542a6c8c:482}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:86e-3f57c7ff:efbe:542a6d09:9c0}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eafe:542a6b9a:182-3f57c7ff:eafe:542a6b9a:2de}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:521-3f57c7ff:ed72:542a6c5e:673}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:19e-3f57c7ff:eb5c:542a6bc7:305}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ebbb:542a6bef:aa0-3f57c7ff:ebbb:542a6bef:bf9}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ef42:542a6ce0:2ac-3f57c7ff:ef42:542a6ce0:3f7}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:f7d0:542a6d3a:5af-3f57c7ff:f7d0:542a6d3a:700}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eb5c:542a6bc7:192-3f57c7ff:eb5c:542a6bc7:2fa}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:efbe:542a6d09:842-3f57c7ff:efbe:542a6d09:99f}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:ed72:542a6c5e:50c-3f57c7ff:ed72:542a6c5e:65d}, {formatID=131075 gtrid_length=29 bqual_length=27 data=1--3f57c7ff:eeb2:542a6cb6:48d-3f57c7ff:eeb2:542a6cb6:5d7}]
10:45:43,730 (Thread-18) Found 58 xids in doubt

10:45:47,213 (Thread-18) +---- RESOURCE INITIATED RECOVERY completed
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:ecce:542a6c31:540) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:ecce:542a6c31:691
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 171 record
10:45:47,213 (Thread-18) StateManager::StateManager( 0:0:0:0 )
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.AbstractRecord_1] - AbstractRecord::AbstractRecord () - crash recovery constructor
10:45:47,213 (Thread-18) | RECOVERY XIDS for org.jboss.jms.server.recovery.MessagingXAResourceWrapper@2c8b18f5 contains -1217944454 ? true
10:45:47,213 (Thread-18) +---- RESOURCE INITIATED RECOVERY completed
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:ecce:542a6c31:540 -3f57c7ff:ecce:542a6c31:691) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:ecce:542a6c31:694
10:45:47,213 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_20] - Unpacked a 463 record
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_22] - HeuristicList - Unpacked heuristic list size of 0
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_25] - Restored action status of ActionStatus.COMMITTING 6
10:45:47,214 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_26] - Restored action type Top-level 0
10:45:47,215 (Thread-18) [com.arjuna.ats.arjuna.coordinator.BasicAction_27] - Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
10:45:47,215 (Thread-18) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_1] - RecoverAtomicAction.replayPhase2 recovering -3f57c7ff:ecce:542a6c31:53b ActionStatus is ActionStatus.COMMITTED
10:45:47,215 (Thread-18) BasicAction::phase2Commit() for action-id -3f57c7ff:ecce:542a6c31:53b
10:45:47,215 (Thread-18) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@6fd5af22)
10:45:47,215 (Thread-18) XAResourceRecord.topLevelCommit for < 131075, 29, 27, 494545511025355995510210258101999910158535250975499514958535198455110253559955102102581019999101585352509754995149585351102 >
10:45:47,215 (Thread-18) [EMS] Recovery session will be created
10:45:47,216 (Thread-18) [EMS] Establishing handler for connection #-17

10:45:48,222 (Thread-18) BasicAction::updateState() for action-id -3f57c7ff:ecce:542a6c31:53b
10:45:48,222 (Thread-18) FileSystemStore.remove_committed(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:45:48,222 (Thread-18) ShadowingStore.remove_state(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:45:48,222 (Thread-18) HashedStore.genPathName(-3f57c7ff:ecce:542a6c31:53b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,222 (Thread-18) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#102#\-3f57c7ff_ecce_542a6c31_53b, FileLock.F_WRLCK, false)
10:45:48,223 (Thread-18) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#102#\-3f57c7ff_ecce_542a6c31_53b, null, null)
10:45:48,223 (Thread-18) [com.arjuna.ats.arjuna.recovery.RecoverAtomicAction_3] - RecoverAtomicAction.replayPhase2( -3f57c7ff:ecce:542a6c31:53b )  finished
10:45:48,223 (Thread-18) HashedStore.genPathName(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:45:48,223 (Thread-18) HashedStore.genPathName(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:45:48,224 (Thread-18) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:ef42:542a6ce0:26a, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:45:48,224 (Thread-18) InputObjectState::InputObjectState()
10:45:48,224 (Thread-18) HashedStore.allObjUids(/Recovery/TransactionStatusManager, InputObjectState Uid   : 0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , 0)
10:45:48,224 (Thread-18) OutputObjectState::OutputObjectState()

Transactional MDB on JBoss 5: look inside

10:36:49,975 (Connection consumer 120) BaseTransaction.begin
10:36:49,975 (Connection consumer 120) StateManager::StateManager( 2 )
10:36:49,971 (Connection consumer 115) [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:a2 adding Thread[Connection consumer 115,5,JBoss Pooled Threads] result = true
10:36:49,975 (Connection consumer 120) BasicAction::BasicAction()
10:36:49,976 (Connection consumer 120) BasicAction::Begin() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:49,976 (Connection consumer 120) BasicAction::actionInitialise() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:49,976 (Connection consumer 120) ActionHierarchy::ActionHierarchy(5)
10:36:49,976 (Connection consumer 120) ActionHierarchy::add(-3f57c7ff:eafe:542a6b9a:ab, 1)
10:36:49,976 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:ab adding Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:49,976 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action -3f57c7ff:eafe:542a6b9a:ab adding Thread[Connection consumer 120,5,JBoss Pooled Threads] result = true
10:36:49,979 (Connection consumer 120) TransactionReaper::create ( 120000 )
10:36:49,979 (Connection consumer 120) TransactionReaper::insert ( BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING, 300 )
10:36:49,979 (Connection consumer 120) ReaperElement::ReaperElement ( BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING, 300 )
10:36:49,979 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue started transaction=TransactionImple < ac, BasicAction: -3f57c7ff:eafe:542a6b9a:ab status: ActionStatus.RUNNING >
10:36:49,979 (Connection consumer 120) TransactionImple.enlistResource ( com.tibco.tibjms.XResource@4f9ee648 )
10:36:49,979 (Connection consumer 120) TransactionImple.getStatus
10:36:49,980 (Connection consumer 115) TransactionReaper::create ( 120000 )
10:36:49,980 (Connection consumer 120) StateManager::StateManager( 1 )
10:36:49,980 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:ad, 1)
10:36:49,971 (Thread-15) ReaperThread.run ()
10:36:49,980 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 > )
10:36:49,980 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:ad
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue enlisted=com.tibco.tibjms.XResource@4f9ee648
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue in use by public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message) Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:49,980 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue delivering
10:36:51,262 [org.jboss.ejb3.pool.StrictMaxPool] (Connection consumer 120) Acquired(true) strictMaxSize semaphore, remaining=0

10:36:51,262 INFO  [STDOUT] (Connection consumer 120) Received text: 2014-09-30T10:35:10.304+02:00 on test.fw1, id=ID:EMS-SERVER-DC2.2354542947B3299:101

10:36:52,330 (Connection consumer 120) TransactionImple.registerSynchronization
10:36:52,331 (Connection consumer 120) TransactionImple.enlistResource ( org.jboss.resource.adapter.jdbc.xa.XAManagedConnection@5c675382 )
10:36:52,331 (Connection consumer 120) TransactionImple.getStatus
10:36:52,331 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:1d1, 1)
10:36:52,331 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 > )
10:36:52,333 (Connection consumer 120) TransactionImple.enlistResource ( org.jboss.resource.adapter.jms.JmsXAResource@21f7e1c6 )
10:36:52,333 (Connection consumer 120) TransactionImple.getStatus
10:36:52,333 (Connection consumer 120) StateManager::StateManager( 1 )
10:36:52,333 (Connection consumer 120) AbstractRecord::AbstractRecord (-3f57c7ff:eafe:542a6b9a:1d7, 1)
10:36:52,333 (Connection consumer 120) XAResourceRecord.XAResourceRecord ( < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 > )
10:36:52,360 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad -3f57c7ff:eafe:542a6b9a:1d1) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d7
10:36:52,361 (Connection consumer 120) TransactionImple.getStatus
10:36:52,361 (Connection consumer 120) TransactionImple.getStatus
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) Invocation took 2412ms: public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message)
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue in use by public abstract void javax.resource.spi.endpoint.MessageEndpoint.afterDelivery() throws javax.resource.ResourceException Thread[Connection consumer 120,5,JBoss Pooled Threads]
10:36:52,392 (Connection consumer 120) TransactionImple.equals
10:36:52,392 (Connection consumer 120) TransactionImple.getStatus
10:36:52,392 [org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy] (Connection consumer 120) MessageEndpoint TestQueue commit
10:36:52,392 (Connection consumer 120) BaseTransaction.commit
10:36:52,392 (Connection consumer 120) TransactionImple.commitAndDisassociate
10:36:52,392 (Connection consumer 120) SynchronizationImple.beforeCompletion

10:36:52,392 (Connection consumer 120) BasicAction::End() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,392 (Connection consumer 120) BasicAction::prepare () for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,392 (Connection consumer 120) ShadowingStore.ShadowingStore( 14 )
10:36:52,392 (Connection consumer 120) ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
10:36:52,392 (Connection consumer 120) HashedStore.HashedStore( 14 )
10:36:52,392 (Connection consumer 120) HashedStore.HashedActionStore()
10:36:52,392 (Connection consumer 120) FileSystemStore.setupStore()
10:36:52,392 (Connection consumer 120) FileSystemStore.createHierarchy(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\)
10:36:52,393 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 >
10:36:52,430 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:ad
10:36:52,430 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 >
10:36:52,494 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d1
10:36:52,494 (Connection consumer 120) XAResourceRecord.topLevelPrepare for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 >
10:36:52,556 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: -3f57c7ff:eafe:542a6b9a:ad -3f57c7ff:eafe:542a6b9a:1d1) : appending /StateManager/AbstractRecord/XAResourceRecord for -3f57c7ff:eafe:542a6b9a:1d7
10:36:52,557 (Connection consumer 120) OutputObjectState::OutputObjectState(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,557 (Connection consumer 120) BasicAction::save_state ()
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_14] - BasicAction::save_state - next record to pack is a 171 record (/StateManager/AbstractRecord/XAResourceRecord) should save it? = true
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_15] - Packing a 171 record
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_16] - Packing a NONE_RECORD
10:36:52,557 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_19] - Packing action status of ActionStatus.COMMITTING
10:36:52,557 (Connection consumer 120) FileSystemStore.write_committed(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,557 (Connection consumer 120) ShadowingStore.write_state(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,557 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,557 (Connection consumer 120) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, FileLock.F_WRLCK, true)
10:36:52,557 (Connection consumer 120) FileSystemStore.createHierarchy(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab)
10:36:52,647 (Connection consumer 120) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, null, java.io.FileOutputStream@7e1b811b)
10:36:52,651 (Connection consumer 120) BasicAction::phase2Commit() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,651 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@4407393d)
10:36:52,651 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 26, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797589799 >
10:36:52,734 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@32955ada)
10:36:52,734 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910048 >
10:36:52,911 (Connection consumer 120) BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@1cc05dc2)
10:36:52,911 (Connection consumer 120) XAResourceRecord.topLevelCommit for < 131075, 28, 27, 494545511025355995510210258101971021015853525097549857975897984551102535599551021025810197102101585352509754985797584910054 >
10:36:52,947 (Connection consumer 120) BasicAction::updateState() for action-id -3f57c7ff:eafe:542a6b9a:ab
10:36:52,947 (Connection consumer 120) FileSystemStore.remove_committed(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
10:36:52,947 (Connection consumer 120) ShadowingStore.remove_state(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
10:36:52,947 (Connection consumer 120) HashedStore.genPathName(-3f57c7ff:eafe:542a6b9a:ab, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
10:36:52,947 (Connection consumer 120) FileSystemStore.openAndLock(C:\_dev\jboss-5.1.0.GA\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, FileLock.F_WRLCK, false)
10:36:52,948 (Connection consumer 120) FileSystemStore.closeAndUnlock(C:\_dev\jboss-5.1.0.GA\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#97#\-3f57c7ff_eafe_542a6b9a_ab, null, null)
10:36:52,948 (Connection consumer 120) SynchronizationImple.afterCompletion
10:36:52,948 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action -3f57c7ff:eafe:542a6b9a:ab removing TSThread:17
10:36:52,948 (Connection consumer 120) [com.arjuna.ats.arjuna.coordinator.BasicAction_9] -  BasicAction::removeChildThread () action -3f57c7ff:eafe:542a6b9a:ab removing TSThread:17 result = true

JBossTS stores

https://access.redhat.com/documentation/en-US/JBoss_Enterprise_Application_Platform/4.3/html/Transactions_Programmers_Guide/ch02s03s02.html

<!-- (default is BasicLockStore) --> <property name="com.arjuna.ats.txoj.lockstore.lockStoreType" value="BasicPersistentLockStore"/>

https://access.redhat.com/documentation/en-US/JBoss_Enterprise_Application_Platform/5/html/Transactions_Development_Guide/ch15.html

<property name="com.arjuna.ats.arjuna.coordinator.actionStore" value="HashedActionStore"/>

Globalny wynalazek IBM-a

Elektrownia słoneczna.

EMS datastores

EMS handles datastores by using dedicated threads, having heavily utilized queues on separated stores is a wise step to dismiss 'slow clock' warnings.

JBoss 7.4 (RedHat EAP 6.3) and MDB XA

It is possible to setup XA on EAP 6.3, however there is a minor problem with recovery:

14:53:47,756 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac1211d8:-30ef1c07:541c1f35:24dc, node_name=1, branch_uid=0:ffffac1211d8:-30ef1c07:541c1f35:24fa, subordinatenodename=null, eis_name=java:/sun/XAQueueConnectionFactory >, heuristic: TwoPhaseOutcome.FINISH_OK, product: x/X, jndiName: java:/sun/XAQueueConnectionFactory com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@1c554391 >
14:53:47,756 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016038: No XAResource to recover < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac1211d8:-30ef1c07:541c1f35:24dc, node_name=1, branch_uid=0:ffffac1211d8:-30ef1c07:541c1f35:24fa, subordinatenodename=null, eis_name=java:/sun/XAQueueConnectionFactory >
14:53:47,800 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac1211d8:-30ef1c07:541c1f35:2e9a, node_name=1, branch_uid=0:ffffac1211d8:-30ef1c07:541c1f35:2ea6, subordinatenodename=null, eis_name=java:/XAOracleDS >, heuristic: TwoPhaseOutcome.FINISH_OK, product: Oracle/Oracle Database 11g Express Edition Release 11.2.0.2.0 - Production, jndiName: java:/XAOracleDS com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@2ebed222 >
14:53:47,800 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016038: No XAResource to recover < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac1211d8:-30ef1c07:541c1f35:2e9a, node_name=1, branch_uid=0:ffffac1211d8:-30ef1c07:541c1f35:2ea6, subordinatenodename=null, eis_name=java:/XAOracleDS >

Transaction log has orphaned entries, which do not exists on remote Resource Managers. We can live with it.

Konfiguracja dbstore.properties dla EMS-a

hibernate.cache.use_second_level_cache=false
hibernate.current_session_context_class=thread
hiberate.cache.provider_class=org.hibernate.cache.NoCacheProvider
hibernate.connection.provider_class=org.hibernate.connection.C3P0ConnectionProvider
hibernate.c3p0.connectionCustomizerClassName=com.tibco.tibems.tibemsd.internal.db.DataStoreConnectionCustomizer

# Hibernate optimization
hibernate.bytecode.use_reflection_optimizer=true
hibernate.jdbc.batch_size=50
hibernate.id.new_generator_mappings=true
javax.persistence.validation.mode=NONE
hibernate.c3p0.forceIgnoreUnresolvedTransactions=false

# Pool config
hibernate.c3p0.acquireIncrement=1
hibernate.c3p0.checkoutTimeout=10000
hibernate.c3p0.maxPoolSize=12
hibernate.c3p0.minPoolSize=4
hibernate.c3p0.numHelperThreads=6
hibernate.c3p0.maxStatementsPerConnection=100
hibernate.c3p0.maxIdleTimeExcessConnections=900
hibernate.c3p0.maxIdleTime=0
hibernate.c3p0.acquireRetryAttempts=20
hibernate.c3p0.acquireRetryDelay=3000
hibernate.c3p0.idleConnectionTestPeriod=0
# use connection.isvalid from JDBC 4.0
#hibernate.c3p0.preferredTestQuery=select 1 from dual
hibernate.c3p0.testConnectionOnCheckin=false
hibernate.c3p0.testConnectionOnCheckout=true
hibernate.generate_statistics=false

hibernate.connection.oracle.jdbc.StreamBufferSize = 8192
# Column size settings for storing messages
org.hibernate.dialect.Oracle10gDialect.small_len = 1024
org.hibernate.dialect.Oracle9iDialect.small_len = 1024

Jak działa dbstore w EMS-ie

Klasa Javy com.tibco.tibems.tibemsd.internal.db.CallableDataStore jest używana przez kod C++ (poprzez JNI) do trzymania bieżących danych sterujących oraz zapisywania i odczytywania komunikatów. Do zapisywania wszystkich obiektów służy Hibernate:

[2014-09-09 10:48:28,006] DEBUG [tibemsd] (AbstractBatcher.java:424) - insert into EMS_MESSAGES (MESSAGE_SEQNO, TYPE, PRIORITY, DELIVERYMODE, REDELIVERED, DELIVERY_COUNT, DESTINATION, DESTINATION_TYPE, EXPIRATION, TIMESTAMP, DELIVERYTIME, REPLYTO, REPLYTO_TYPE, USERTYPE, MSGID, CORRELATIONID, COMPRESSED, CLIENTFLAGS, ENCODING, ENCODED_PROPERTIES, ENCODED_SUPPRESS_CONSIDS, TXNID, ZONEID, ROUTESRC, ROUTESEQNO, ROUTECONSID, PRODUCERID, DELETED, MESSAGE_SIZE, SMALL_MESSAGE_BODY, LARGE_MESSAGE_BODY, STORE_ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '337' to parameter: 1
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '3' to parameter: 2
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '4' to parameter: 3
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '2' to parameter: 4
[2014-09-09 10:48:28,006] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 5
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 6
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding 'test.fw1' to parameter: 7
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '1' to parameter: 8
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 9
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '1410252507549' to parameter: 10
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 11
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 12
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 13
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 14
[2014-09-09 10:48:28,007] TRACE [tibemsd] (NullableType.java:133) - binding 'ID:EMS-SERVER-DC2.23FC540EBDA24:2' to parameter: 15
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 16
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding 'false' to parameter: 17
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 18
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 19
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 20
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 21
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 22
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 23
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:126) - binding null to parameter: 24
[2014-09-09 10:48:28,008] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 25
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '0' to parameter: 26
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '1' to parameter: 27
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding 'false' to parameter: 28
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '123' to parameter: 29
[2014-09-09 10:48:28,009] TRACE [tibemsd] (NullableType.java:133) - binding '337' to parameter: 32
[2014-09-09 10:48:28,085] DEBUG [tibemsd] (AbstractBatcher.java:424) - select message0_.STORE_ID as STORE1_17_0_, message0_.MESSAGE_SEQNO as MESSAGE2_17_0_, message0_.TYPE as TYPE17_0_, message0_.PRIORITY as PRIORITY17_0_, message0_.DELIVERYMODE as DELIVERY5_17_0_, message0_.REDELIVERED as REDELIVE6_17_0_, message0_.DELIVERY_COUNT as DELIVERY7_17_0_, message0_.DESTINATION as DESTINAT8_17_0_, message0_.DESTINATION_TYPE as DESTINAT9_17_0_, message0_.EXPIRATION as EXPIRATION17_0_, message0_.TIMESTAMP as TIMESTAMP17_0_, message0_.DELIVERYTIME as DELIVER12_17_0_, message0_.REPLYTO as REPLYTO17_0_, message0_.REPLYTO_TYPE as REPLYTO14_17_0_, message0_.USERTYPE as USERTYPE17_0_, message0_.MSGID as MSGID17_0_, message0_.CORRELATIONID as CORRELA17_17_0_, message0_.COMPRESSED as COMPRESSED17_0_, message0_.CLIENTFLAGS as CLIENTF19_17_0_, message0_.ENCODING as ENCODING17_0_, message0_.ENCODED_PROPERTIES as ENCODED21_17_0_, message0_.ENCODED_SUPPRESS_CONSIDS as ENCODED22_17_0_, message0_.TXNID as TXNID17_0_, message0_.ZONEID as ZONEID17_0_, message0_.ROUTESRC as ROUTESRC17_0_, message0_.ROUTESEQNO as ROUTESEQNO17_0_, message0_.ROUTECONSID as ROUTECO27_17_0_, message0_.PRODUCERID as PRODUCERID17_0_, message0_.DELETED as DELETED17_0_, message0_.MESSAGE_SIZE as MESSAGE30_17_0_, message0_.SMALL_MESSAGE_BODY as SMALL31_17_0_, message0_.LARGE_MESSAGE_BODY as LARGE32_17_0_ from EMS_MESSAGES message0_ where message0_.STORE_ID=?
[2014-09-09 10:48:28,085] TRACE [tibemsd] (NullableType.java:133) - binding '247' to parameter: 1
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '247' as column: MESSAGE2_17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '3' as column: TYPE17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '4' as column: PRIORITY17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '2' as column: DELIVERY5_17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: REDELIVE6_17_0_
[2014-09-09 10:48:28,087] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: DELIVERY7_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning 'test.fw1' as column: DESTINAT8_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '1' as column: DESTINAT9_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: EXPIRATION17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '1410249505675' as column: TIMESTAMP17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: DELIVER12_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:166) - returning null as column: REPLYTO17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: REPLYTO14_17_0_
[2014-09-09 10:48:28,088] TRACE [tibemsd] (NullableType.java:166) - returning null as column: USERTYPE17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning 'ID:EMS-SERVER-DC2.32DC540EB2EE4:141' as column: MSGID17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: CORRELA17_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning 'false' as column: COMPRESSED17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: CLIENTF19_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ENCODING17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ENCODED21_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ENCODED22_17_0_
[2014-09-09 10:48:28,089] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: TXNID17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: ZONEID17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:166) - returning null as column: ROUTESRC17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: ROUTESEQNO17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '0' as column: ROUTECO27_17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '1' as column: PRODUCERID17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning 'false' as column: DELETED17_0_
[2014-09-09 10:48:28,090] TRACE [tibemsd] (NullableType.java:172) - returning '125' as column: MESSAGE30_17_0_

Gdyby numer sekwencji komunikatu był trzymany w bazie (Hibernate IdentifierGenerator = native/sequence) a nie był typem long trzymanym w pamięci to wiele instancji EMS-a mogłoby korzystać z tego samego schematu bazodanowego.

Why does EMS have poor client initialization concurrency?

"TibemsXAUniConnectionHandler/pushConnection-336" daemon prio=6 tid=0x000000000fbde000 nid=0x1e58 waiting for monitor entry [0x0000000026dce000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at com.tibco.tibjms.TibjmsxLinkTcp._createSocket(TibjmsxLinkTcp.java:797)
- waiting to lock <0x00000000fdea8b90> (a java.lang.Object)
at com.tibco.tibjms.TibjmsxLinkTcp.connect(TibjmsxLinkTcp.java:914)
at com.tibco.tibjms.TibjmsConnection._create(TibjmsConnection.java:1354)
at com.tibco.tibjms.TibjmsConnection.(TibjmsConnection.java:4320)
at com.tibco.tibjms.TibjmsXAConnection.(TibjmsXAConnection.java:30)
at com.tibco.tibjms.TibjmsXAQueueConnection.(TibjmsXAQueueConnection.java:29)
at com.tibco.tibjms.TibjmsxCFImpl._createImpl(TibjmsxCFImpl.java:164)
at com.tibco.tibjms.TibjmsxCFImpl._createConnection(TibjmsxCFImpl.java:253)
at com.tibco.tibjms.TibjmsXAQueueConnectionFactory.createXAQueueConnection(TibjmsXAQueueConnectionFactory.java:111)
at com.tibco.tibjms.XConnectionHandler$2.run(XConnectionHandler.java:201)

Process of connecting is degraded to single threaded processing due to private static Object _shutdownLock over which almost everything is synchronized inside TibjmsxLinkTcp class including socket creation and heartbeat processing. Fixing this lock (degrading from static) we step down from 8 seconds to 120ms on connection establishing while allocating 20 connections with 10 seconds heartbeat.