[jbossts-issues] [JBoss JIRA] Commented: (JBTM-338) Slow shutdown of the transaction service

Wed Mar 5 06:17:57 EST 2008

    [ 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.BETA2/resources/jbossjta-properties.xml

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-TestSuite-sun15/426/console
> ...
> [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