search

CloudSlang / cloud-slang

CloudSlang Language, CLI and Builder
http://cloudslang.io
Apache License 2.0
235 stars 82 forks source link

More then 15 sec for CLI to start on Ubuntu - version 0.7.29 [3] #294

Open meirwah opened 9 years ago

meirwah commented 9 years ago

2015-05-08 15:19:29:430 0 [main] INFO org.springframework.beans.factory.xml.XmlBeanDefinitionReader - Loading XML bean definitions from URL [jar:file:/home/cloudslang/cslang/cslang/lib/cloudslang-cli-0.7.29.jar!/META-INF/spring/spring-shell-plugin.xml] .... 2015-05-08 15:19:38:349 8919 [main] INFO org.hibernate.ejb.Ejb3Configuration - HHH000204: Processing PersistenceUnitInfo [ name: default ...] 2015-05-08 15:19:39:188 9758 [main] INFO org.hibernate.service.jdbc.connections.internal.ConnectionProviderInitiator - HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider 2015-05-08 15:19:39:825 10395 [main] INFO io.cloudslang.engine.dialects.ScoreDialectResolver - Database name is: H2 databaseMajorVersion is: 1 2015-05-08 15:19:39:861 10431 [main] INFO org.hibernate.dialect.Dialect - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect 2015-05-08 15:19:40:494 11064 [main] INFO org.hibernate.engine.transaction.internal.TransactionFactoryInitiator - HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jdbc.JdbcTransactionFactory 2015-05-08 15:19:40:516 11086 [main] INFO org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory - HHH000397: Using ASTQueryTranslatorFactory 2015-05-08 15:19:40:606 11176 [main] INFO org.hibernate.validator.internal.util.Version - HV000001: Hibernate Validator 4.3.0.Final 2015-05-08 15:19:41:036 11606 [main] INFO org.hibernate.tool.hbm2ddl.SchemaValidator - HHH000229: Running schema validator 2015-05-08 15:19:41:036 11606 [main] INFO org.hibernate.tool.hbm2ddl.SchemaValidator - HHH000102: Fetching database metadata 2015-05-08 15:19:41:063 11633 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_EXECUTION_STATE 2015-05-08 15:19:41:063 11633 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [execution_object, id, status, execution_id, branch_id] 2015-05-08 15:19:41:074 11644 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_FINISHED_BRANCHES 2015-05-08 15:19:41:074 11644 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [suspended_execution_id, id, split_id, execution_id, branch_exception, branch_id, branch_context] 2015-05-08 15:19:41:085 11655 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_PARTITION_GROUPS 2015-05-08 15:19:41:085 11655 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [id, last_roll_time, time_threshold, active_partition, name, size_threshold, group_size] 2015-05-08 15:19:41:094 11664 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_RUNNING_EXECUTION_PLANS 2015-05-08 15:19:41:094 11664 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [id, result, execution_plan_zipped, uuid, execution_plan] 2015-05-08 15:19:41:111 11681 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_SUSPENDED_EXECUTIONS 2015-05-08 15:19:41:111 11681 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [execution_object, id, split_id, execution_id, number_of_branches] 2015-05-08 15:19:41:140 11710 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_VERSION_COUNTERS 2015-05-08 15:19:41:140 11710 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [id, counter_version, counter_name] 2015-05-08 15:19:41:165 11735 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_WORKER_GROUPS 2015-05-08 15:19:41:165 11735 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [group_name, worker_id] 2015-05-08 15:19:41:183 11753 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_WORKER_LOCKS 2015-05-08 15:19:41:183 11753 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [id, uuid] 2015-05-08 15:19:41:209 11779 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000261: Table found: TESTDB.PUBLIC.OO_WORKER_NODES 2015-05-08 15:19:41:209 11779 [main] INFO org.hibernate.tool.hbm2ddl.TableMetadata - HHH000037: Columns: [bulk_number, os, ack_time, ack_version, status, is_active, jvm, host_name, password, wrv, id, is_deleted, dot_net_version, description, uuid, install_path] 2015-05-08 15:19:43:018 13588 [main] INFO io.cloudslang.engine.partitions.services.PartitionTemplateImpl - Registering callback class ExecutionStatesCallback for partition group [null] 2015-05-08 15:19:43:189 13759 [main] INFO io.cloudslang.engine.partitions.services.PartitionServiceImpl - Partition group [OO_EXECUTION_STATES] was created, with group size 2, and timeThreshold -1, and sizeThreshold 50000 2015-05-08 15:19:44:947 15517 [main] INFO org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler - Initializing ExecutorService 'scoreOrchestratorScheduler' 2015-05-08 15:19:45:652 16222 [main] INFO io.cloudslang.worker.management.services.OutboundBufferImpl - maxBufferWeight = 10000 2015-05-08 15:19:45:677 16247 [main] INFO io.cloudslang.worker.management.services.WorkerManager - Initialize worker with UUID: -1 2015-05-08 15:19:45:771 16341 [main] INFO io.cloudslang.worker.management.services.InBuffer - InBuffer capacity is set to :500, coolDownPollingMillis is set to :200 2015-05-08 15:19:45:939 16509 [main] INFO io.cloudslang.worker.management.WorkerRegistration - Registering worker -1 2015-05-08 15:19:45:940 16510 [main] INFO io.cloudslang.worker.management.WorkerRegistration - Creating worker... 2015-05-08 15:19:46:193 16763 [main] INFO io.cloudslang.worker.management.WorkerRegistration - Worker [-1] registered and activated 2015-05-08 15:19:46:204 16774 [main] INFO org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler - Initializing ExecutorService 'scoreWorkerScheduler' 2015-05-08 15:20:05:175 35745 [Thread-3] WARN io.cloudslang.engine.queue.services.recovery.WorkerRecoveryServiceImpl - Worker [-1] is up and will be recovered 2015-05-08 15:20:05:214 35784 [Thread-3] WARN io.cloudslang.engine.queue.services.recovery.WorkerRecoveryServiceImpl - Worker [-1] is going to be recovered 2015-05-08 15:20:05:387 35957 [Thread-3] WARN io.cloudslang.engine.queue.services.recovery.WorkerRecoveryServiceImpl - Worker [-1] recovery id done in 172 ms 2015-05-08 15:20:05:500 36070 [Thread-3] INFO io.cloudslang.worker.management.services.WorkerManager - Worker is up

orius123 commented 9 years ago

please check with release 0.7.35

meirwah commented 9 years ago

took <20 sec with version 0.7.35: 2015-05-31 13:32:33:951 0 [main] INFO org.springframework.beans.factory.xml.XmlBeanDefinitionReader - Loadi ... ... 2015-05-31 13:32:51:849 17898 [Thread-3] INFO io.cloudslang.worker.management.services.WorkerManager - Worker is up

meirwah commented 9 years ago

7 sec on this part alone:

2015-05-31 13:32:44:329 10378 [main] INFO org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler - Initializing ExecutorService 'scoreWorkerScheduler' 2015-05-31 13:32:51:708 17757 [Thread-3] WARN io.cloudslang.engine.queue.services.recovery.WorkerRecoveryServiceImpl - Worker [-1] is up and will be recovered

orius123 commented 9 years ago

how much time does it take now? what is good enough for us?

meirwah commented 9 years ago

it takes 17 sec.. we should lower this to around 3-4.. but lets start with seeing why "Initializing ExecutorService 'scoreWorkerScheduler'" is so time consuming...

oritstone commented 9 years ago

@meirwah check if it is still an issue

orius123 commented 9 years ago

This is what I think we can do.

@meirwah @oritstone @Bonczidai @natabeck @shajyhia anything else you think of? WDYT?

oritstone commented 9 years ago

@orius123 please add your investigation results of where the time is spent

meirwah commented 9 years ago

CloudSlang as a daemon? maybe we should understand why 'scoreWorkerScheduler' is so slow?

orius123 commented 9 years ago

my findings are the the majority of the time is around Jython and starting the DB and ORM stuff. On my machine starting the CLI takes ~11 secs.

There are more stuff but those are the big ones. Also, saw occasions when liquibase took much more (4+ sec)

orius123 commented 9 years ago

Regarding @meirwah comment. I don't think that the scoreWorkerScheduler print to the log is what takes so much time. I think that in the BG Liquibase and hibernate are running (or Jython) when this print is going out.

orius123 commented 9 years ago

@oritstone with my fixes at #400 is time reasonable?

meirwah commented 9 years ago

Maybe we can use this (https://github.com/jhipster/jhipster-sample-app/blob/master/src/main/java/com/mycompany/myapp/config/liquibase/AsyncSpringLiquibase.java) to cut time, thanks @orius123 for the tip !!