[jboss-user] [JBoss Portal] - JBOSS portal takes forever to start

Boris Bardak [http://community.jboss.org/people/borbar] created the discussion "JBOSS portal takes forever to start" To view the discussion, visit: http://community.jboss.org/message/582444#582444 -------------------------------------------------------------- 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. -------------------------------------------------------------- Reply to this message by going to Community [http://community.jboss.org/message/582444#582444] Start a new discussion in JBoss Portal at Community [http://community.jboss.org/choose-container!input.jspa?contentType=1&...]