11:39 a.m.
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public (Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is Stopping.
NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
11:50 a.m.
New subject: [JBoss JIRA] Assigned: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=all ]
Jonathan Halliday reassigned JBTM-338:
--------------------------------------
Assignee: Andrew Dinn
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
12:17 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401372 ]
Dimitris Andreadis commented on JBTM-338:
-----------------------------------------
The jbossjta-properties.xml used is the stock one that comes with JBossTS 4.3.0.Beta2:
http://anonsvn.jboss.org/repos/repository.jboss.org/jboss/jbossts/4.3.0.B...
That particular test configuration executes a relatively small set of tests, so there
shouldn't be much tx activety there.
The long shutdown delay makes me think that the "reaper" thread is not
interrupted at shutdown time, and so it waits until the next run to perform a recovery
cycle and shutdown afterwards?
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
12:19 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401373 ]
Dimitris Andreadis commented on JBTM-338:
-----------------------------------------
I would also like to see the "Dynamic" reaper mode algorightm explained in the
documentation (I couldn't find how the timeout is calculated).
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
12:25 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401375 ]
Jonathan Halliday commented on JBTM-338:
----------------------------------------
Recovery and the reaper thread (which processes timedout transactions) are not related,
don't confuse them.
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
12:56 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401382 ]
Mark Little commented on JBTM-338:
----------------------------------
Which documentation did you read on Dynamic mode? It's in the JBossTS docs. Has been
for about 10 years.
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
12:59 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401384 ]
Andrew Dinn commented on JBTM-338:
----------------------------------
The periodic recovery thread is stopped from TransactionManagerService.destroyService()
which logs an info message,
"Stopping recovery manager". This message does not appear in the server log
which makes me question whether
the error is in the AS shutdown. If destroyService() gets called then I cannot see how the
recovery manager thread can
fail to stop. (I did identify a race condition in stopping the socket listener worker
thread but that's not the one that is
repeatedly printing recovery messages).
n.b. TransactionManagerService does not implement the stopService() method. Is the AS
sending this message
but failing to invoke destroyService()?
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
3:45 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401406 ]
Dimitris Andreadis commented on JBTM-338:
-----------------------------------------
I'm just checking a normal shutdown and I can see that the tx manager properly stops:
2008-03-05 16:37:42,609 DEBUG [org.jboss.system.ServiceController] stopping service:
jboss:service=TransactionManager
2008-03-05 16:37:42,609 DEBUG [com.arjuna.ats.jbossatx.jta.TransactionManagerService]
Stopping jboss:service=TransactionManager
2008-03-05 16:37:42,609 DEBUG [com.arjuna.ats.jbossatx.jta.TransactionManagerService]
Stopped jboss:service=TransactionManager
2008-03-05 16:37:42,609 DEBUG [org.jboss.system.ServiceController] destroying service:
jboss:service=TransactionManager
2008-03-05 16:37:42,609 DEBUG [com.arjuna.ats.jbossatx.jta.TransactionManagerService]
Destroying jboss:service=TransactionManager
2008-03-05 16:37:42,609 INFO [com.arjuna.ats.jbossatx.jta.TransactionManagerService]
Stopping recovery manager
2008-03-05 16:37:42,609 DEBUG [com.arjuna.ats.jbossatx.jta.TransactionManagerService]
Destroyed jboss:service=TransactionManager
2008-03-05 16:37:42,609 DEBUG [org.jboss.system.ServiceController] removing service:
jboss:service=TransactionManager
2008-03-05 16:37:42,609 DEBUG [org.jboss.system.ServiceCreator] Removing mbean from
server: jboss:service=TransactionManage
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
3:49 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401408 ]
Dimitris Andreadis commented on JBTM-338:
-----------------------------------------
From that same default shutdown, I can also see the JBoss Messaging
server peer stopping properly, so maybe this is the culprit of the delay:
2008-03-05 16:37:41,437 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-05 16:37:41,437 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is Stopping.
NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-05 16:37:41,437 DEBUG
[org.jboss.jms.server.connectionfactory.ConnectionFactoryJNDIMapper] stopped
2008-03-05 16:37:41,546 INFO [org.jboss.jms.server.ServerPeer] JMS ServerPeer[0] stopped
2008-03-05 16:37:41,546 DEBUG [org.jboss.jms.server.ServerPeer] Stopped
jboss.messaging:service=ServerPeer
...
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
Fix For: 4.3.0.BETA3
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
1:03 a.m.
New subject: [JBoss JIRA] Closed: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=all ]
Dimitris Andreadis closed JBTM-338.
-----------------------------------
Fix Version/s: (was: 4.3.0.BETA3)
Resolution: Rejected
I'm closing this issue, it doesn't seem to be caused by the transaction service.
It is most probably a jboss messaging issue, but we haven't identified yet.
Thanks.
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
6:08 p.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12401872 ]
Tim Fox commented on JBTM-338:
------------------------------
Can you do a killall -3 java and provide the java stack traces for when the server is in
it hung state shutting down?
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
1:53 a.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12410626 ]
rich bodo commented on JBTM-338:
--------------------------------
I see this frequently on my jboss install. Just reporting the environment because
it's different:
Centos 5.1 x86_64
java version "1.5.0_15"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_15-b04)
Java HotSpot(TM) Server VM (build 1.5.0_15-b04, mixed mode)
We're running jboss-4.2.0.GA
Shutdown seems to go well, but then it looks like the arjuna periodic recovery thread just
refuses to quit.
I'll get this installed elsewhere and try to get a stack trace:
2008-04-24 04:25:24,722 INFO [org.jboss.system.server.Server] Server exit(0) called
2008-04-24 04:25:36,973 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Thu, 24 Apr 2008 04:25:36>
2008-04-24 04:25:36,973 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-04-24 04:25:36,973 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - f
irst pass
2008-04-24 04:25:36,973 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first p
ass
2008-04-24 04:25:46,977 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Thu, 24 Apr 2008 04:25:46>
2008-04-24 04:25:46,977 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-04-24 04:25:46,977 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - s
econd pass
2008-04-24 04:25:46,977 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-04-24 04:27:46,998 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Thu, 24 Apr 2008 04:27:46>
2008-04-24 04:27:46,998 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-04-24 04:27:46,998 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - f
irst pass
2008-04-24 04:27:46,998 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first p
ass
2008-04-24 04:27:57,001 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Thu, 24 Apr 2008 04:27:57>
2008-04-24 04:27:57,001 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-04-24 04:27:57,001 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - s
econd pass
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
9:55 a.m.
New subject: [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service
[ http://jira.jboss.com/jira/browse/JBTM-338?page=comments#action_12410663 ]
Andrew Dinn commented on JBTM-338:
----------------------------------
I see this frequently on my jboss install. Just reporting the
environment because it's different:
. . .
Centos 5.1 x86_64
. . .
Shutdown seems to go well, but then it looks like the arjuna periodic recovery thread
just refuses to quit.
If you had cared to scan all the comments before adding your 2 centos you would have
noticed that the
periodic recovery thread is not receiving the shutdown message because messaging is
blocking the
shutdown further upstream. So, no refusal going on here. I think you need to you look for
a (open)
messaging issue to hang your problem on (or create a new one). This one is closed.
Slow shutdown of the transaction service
----------------------------------------
Key: JBTM-338
URL: http://jira.jboss.com/jira/browse/JBTM-338
Project: JBoss Transaction Manager
Issue Type: Bug
Security Level: Public(Everyone can see)
Components: JTA Implementation
Affects Versions: 4.3.0.BETA2
Reporter: Dimitris Andreadis
Assigned To: Andrew Dinn
Priority: Critical
I'm looking in the jboss testsuite, at a group of tests that starts a custom jboss
config (jacc) and spotted this failed attempt to stop the server within 45secs.
http://hudson.qa.jboss.com/hudson/view/JBoss%20AS/job/JBoss-AS-5.0.x-Test...
...
[server:stop] Shutting down server: jacc
[server:stop] Shutting down server: /qa/tools/opt/jdk1.5.0_12/bin/java -cp
/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/bin/shutdown.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jbossall-client.jar:/qa/services/hudson/hudson_workspace/workspace/JBoss-AS-5.0.x-TestSuite-sun15/trunk/build/output/jboss-5.0.0.CR1/client/jboss-common.jar
org.jboss.Shutdown --server jnp://10.18.96.175:1099 --shutdown
[server:stop] shutdownTimeout will be=45
[server:stop] Failed to shutdown server "jacc" before timeout. Destroying the
process.
...
By digging further in the server.log you can see that most of the shutdown sequence is
completed within 1 second, but then almost a minute after the last logged message (58secs)
the arjuna periodic recovery thread is still active (see below) and this causes the
testsuite to kill the process.
JBossTS seems to not shutdown properly / in-time.
2008-03-04 04:38:43,432 DEBUG
[org.jboss.resource.connectionmanager.ManagedConnectionFactoryDeployment] Stopped
jboss.jca:service=ManagedConnectionFactory,name=JmsXA
2008-03-04 04:38:43,433 DEBUG [org.jboss.jms.server.ServerPeer] Stopping
jboss.messaging:service=ServerPeer
2008-03-04 04:38:43,433 INFO [org.jboss.jms.server.ServerPeer] ServerPeer[0] is
Stopping. NOTE! Stopping the server peer cleanly will NOT cause failover to occur
2008-03-04 04:39:41,452 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:39:41>
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:39:41,453 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:39:41,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:39:51>
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:39:51,454 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- first pass <Tue, 4 Mar 2008 04:41:51>
2008-03-04 04:41:51,457 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule:
first pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first
pass
2008-03-04 04:41:51,458 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery
- second pass <Tue, 4 Mar 2008 04:42:01>
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger]
AtomicActionRecoveryModule: Second pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N]
[com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second
pass
2008-03-04 04:42:01,460 DEBUG [com.arjuna.ats.jta.logging.loggerI18N]
[com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second
pass
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.jboss.com/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
5838
days inactive
5889
days old
jbossts-issues@lists.jboss.org
12 comments
6 participants
participants (6)
-
Andrew Dinn (JIRA) -
Dimitris Andreadis (JIRA)
-
Jonathan Halliday (JIRA)
-
Mark Little (JIRA)
-
rich bodo (JIRA)
-
Tim Fox (JIRA)