12 Replies Latest reply on Dec 11, 2009 10:20 AM by kukeltje

    deploy() takes an awefully LONG time

       

      deployment.addResourceFromClasspath(wfDefinitionFile).deploy();


      log snippet:
      ...
      2009-12-07 17:06:12,378 DEBUG Log4jLog - ----- beginning hibernate tx 26657129 --------------------------------------------------------
      2009-12-07 17:06:13,441 DEBUG Log4jLog - ----- committing hibernate tx 29076847 -------------------------------------------------------
      2009-12-07 17:06:13,534 DEBUG Log4jLog - acquired new id block [810001-820000]
      2009-12-07 17:07:36,815 DEBUG Log4jLog - ----- committing hibernate tx 22678464 -------------------------------------------------------
      


      Any idea what takes 1 minute and 23 seconds?

      Thanks

      Ajay

        • 1. Re: deploy() takes an awefully LONG time
          kukeltje

          Uhhmmmm I assume you have WAY more logging.... if so please post here. If not, it is very, very hard for us to help.

          • 2. Re: deploy() takes an awefully LONG time

            Sure. Here you go... The complete log leading upto this. The time lag occurs between 9:33:57 to 9:35:43. This is when the deploy() runs.

            PS: Could this be a timeout thing? Does deploy() go out to the internet, and try to retrieve a DTD file or something like that? We are behind a proxy, so that could be a problem.

            Any help / pointers will be appreciated.

            Thanks

            Ajay

            2009-12-10 09:33:52,191 INFO WorkflowEngineTest - Creating workflow engine
            2009-12-10 09:33:52,691 DEBUG Log4jLog - eagerly initializing org.jbpm.pvm.internal.id.DatabaseIdComposer
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.Environment <clinit>
            INFO: Hibernate 3.3.1.GA
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.Environment <clinit>
            INFO: hibernate.properties not found
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.Environment buildBytecodeProvider
            INFO: Bytecode provider name : javassist
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.Environment <clinit>
            INFO: using JDK 1.4 java.sql.Timestamp handling
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.Configuration configure
            INFO: configuring from resource: jbpm.hibernate.cfg.xml
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.Configuration getConfigurationInputStream
            INFO: Configuration resource: jbpm.hibernate.cfg.xml
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.Configuration addResource
            INFO: Reading mappings from resource : jbpm.repository.hbm.xml
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.repository.DeploymentImpl -> JBPM4_DEPLOYMENT
            Dec 10, 2009 9:33:52 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.repository.DeploymentProperty -> JBPM4_DEPLOYPROP
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.id.PropertyImpl -> JBPM4_PROPERTY
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.Configuration addResource
            INFO: Reading mappings from resource : jbpm.execution.hbm.xml
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.model.ExecutionImpl -> JBPM4_EXECUTION
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.type.Variable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.BlobVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.DateVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.DoubleVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.HibernateLongVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.HibernateStringVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.LongVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.NullVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.StringVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.type.variable.TextVariable -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.lob.Lob -> JBPM4_LOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.job.JobImpl -> JBPM4_JOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.job.MessageImpl -> JBPM4_JOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.model.op.ExecuteActivityMessage -> JBPM4_JOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.model.op.ExecuteEventListenerMessage -> JBPM4_JOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.job.CommandMessage -> JBPM4_JOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.job.TimerImpl -> JBPM4_JOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.Configuration addResource
            INFO: Reading mappings from resource : jbpm.history.hbm.xml
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.history.model.HistoryProcessInstanceImpl -> JBPM4_HIST_PROCINST
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.history.model.HistoryActivityInstanceImpl -> JBPM4_HIST_ACTINST
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryAutomaticInstanceImpl -> JBPM4_HIST_ACTINST
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryDecisionInstanceImpl -> JBPM4_HIST_ACTINST
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryTaskInstanceImpl -> JBPM4_HIST_ACTINST
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.history.model.HistoryTaskImpl -> JBPM4_HIST_TASK
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.history.model.HistoryVariableImpl -> JBPM4_HIST_VAR
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.history.model.HistoryDetailImpl -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryCommentImpl -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryProcessInstanceMigrationImpl -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryPriorityUpdateImpl -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryTaskAssignmentImpl -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryTaskDuedateUpdateImpl -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindSubclass
            INFO: Mapping subclass: org.jbpm.pvm.internal.history.model.HistoryVariableUpdateImpl -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.Configuration addResource
            INFO: Reading mappings from resource : jbpm.task.hbm.xml
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.task.TaskImpl -> JBPM4_TASK
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.task.ParticipationImpl -> JBPM4_PARTICIPATION
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.task.SwimlaneImpl -> JBPM4_SWIMLANE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.Configuration addResource
            INFO: Reading mappings from resource : jbpm.identity.hbm.xml
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.identity.impl.UserImpl -> JBPM4_ID_USER
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.identity.impl.MembershipImpl -> JBPM4_ID_MEMBERSHIP
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindRootPersistentClassCommonValues
            INFO: Mapping class: org.jbpm.pvm.internal.identity.impl.GroupImpl -> JBPM4_ID_GROUP
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.Configuration doConfigure
            INFO: Configured SessionFactory: null
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.repository.DeploymentImpl.resources -> JBPM4_LOB
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.repository.DeploymentImpl.objectProperties -> JBPM4_DEPLOYPROP
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.model.ExecutionImpl.variables -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.model.ExecutionImpl.systemVariables -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.model.ExecutionImpl.executions -> JBPM4_EXECUTION
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.model.ExecutionImpl.swimlanes -> JBPM4_SWIMLANE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryProcessInstanceImpl.historyActivityInstances -> JBPM4_HIST_ACTINST
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryProcessInstanceImpl.historyVariables -> JBPM4_HIST_VAR
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryProcessInstanceImpl.details -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryActivityInstanceImpl.details -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryTaskImpl.details -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryTaskImpl.historyVariables -> JBPM4_HIST_VAR
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryTaskImpl.subTasks -> JBPM4_HIST_TASK
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryVariableImpl.details -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.history.model.HistoryCommentImpl.replies -> JBPM4_HIST_DETAIL
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.task.TaskImpl.participations -> JBPM4_PARTICIPATION
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.task.TaskImpl.variables -> JBPM4_VARIABLE
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.task.TaskImpl.subTasks -> JBPM4_TASK
            Dec 10, 2009 9:33:53 AM org.hibernate.cfg.HbmBinder bindCollectionSecondPass
            INFO: Mapping collection: org.jbpm.pvm.internal.task.SwimlaneImpl.participations -> JBPM4_PARTICIPATION
            Dec 10, 2009 9:33:53 AM org.hibernate.connection.DriverManagerConnectionProvider configure
            INFO: Using Hibernate built-in connection pool (not for production use!)
            Dec 10, 2009 9:33:53 AM org.hibernate.connection.DriverManagerConnectionProvider configure
            INFO: Hibernate connection pool size: 20
            Dec 10, 2009 9:33:53 AM org.hibernate.connection.DriverManagerConnectionProvider configure
            INFO: autocommit mode: false
            Dec 10, 2009 9:33:53 AM org.hibernate.connection.DriverManagerConnectionProvider configure
            INFO: using driver: oracle.jdbc.driver.OracleDriver at URL: jdbc:oracle:thin:@(DESCRIPTION =(ADDRESS =
             (PROTOCOL = TCP)(HOST = LON3230XUS.fm.rbsgrp.net)(PORT =
             1621))(ADDRESS = (PROTOCOL = TCP)(HOST =
             LON3231XUS.fm.rbsgrp.net)(PORT = 1621)) (LOAD_BALANCE =
             yes)(CONNECT_DATA = (SERVER = DEDICATED)(SERVICE_NAME = RSLONU)))
            Dec 10, 2009 9:33:53 AM org.hibernate.connection.DriverManagerConnectionProvider configure
            INFO: connection properties: {user=rates_services_dev_2_owner, password=****}
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: RDBMS: Oracle, version: Oracle Database 10g Enterprise Edition Release 10.2.0.2.0 - 64bit Production
            With the Partitioning, Real Application Clusters and Data Mining options
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: JDBC driver: Oracle JDBC driver, version: 10.2.0.1.0
            Dec 10, 2009 9:33:54 AM org.hibernate.dialect.Dialect <init>
            INFO: Using dialect: org.hibernate.dialect.Oracle10gDialect
            Dec 10, 2009 9:33:54 AM org.hibernate.transaction.TransactionFactoryFactory buildTransactionFactory
            INFO: Using default transaction strategy (direct JDBC transactions)
            Dec 10, 2009 9:33:54 AM org.hibernate.transaction.TransactionManagerLookupFactory getTransactionManagerLookup
            INFO: No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Automatic flush during beforeCompletion(): disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Automatic session close at end of transaction: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: JDBC batch size: 15
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: JDBC batch updates for versioned data: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Scrollable result sets: enabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: JDBC3 getGeneratedKeys(): disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Connection release mode: auto
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Default batch fetch size: 1
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Generate SQL with comments: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Order SQL updates by primary key: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Order SQL inserts for batching: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory createQueryTranslatorFactory
            INFO: Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
            Dec 10, 2009 9:33:54 AM org.hibernate.hql.ast.ASTQueryTranslatorFactory <init>
            INFO: Using ASTQueryTranslatorFactory
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Query language substitutions: {}
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: JPA-QL strict compliance: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Second-level cache: enabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Query cache: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory createRegionFactory
            INFO: Cache region factory : org.hibernate.cache.impl.NoCachingRegionFactory
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Optimize cache for minimal puts: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Structured second-level cache entries: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Statistics: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Deleted entity synthetic identifier rollback: disabled
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Default entity-mode: pojo
            Dec 10, 2009 9:33:54 AM org.hibernate.cfg.SettingsFactory buildSettings
            INFO: Named query checking : enabled
            Dec 10, 2009 9:33:54 AM org.hibernate.impl.SessionFactoryImpl <init>
            INFO: building session factory
            Dec 10, 2009 9:33:55 AM org.hibernate.impl.SessionFactoryObjectFactory addInstance
            INFO: Not binding factory to JNDI, no JNDI name configured
            2009-12-10 09:33:55,769 DEBUG Log4jLog - ----- beginning hibernate tx 31633330 --------------------------------------------------------
            2009-12-10 09:33:56,457 INFO Log4jLog - jBPM version info: library[4.2], schema[null]
            2009-12-10 09:33:56,457 DEBUG Log4jLog - ----- committing hibernate tx 21719810 -------------------------------------------------------
            2009-12-10 09:33:56,550 DEBUG WorkflowEngineImpl - adding definition file [pretrade.jpdl.xml]
            2009-12-10 09:33:56,566 DEBUG Log4jLog - ----- beginning hibernate tx 27253707 --------------------------------------------------------
            2009-12-10 09:33:56,613 DEBUG Log4jLog - last id -2 was consumed. acquiring new block...
            2009-12-10 09:33:56,613 DEBUG Log4jLog - ----- beginning hibernate tx 19762893 --------------------------------------------------------
            2009-12-10 09:33:57,832 DEBUG Log4jLog - ----- committing hibernate tx 25894799 -------------------------------------------------------
            2009-12-10 09:33:57,910 DEBUG Log4jLog - acquired new id block [1340001-1350000]
            2009-12-10 09:35:43,908 DEBUG Log4jLog - ----- committing hibernate tx 1279942 -------------------------------------------------------
            2009-12-10 09:35:43,986 INFO WorkflowEngineTest - Creating workflow engine
            2009-12-10 09:35:44,002 DEBUG WorkflowEngineTest - ======== testWFStart START ========
            ...
            ...
            ... tests run fine here ...
            ...
            ...
            


            • 3. Re: deploy() takes an awefully LONG time
              kukeltje

              jBPM afaik has the xsd's in a local resolver so should not need to go to the internet. But it could be that (since the xsd changed in 4.2) this was overlooked.

              Regarding the logging.... Well, I (ofcourse ;-)) meant logging of what happens DURING the deploy. So if it turns out not to be a internet access thing, turn on logging of lots of other libraries. And before you say 'which?' I'd go for 'all' OR maybe run JBoss in debugging mode and put a breakpoint on the deploy and go from there.

              • 4. Re: deploy() takes an awefully LONG time

                 

                "kukeltje" wrote:
                jBPM afaik has the xsd's in a local resolver so should not need to go to the internet. But it could be that (since the xsd changed in 4.2) this was overlooked.

                Regarding the logging.... Well, I (ofcourse ;-)) meant logging of what happens DURING the deploy. So if it turns out not to be a internet access thing, turn on logging of lots of other libraries. And before you say 'which?' I'd go for 'all' OR maybe run JBoss in debugging mode and put a breakpoint on the deploy and go from there.



                I guess, if I had *that* log, I wouldn't be posting ;)

                • 5. Re: deploy() takes an awefully LONG time
                  kukeltje

                  Is there any reason you cannot configure log4j (or jdk logging) to log in more detail? Works fine here (and I'm serious, not joking or trying to make fun of you or anything)

                  Now (besides the internet access) It's like saying: "Hey, look at that car driving by, it is going slow. Can you tell me what is wrong with it?" :-)

                  • 6. Re: deploy() takes an awefully LONG time

                    This statement takes all the time:

                    ProcessDeployer.java line 134, method checkKey().
                    
                    
                     List<ProcessDefinition> existingProcesses = repositorySession.createProcessDefinitionQuery()
                     .processDefinitionName(processDefinitionName)
                     .list();
                    


                    Then the code goes on to perform a "find":
                     for (ProcessDefinition existingProcess: existingProcesses) {
                     if (!processDefinitionKey.equals(existingProcess.getKey())) {
                     deployment.addProblem("invalid key '"+processDefinitionKey+"' in process "+processDefinition.getName()+". Existing process has name '"+processDefinitionName+"' and key '"+processDefinitionKey+"'");
                     }
                     }
                    


                    uuumm.... shouldn't the query actually be performed at the database level !?!?

                    On top of that, here is the code that performs the actual query:

                     public Object execute(Session session) {
                     List<Map<String, Object>> propertyMaps = (List<Map<String, Object>>) super.execute(session);
                    
                     List<ProcessDefinition> processDefinitions = new ArrayList<ProcessDefinition>();
                     for (Map<String, Object> properties: propertyMaps) {
                     String deploymentId = properties.get("deploymentDbid").toString();
                     String objectName = (String)properties.get("objectName");
                     RepositorySession repositorySession = EnvironmentImpl.getFromCurrent(RepositorySession.class);
                     ProcessDefinitionImpl processDefinition = (ProcessDefinitionImpl) repositorySession.getObject(deploymentId, objectName);
                     processDefinitions.add(processDefinition);
                     }
                    
                     return processDefinitions;
                     }
                    


                    So, instead of loading everything from the database in one go, its loading data one row at a time! - FROM THE DATABASE !! HOLY PENGUIN!

                    Whats going on?

                    The symptom is magnified, by the fact that the process is running in US, and the database is in UK!

                    Or am I using it wrong?

                    Ajay

                    • 7. Re: deploy() takes an awefully LONG time

                      Changing the database location from cross continent to local fixes the time issue.

                      I think I should file this as a bug. Database developers should be frugal with resources.

                      What do you think?

                      Ajay

                      • 8. Re: deploy() takes an awefully LONG time
                        saraswati.santanu

                        Ajay,
                        I did not get the first part of your question

                        shouldn't the query actually be performed at the database level !?!?


                        The query will be performed at the db only.
                        Do you mean a db procedure kind of thing? That will have other significant disadvantages. So that query there looks fine.

                        About the second part, where the query seems to be fired in a loop - I think the goal should be to fire less number of queries. Though it appears that the queries are fired in a loop, but making query in that way actually will result in less number of queries (in fact no query to db most of the time). If you try to aggregate values and fire query then cache hit will not be possible most of the time.

                        • 9. Re: deploy() takes an awefully LONG time
                          kukeltje

                          I do not get it either. jBPM retrieves all processdefinitions with the same name (how many can that be, just several I think) and loops over that.

                          I again urge you to log additional things, you might e.g. have a problem with a reverse dns lookup why things take long...

                          So I would not file a bug for this since it most likely will be marked invalid.

                          • 10. Re: deploy() takes an awefully LONG time

                             

                            "saraswati.santanu" wrote:
                            Ajay,
                            I did not get the first part of your question

                            shouldn't the query actually be performed at the database level !?!?


                            The query will be performed at the db only.

                            Do you mean a db procedure kind of thing? That will have other significant disadvantages. So that query there looks fine.




                            Well... what I meant was that instead of querying for everything, loading everything, then performing a find in java code, shouldn't jBPM be creating a query criteria with the call that goes to the database? I mean, whats the point of loading everything in memory, and searching through it... databases are designed for tasks like these...


                            "saraswati.santanu" wrote:

                            About the second part, where the query seems to be fired in a loop - I think the goal should be to fire less number of queries. Though it appears that the queries are fired in a loop, but making query in that way actually will result in less number of queries (in fact no query to db most of the time). If you try to aggregate values and fire query then cache hit will not be possible most of the time.


                            I think is some misunderstanding here. I will code at the code again, and comment.

                            Thanks

                            Ajay

                            • 11. Re: deploy() takes an awefully LONG time

                               

                              "kukeltje" wrote:
                              I do not get it either. jBPM retrieves all processdefinitions with the same name (how many can that be, just several I think) and loops over that.

                              I again urge you to log additional things, you might e.g. have a problem with a reverse dns lookup why things take long...

                              So I would not file a bug for this since it most likely will be marked invalid.


                              I can't seem to get my head around jbpm's logging. Do you have a log file I could use - that would generate the additional logs?

                              Here is what my log file looks like (DEBUG level, with NO class level filters):
                              log4j.rootLogger=DEBUG, A1
                              
                              log4j.appender.A1=org.apache.log4j.ConsoleAppender
                              log4j.appender.A1.layout=org.apache.log4j.PatternLayout
                              log4j.appender.A1.layout.ConversionPattern=%d %-5p %C{1} %3x - %m%n
                              


                              • 12. Re: deploy() takes an awefully LONG time
                                kukeltje

                                 

                                "ajaygautam" wrote:
                                "saraswati.santanu" wrote:
                                Ajay,
                                I did not get the first part of your question

                                shouldn't the query actually be performed at the database level !?!?


                                The query will be performed at the db only.

                                Do you mean a db procedure kind of thing? That will have other significant disadvantages. So that query there looks fine.




                                Well... what I meant was that instead of querying for everything, loading everything, then performing a find in java code, shouldn't jBPM be creating a query criteria with the call that goes to the database? I mean, whats the point of loading everything in memory, and searching through it... databases are designed for tasks like these...



                                It doesn't

                                List<ProcessDefinition> existingProcesses = repositorySession.createProcessDefinitionQuery()
                                 .processDefinitionName(processDefinitionName)
                                 .list();
                                


                                only retrieves those processdefinitions with the same name.In most production environments that will only be a few....