JBOSS portal takes forever to start
Hi.We use JBoss Portal 2.7.2.
When we start Jboss portal, we have problem with CMS.It takes forever to start CMS.
When we starting Jboss portal,error was:
08:29:12,519 INFO [JBossCachePersistenceManager] Pre-loading the PersistenceMan
09:17:25,935 WARN [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id a000414:c982:4d36921b:b invoked while multiple threads active within it.
09:17:25,936 WARN [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action a000414:c982 :4d36921b:b aborting with 1 threads active!
In this case portal won't start.
After we increase timeout period from 300 to 10 000 (like this):
<!-- JBoss Transactions JTA -->
<mbean code="com.arjuna.ats.jbossatx.jta.TransactionManagerService"
name="jboss:service=TransactionManager">
<attribute name="TransactionTimeout">10000</attribute>
<attribute name="ObjectStoreDir">${jboss.server.data.dir}/tx-object-store</attribute>
</mbean>
Jboss Portal starts "normaly" but it takes forever to start!!!
INFO [org.jboss.portal.cms.impl.jcr.JCRCMS] Started JCR CMS in: 74m:53s:59ms
CMS is on FileSystem.
In server.log file it stops at this point:
12:26:49,658 INFO [JBossCachePersistenceManager] Pre-loading the PersistenceManager Cache for/wsp_node (finished).......
12:26:52,309 INFO [JBossCachePersistenceManager] Pre-loading the PersistenceManager Cache for/wsp_prop (finished).......
12:27:06,194 INFO [JBossCachePersistenceManager] Pre-loading the PersistenceManager Cache for/version_ref (finished).......
12:28:18,358 INFO [JBossCachePersistenceManager] Pre-loading the PersistenceManager Cache for/version_node (finished).......
12:33:26,756 INFO [JBossCachePersistenceManager] Pre-loading the PersistenceManager Cache for/version_prop (finished).......
and wait here forever.When we change log level it continuesly repeating this:
2011-01-21 13:07:34,262 DEBUG [org.hibernate.transaction.JTATransaction] commit
2011-01-21 13:07:34,262 DEBUG [org.jbpm.JbpmContext] end user JTA transaction
2011-01-21 13:07:34,263 DEBUG [org.jbpm.JbpmContext] end jta transation with COMMIT
2011-01-21 13:07:34,263 DEBUG [org.hibernate.transaction.CacheSynchronization] transaction before completion callback
2011-01-21 13:07:34,263 DEBUG [org.hibernate.transaction.CacheSynchronization] automatically flushing session
2011-01-21 13:07:34,263 DEBUG [org.hibernate.impl.SessionImpl] automatically flushing session
2011-01-21 13:07:34,263 DEBUG [org.hibernate.jdbc.JDBCContext] before transaction completion
2011-01-21 13:07:34,263 DEBUG [org.hibernate.impl.SessionImpl] before transaction completion
2011-01-21 13:07:34,263 DEBUG [org.hibernate.transaction.CacheSynchronization] transaction after completion callback, status: 3
2011-01-21 13:07:34,263 DEBUG [org.hibernate.jdbc.JDBCContext] after transaction completion
2011-01-21 13:07:34,263 DEBUG [org.hibernate.impl.SessionImpl] after transaction completion
2011-01-21 13:07:34,263 DEBUG [org.hibernate.transaction.CacheSynchronization] automatically closing session
2011-01-21 13:07:34,263 DEBUG [org.hibernate.impl.SessionImpl] automatically closing session
2011-01-21 13:07:34,263 DEBUG [org.hibernate.impl.SessionImpl] closing session
2011-01-21 13:07:34,263 DEBUG [org.hibernate.jdbc.ConnectionManager] connection already null in cleanup : no action
2011-01-21 13:07:34,263 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@4978fa
2011-01-21 13:07:34,264 DEBUG [org.jbpm.job.executor.JobExecutorThread] obtained locks on following jobs: []
2011-01-21 13:07:34,264 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, persistence]'
2011-01-21 13:07:34,264 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@1a59fb4
2011-01-21 13:07:34,264 DEBUG [org.jbpm.JbpmContext] start user JTA transaction
2011-01-21 13:07:34,264 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2011-01-21 13:07:34,264 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 5306825335865344
2011-01-21 13:07:34,264 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]])
2011-01-21 13:07:34,264 DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction
2011-01-21 13:07:34,264 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2011-01-21 13:07:34,264 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2011-01-21 13:07:34,264 DEBUG [org.hibernate.transaction.JTATransaction] begin
2011-01-21 13:07:34,264 DEBUG [org.hibernate.jdbc.JDBCContext] after transaction begin
2011-01-21 13:07:34,264 DEBUG [org.jbpm.persistence.db.DbPersistenceService] begun hibernate transaction org.hibernate.transaction.JTATransaction@a09e05
2011-01-21 13:07:34,265 DEBUG [org.hibernate.engine.query.QueryPlanCache] located HQL query plan in cache (
select job
from org.jbpm.job.Job as job
where ( (job.lockOwner is null) or (job.lockOwner = :lockOwner) )
and job.retries > 0
and job.isSuspended != true
order by job.dueDate asc
)
2011-01-21 13:07:34,265 DEBUG [org.hibernate.engine.query.QueryPlanCache] located HQL query plan in cache (
select job
from org.jbpm.job.Job as job
where ( (job.lockOwner is null) or (job.lockOwner = :lockOwner) )
and job.retries > 0
and job.isSuspended != true
order by job.dueDate asc
)
2011-01-21 13:07:34,265 DEBUG [org.hibernate.engine.query.HQLQueryPlan] find:
select job
from org.jbpm.job.Job as job
where ( (job.lockOwner is null) or (job.lockOwner = :lockOwner) )
and job.retries > 0
and job.isSuspended != true
order by job.dueDate asc
2011-01-21 13:07:34,265 DEBUG [org.hibernate.engine.QueryParameters] named parameters: {lockOwner=JbpmJobExector:10.0.4.20:1}
2011-01-21 13:07:34,265 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-01-21 13:07:34,265 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2011-01-21 13:07:34,265 DEBUG [org.hibernate.SQL]
/* named HQL query JobSession.getFirstDueJob */ select
job0_.ID_ as ID1_205_,
job0_.VERSION_ as VERSION3_205_,
job0_.DUEDATE_ as DUEDATE4_205_,
job0_.PROCESSINSTANCE_ as PROCESSI5_205_,
job0_.TOKEN_ as TOKEN6_205_,
job0_.TASKINSTANCE_ as TASKINST7_205_,
job0_.ISSUSPENDED_ as ISSUSPEN8_205_,
job0_.ISEXCLUSIVE_ as ISEXCLUS9_205_,
job0_.LOCKOWNER_ as LOCKOWNER10_205_,
job0_.LOCKTIME_ as LOCKTIME11_205_,
job0_.EXCEPTION_ as EXCEPTION12_205_,
job0_.RETRIES_ as RETRIES13_205_,
job0_.NAME_ as NAME14_205_,
job0_.REPEAT_ as REPEAT15_205_,
job0_.TRANSITIONNAME_ as TRANSIT16_205_,
job0_.ACTION_ as ACTION17_205_,
job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_205_,
job0_.GRAPHELEMENT_ as GRAPHEL19_205_,
job0_.NODE_ as NODE20_205_,
job0_.CLASS_ as CLASS2_205_
from
JBPM_JOB job0_
where
(
job0_.LOCKOWNER_ is null
or job0_.LOCKOWNER_=?
)
and job0_.RETRIES_>0
and job0_.ISSUSPENDED_<>true
order by
job0_.DUEDATE_ asc limit ?
2011-01-21 13:07:34,265 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
2011-01-21 13:07:34,266 DEBUG [org.hibernate.type.StringType] binding 'JbpmJobExector:10.0.4.20:1' to parameter: 1
2011-01-21 13:07:34,267 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2011-01-21 13:07:34,267 DEBUG [org.hibernate.loader.Loader] processing result set
2011-01-21 13:07:34,267 DEBUG [org.hibernate.loader.Loader] done processing result set (0 rows)
2011-01-21 13:07:34,267 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2011-01-21 13:07:34,267 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-01-21 13:07:34,267 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
2011-01-21 13:07:34,267 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2011-01-21 13:07:34,267 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
Finally,when CMS (after 70 to 80 minutes) is up everything else goes up very quicky.
We also use LDAP,Postgresql for portal and Hypersonic for AS.
Does anybody knows what to be a issue here?
OS is CentOS 5.3 32-bit.