AnsweredAssumed Answered

Alfresco startup takes more than 30 min.

Question asked by martinsmith on Sep 8, 2015
Latest reply on Feb 16, 2016 by andrewjones
Hi,
I'm begginer in Alfresco. Lately our client ask us about Alfresco startup time reduction which takes more than 30 minutes.
Alfresco is  setup on one phisicall machine in number of two instances(Version :Community - v3.4.0 (d 3370)). Logs from startup shows that there is in total 22 minutes gap beetwen operation. I was trying to find some info on internet regarding phases of Alfresco startup process, but after two weeks I gave up. Is there any chcance to increase details of logs - I don't see such properties in log4j.properties file and also could not find them on internet. What is the average Alfresco startup time?

The system is operated by max 30 concurrent users.
The average number of queries per day is 5500
The server details: 2 x CPU Quad Core 2,0 GHz/32 GB RAM/Windows Server 2008 Enterprise R2/Tomcat 6.0.29

1)
05:01:27,574  INFO  [domain.schema.SchemaBootstrap] Schema managed by database dialect org.alfresco.repo.domain.hibernate.dialect.AlfrescoOracle9Dialect.
05:09:18,141  INFO  [domain.schema.SchemaBootstrap] No changes were made to the schema.

2)
05:09:18,141  INFO  [domain.schema.SchemaBootstrap] No changes were made to the schema.
05:15:28,166  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'sysAdmin' subsystem, ID: [sysAdmin, default]

3)
05:22:46,851  INFO  [extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
05:30:00,067 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}

The etire log file (for first 30 minutes) looks like this (alfresco instance no.1):

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/apps/alfresco1/tomcat/webapps/alfresco/WEB-INF/lib/slf4j-log4j12-1.5.10.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/apps/alfresco1/tomcat/webapps/alfresco/WEB-INF/lib/slf4j-log4j12-1.5.11.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
05:00:43,273  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alfresco/repository.properties]
05:00:43,367  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alfresco/domain/transaction.properties]
05:00:43,383  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from file [C:\apps\alfresco1\tomcat\webapps\alfresco\WEB-INF\classes\alfresco\module\cao-alfresco-amp\alfresco-global.properties]
05:00:43,383  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from file [C:\apps\alfresco1\tomcat\webapps\alfresco\WEB-INF\classes\alfresco\module\test\alfresco-global.properties]
05:00:43,383  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from file [C:\apps\alfresco1\tomcat\webapps\alfresco\WEB-INF\classes\alfresco\module\tests\alfresco-global.properties]
05:00:43,383  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from URL [file:/C:/apps/alfresco1/tomcat/shared/classes/alfresco-global.properties]
05:00:43,664  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:00:43,789  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:00:43,836  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:01:18,557  INFO  [extensions.webscripts.TemplateProcessorRegistry] Registered template processor Repository Template Processor for extension ftl
05:01:18,557  INFO  [extensions.webscripts.ScriptProcessorRegistry] Registered script processor Repository Script Processor for extension js
05:01:27,574  INFO  [domain.schema.SchemaBootstrap] Schema managed by database dialect org.alfresco.repo.domain.hibernate.dialect.AlfrescoOracle9Dialect.
05:09:18,141  INFO  [domain.schema.SchemaBootstrap] No changes were made to the schema.
05:15:28,166  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'sysAdmin' subsystem, ID: [sysAdmin, default]
05:15:28,276  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:28,276  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:28,276  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:28,369  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'sysAdmin' subsystem, ID: [sysAdmin, default] complete
05:15:33,088  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'thirdparty' subsystem, ID: [thirdparty, default]
05:15:33,119  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:33,119  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:33,119  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:34,651  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'thirdparty' subsystem, ID: [thirdparty, default] complete
05:15:34,651  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'OOoDirect' subsystem, ID: [OOoDirect, default]
05:15:34,713  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:34,713  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:34,713  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:36,994  WARN  [alfresco.util.OpenOfficeConnectionTester] An initial OpenOffice connection could not be established.
05:15:36,994  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'OOoDirect' subsystem, ID: [OOoDirect, default] complete
05:15:44,401  INFO  [repo.admin.ConfigurationChecker] The Alfresco root data directory ('dir.root') is: E:\alf_data
05:15:44,588  INFO  [admin.patch.PatchExecuter] Checking for patches to apply …
05:15:46,213  INFO  [admin.patch.PatchExecuter] No patches were required.
05:15:46,276 User:System INFO  [repo.module.ModuleServiceImpl] Found 2 module(s).
05:15:46,338 User:System INFO  [repo.module.ModuleServiceImpl] Starting module 'cao-alfresco-amp' version 1.1.5.
05:15:46,495 User:System INFO  [repo.module.ModuleServiceImpl] Starting module 'Oracle.for.Alfresco.3.4.a.Community' version 1.0.
05:15:46,510  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'fileServers' subsystem, ID: [fileServers, default]
05:15:46,557  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:46,557  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:46,557  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:47,557  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'fileServers' subsystem, ID: [fileServers, default] complete
05:15:47,557  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'imap' subsystem, ID: [imap, default]
05:15:47,588  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:47,604  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:47,604  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:47,870  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'imap' subsystem, ID: [imap, default] complete
05:15:47,870  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'email' subsystem, ID: [email, outbound]
05:15:47,885  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:47,885  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:47,885  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:48,026  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'email' subsystem, ID: [email, outbound] complete
05:15:48,026  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'email' subsystem, ID: [email, inbound]
05:15:48,041  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:48,041  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:48,041  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:48,120  WARN  [springframework.beans.GenericTypeAwarePropertyDescriptor] Invalid JavaBean property 'blockedSenders' being accessed! Ambiguous write methods found next to actually used [public void org.alfresco.email.server.EmailServer.setBlockedSenders(java.lang.String)]: [public void org.alfresco.email.server.EmailServer.setBlockedSenders(java.util.List)]
05:15:48,120  WARN  [springframework.beans.GenericTypeAwarePropertyDescriptor] Invalid JavaBean property 'allowedSenders' being accessed! Ambiguous write methods found next to actually used [public void org.alfresco.email.server.EmailServer.setAllowedSenders(java.util.List)]: [public void org.alfresco.email.server.EmailServer.setAllowedSenders(java.lang.String)]
05:15:48,135  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'email' subsystem, ID: [email, inbound] complete
05:15:48,135  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'googledocs' subsystem, ID: [googledocs, default]
05:15:48,151  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:48,151  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:48,151  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:49,666  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'googledocs' subsystem, ID: [googledocs, default] complete
05:15:49,666  INFO  [repo.usage.UserUsageTrackingComponent] Disabled - clear non-missing user usages …
05:15:49,838 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:15:50,838  INFO  [repo.usage.UserUsageTrackingComponent] Found 0 users to clear
05:15:50,838  INFO  [repo.usage.UserUsageTrackingComponent] … cleared non-missing usages for 0 users
05:15:50,838  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Synchronization' subsystem, ID: [Synchronization, default]
05:15:50,854  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:50,854  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:50,854  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:50,932 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, alfinst]
05:15:50,979 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:50,979 User:System INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:50,979 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:51,198 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_send" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 2
05:15:51,323 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, alfinst] complete
05:15:51,323 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, ldap1]
05:15:51,385 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 1 547ms
05:15:51,416 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:51,416 User:System INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:51,416 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:51,854 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, ldap1] complete
05:15:51,854 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Synchronizing users and groups with user registry 'ldap1'
05:15:52,057 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving groups changed since 2015-05-28 09:48:44 from user registry 'ldap1'
05:15:52,166 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Commencing batch of 0 entries
05:15:52,166 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Completed batch of 0 entries
05:15:52,182 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving users changed since 2015-09-06 02:46:27 from user registry 'ldap1'
05:16:02,698 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Commencing batch of 10 entries
05:16:05,245 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Processed 10 entries out of 10. 100% complete. Rate: 3 per second. 0 failures detected.
05:16:05,245 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Completed batch of 10 entries
05:16:05,542 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Finished synchronizing users and groups with user registry 'ldap1'
05:16:05,542 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] 10 user(s) and 0 group(s) processed
05:16:05,635  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Synchronization' subsystem, ID: [Synchronization, default] complete
05:16:05,760  INFO  [service.descriptor.DescriptorService] Alfresco JVM - v1.6.0_45-b06; maximum heap size 13721,625MB
05:16:05,760  INFO  [service.descriptor.DescriptorService] Alfresco started (Community): Current version 3.4.0 (d 3370) schema 4113 - Originally installed version 3.4.0 (d 3370) schema 4113
05:16:05,776  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Replication' subsystem, ID: [Replication, default]
05:16:05,776  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:16:05,776  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:16:05,776  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:16:05,792  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Replication' subsystem, ID: [Replication, default] complete
05:17:04,339 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_pass" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 3242
05:17:05,871 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 74 486ms
05:17:05,871 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,014 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,999 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_send" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 2
05:20:00,999 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 985ms
05:20:10,609 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_pass" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 3242
05:20:11,640 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 10 641ms
05:20:11,640 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:22:46,835 User:System INFO  [extensions.webscripts.DeclarativeRegistry] Registered 491 Web Scripts (+0 failed), 758 URLs
05:22:46,835 User:System INFO  [extensions.webscripts.DeclarativeRegistry] Registered 2 Package Description Documents (+0 failed)
05:22:46,835 User:System INFO  [extensions.webscripts.DeclarativeRegistry] Registered 1 Schema Description Documents (+0 failed)
05:22:46,835 User:System INFO  [extensions.webscripts.AbstractRuntimeContainer] Initialised Repository Web Script Container (in 397533.88ms)
05:22:46,851  INFO  [extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
05:22:46,851  INFO  [extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
05:30:00,067 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:30:01,098 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_send" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 2
05:30:01,098 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 1 031ms
05:30:07,192 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_pass" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 3242
05:30:07,989 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 6 891ms
05:30:07,989 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:40:00,001 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:40:00,845 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_send" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 2
05:40:00,845 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 844ms
05:40:07,111 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_pass" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 3242
05:40:07,783 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 6 938ms
05:40:07,783 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:45:00,102 User:System DEBUG [alfresco.action.OnDemandIndexTrackingActionExecuter] Execute action 'on-demand-index-tracking-action' - {dry-run=false, force=false, max-record-set-size=20000, days-back=-1}
05:45:55,950 User:System DEBUG [alfresco.action.OnDemandIndexTrackingActionExecuter] Action finished - 'on-demand-index-tracking-action' - {dry-run=false, force=false, max-record-set-size=20000, days-back=-1}
05:50:00,031 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}

2)The etire log file (for the first 20 minutes) looks like this (alfresco instance no.2):

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/apps/alfresco2/tomcat/webapps/alfresco/WEB-INF/lib/slf4j-log4j12-1.5.10.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/C:/apps/alfresco2/tomcat/webapps/alfresco/WEB-INF/lib/slf4j-log4j12-1.5.11.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
05:01:45,700  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alfresco/repository.properties]
05:01:45,731  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from class path resource [alfresco/domain/transaction.properties]
05:01:45,747  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from file [C:\apps\alfresco2\tomcat\webapps\alfresco\WEB-INF\classes\alfresco\module\cao-alfresco-amp\alfresco-global.properties]
05:01:45,747  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from file [C:\apps\alfresco2\tomcat\webapps\alfresco\WEB-INF\classes\alfresco\module\test\alfresco-global.properties]
05:01:45,747  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from file [C:\apps\alfresco2\tomcat\webapps\alfresco\WEB-INF\classes\alfresco\module\tests\alfresco-global.properties]
05:01:45,747  INFO  [alfresco.config.JndiPropertiesFactoryBean] Loading properties file from URL [file:/C:/apps/alfresco2/tomcat/shared/classes/alfresco-global.properties]
05:01:45,841  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:01:45,966  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:01:46,013  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:02:11,890  INFO  [extensions.webscripts.TemplateProcessorRegistry] Registered template processor Repository Template Processor for extension ftl
05:02:11,890  INFO  [extensions.webscripts.ScriptProcessorRegistry] Registered script processor Repository Script Processor for extension js
05:02:18,359  INFO  [domain.schema.SchemaBootstrap] Schema managed by database dialect org.alfresco.repo.domain.hibernate.dialect.AlfrescoOracle9Dialect.
05:11:19,838  INFO  [domain.schema.SchemaBootstrap] No changes were made to the schema.
05:18:27,012  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'sysAdmin' subsystem, ID: [sysAdmin, default]
05:18:27,137  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:27,137  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:27,137  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:27,231  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'sysAdmin' subsystem, ID: [sysAdmin, default] complete
05:18:30,059  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'thirdparty' subsystem, ID: [thirdparty, default]
05:18:30,137  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:30,137  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:30,137  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:30,340  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'thirdparty' subsystem, ID: [thirdparty, default] complete
05:18:30,340  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'OOoDirect' subsystem, ID: [OOoDirect, default]
05:18:30,387  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:30,403  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:30,403  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:31,809  WARN  [alfresco.util.OpenOfficeConnectionTester] An initial OpenOffice connection could not be established.
05:18:31,809  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'OOoDirect' subsystem, ID: [OOoDirect, default] complete
05:18:37,637  INFO  [repo.admin.ConfigurationChecker] The Alfresco root data directory ('dir.root') is: E:\alf_data
05:18:37,715  INFO  [admin.patch.PatchExecuter] Checking for patches to apply …
05:18:39,497  INFO  [admin.patch.PatchExecuter] No patches were required.
05:18:39,528 User:System INFO  [repo.module.ModuleServiceImpl] Found 2 module(s).
05:18:39,575 User:System INFO  [repo.module.ModuleServiceImpl] Starting module 'cao-alfresco-amp' version 1.1.5.
05:18:39,684 User:System INFO  [repo.module.ModuleServiceImpl] Starting module 'Oracle.for.Alfresco.3.4.a.Community' version 1.0.
05:18:39,700  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'fileServers' subsystem, ID: [fileServers, default]
05:18:39,762  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:39,762  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:39,762  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:40,591  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'fileServers' subsystem, ID: [fileServers, default] complete
05:18:40,591  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'imap' subsystem, ID: [imap, default]
05:18:40,622  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:40,622  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:40,622  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:40,700  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'imap' subsystem, ID: [imap, default] complete
05:18:40,700  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'email' subsystem, ID: [email, outbound]
05:18:40,716  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:40,716  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:40,716  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:40,809  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'email' subsystem, ID: [email, outbound] complete
05:18:40,809  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'email' subsystem, ID: [email, inbound]
05:18:40,856  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:40,856  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:40,856  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:40,997  WARN  [springframework.beans.GenericTypeAwarePropertyDescriptor] Invalid JavaBean property 'blockedSenders' being accessed! Ambiguous write methods found next to actually used [public void org.alfresco.email.server.EmailServer.setBlockedSenders(java.lang.String)]: [public void org.alfresco.email.server.EmailServer.setBlockedSenders(java.util.List)]
05:18:40,997  WARN  [springframework.beans.GenericTypeAwarePropertyDescriptor] Invalid JavaBean property 'allowedSenders' being accessed! Ambiguous write methods found next to actually used [public void org.alfresco.email.server.EmailServer.setAllowedSenders(java.util.List)]: [public void org.alfresco.email.server.EmailServer.setAllowedSenders(java.lang.String)]
05:18:41,012  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'email' subsystem, ID: [email, inbound] complete
05:18:41,012  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'googledocs' subsystem, ID: [googledocs, default]
05:18:41,091  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:41,091  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:41,091  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:42,262  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'googledocs' subsystem, ID: [googledocs, default] complete
05:18:42,262  INFO  [repo.usage.UserUsageTrackingComponent] Disabled - clear non-missing user usages …
05:18:42,356  INFO  [repo.usage.UserUsageTrackingComponent] Found 0 users to clear
05:18:42,356  INFO  [repo.usage.UserUsageTrackingComponent] … cleared non-missing usages for 0 users
05:18:42,356  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Synchronization' subsystem, ID: [Synchronization, default]
05:18:42,450  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:42,450  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:42,450  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:42,497 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:18:42,575 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, alfinst]
05:18:42,653 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:42,653 User:System INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:42,653 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:42,825 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, alfinst] complete
05:18:42,825 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, ldap1]
05:18:42,887 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:42,887 User:System INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:42,887 User:System INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:43,028 User:System INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, ldap1] complete
05:18:43,028 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Synchronizing users and groups with user registry 'ldap1'
05:18:43,059 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving groups changed since 2015-05-28 09:48:44 from user registry 'ldap1'
05:18:43,200 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Commencing batch of 0 entries
05:18:43,216 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Completed batch of 0 entries
05:18:43,216 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving users changed since 2015-09-07 04:01:26 from user registry 'ldap1'
05:18:43,544 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Commencing batch of 0 entries
05:18:43,544 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Completed batch of 0 entries
05:18:43,606 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] Finished synchronizing users and groups with user registry 'ldap1'
05:18:43,606 User:System INFO  [security.sync.ChainingUserRegistrySynchronizer] 0 user(s) and 0 group(s) processed
05:18:43,622 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_send" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 2
05:18:43,637  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Synchronization' subsystem, ID: [Synchronization, default] complete
05:18:43,700  INFO  [service.descriptor.DescriptorService] Alfresco JVM - v1.6.0_45-b06; maximum heap size 13721,625MB
05:18:43,700  INFO  [service.descriptor.DescriptorService] Alfresco started (Community): Current version 3.4.0 (d 3370) schema 4113 - Originally installed version 3.4.0 (d 3370) schema 4113
05:18:43,700  INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Replication' subsystem, ID: [Replication, default]
05:18:43,700  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:43,716  INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:43,716  INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:43,716  INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Replication' subsystem, ID: [Replication, default] complete
05:18:43,731 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 1 234ms
05:19:11,763 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_pass" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 3242
05:19:13,153 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 29 422ms
05:19:13,153 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,014 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,796 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_send" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 2
05:20:00,796 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 782ms
05:20:06,733 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omo:office_document_out" +@omo\:task:"ready_to_pass" +(@omo\:registration_date:[2013-01-01T00:00:00.000 TO MAX]) -@omo\:case_removed:"true" -@omo\:task:"removed" returns results: 3242
05:20:07,624 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 6 828ms
05:20:07,624 User:System DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:32,828 User:System INFO  [extensions.webscripts.DeclarativeRegistry] Registered 491 Web Scripts (+0 failed), 758 URLs
05:20:32,828 User:System INFO  [extensions.webscripts.DeclarativeRegistry] Registered 2 Package Description Documents (+0 failed)
05:20:32,828 User:System INFO  [extensions.webscripts.DeclarativeRegistry] Registered 1 Schema Description Documents (+0 failed)
05:20:32,828 User:System INFO  [extensions.webscripts.AbstractRuntimeContainer] Initialised Repository Web Script Container (in 106134.05ms)


I would be thankfull for any piece information for how to speed up Alfresco startup process.

Outcomes