0 Replies Latest reply on Jan 21, 2011 4:17 PM by Boris Bardak

    JBOSS portal takes forever to start

    Boris Bardak Newbie

      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.