Alfresco startup takes more than 30 min.

[martinsmith]

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 Userystem 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 Userystem INFO  [repo.module.ModuleServiceImpl] Found 2 module(s).
05:15:46,338 Userystem INFO  [repo.module.ModuleServiceImpl] Starting module 'cao-alfresco-amp' version 1.1.5.
05:15:46,495 Userystem 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 Userystem 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 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, alfinst]
05:15:50,979 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:50,979 Userystem INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:50,979 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:51,198 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, alfinst] complete
05:15:51,323 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, ldap1]
05:15:51,385 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 1 547ms
05:15:51,416 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:15:51,416 Userystem INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:15:51,416 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:15:51,854 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, ldap1] complete
05:15:51,854 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Synchronizing users and groups with user registry 'ldap1'
05:15:52,057 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving groups changed since 2015-05-28 09:48:44 from user registry 'ldap1'
05:15:52,166 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Commencing batch of 0 entries
05:15:52,166 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Completed batch of 0 entries
05:15:52,182 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving users changed since 2015-09-06 02:46:27 from user registry 'ldap1'
05:16:02,698 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Commencing batch of 10 entries
05:16:05,245 Userystem 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 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Completed batch of 10 entries
05:16:05,542 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Finished synchronizing users and groups with user registry 'ldap1'
05:16:05,542 Userystem 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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 74 486ms
05:17:05,871 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,014 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,999 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 985ms
05:20:10,609 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 10 641ms
05:20:11,640 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:22:46,835 Userystem INFO  [extensions.webscripts.DeclarativeRegistry] Registered 491 Web Scripts (+0 failed), 758 URLs
05:22:46,835 Userystem INFO  [extensions.webscripts.DeclarativeRegistry] Registered 2 Package Description Documents (+0 failed)
05:22:46,835 Userystem INFO  [extensions.webscripts.DeclarativeRegistry] Registered 1 Schema Description Documents (+0 failed)
05:22:46,835 Userystem 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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:30:01,098 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 1 031ms
05:30:07,192 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 6 891ms
05:30:07,989 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:40:00,001 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:40:00,845 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 844ms
05:40:07,111 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 6 938ms
05:40:07,783 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:45:00,102 Userystem 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 Userystem 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 Userystem 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 Userystem INFO  [repo.module.ModuleServiceImpl] Found 2 module(s).
05:18:39,575 Userystem INFO  [repo.module.ModuleServiceImpl] Starting module 'cao-alfresco-amp' version 1.1.5.
05:18:39,684 Userystem 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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:18:42,575 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, alfinst]
05:18:42,653 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:42,653 Userystem INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:42,653 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:42,825 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, alfinst] complete
05:18:42,825 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Starting 'Authentication' subsystem, ID: [Authentication, managed, ldap1]
05:18:42,887 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/version.properties]
05:18:42,887 Userystem INFO  [alfresco.config.JndiPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/alfresco-shared.properties]
05:18:42,887 Userystem INFO  [alfresco.config.FixedPropertyPlaceholderConfigurer] Loading properties file from class path resource [alfresco/domain/cache-strategies.properties]
05:18:43,028 Userystem INFO  [management.subsystems.ChildApplicationContextFactory] Startup of 'Authentication' subsystem, ID: [Authentication, managed, ldap1] complete
05:18:43,028 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Synchronizing users and groups with user registry 'ldap1'
05:18:43,059 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving groups changed since 2015-05-28 09:48:44 from user registry 'ldap1'
05:18:43,200 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Commencing batch of 0 entries
05:18:43,216 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 Group Analysis: Completed batch of 0 entries
05:18:43,216 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Retrieving users changed since 2015-09-07 04:01:26 from user registry 'ldap1'
05:18:43,544 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Commencing batch of 0 entries
05:18:43,544 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] ldap1 User Creation and Association: Completed batch of 0 entries
05:18:43,606 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] Finished synchronizing users and groups with user registry 'ldap1'
05:18:43,606 Userystem INFO  [security.sync.ChainingUserRegistrySynchronizer] 0 user(s) and 0 group(s) processed
05:18:43,622 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 1 234ms
05:19:11,763 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 29 422ms
05:19:13,153 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,014 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Execute action 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:00,796 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_send - 0 objects changed in 782ms
05:20:06,733 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Executing query: +TYPE:"omoffice_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 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Status check for ready_to_pass - 0 objects changed in 6 828ms
05:20:07,624 Userystem DEBUG [alfresco.action.VerifyObjectIndexActionExecuter] Action finished - 'verify-object-index-action' - {dry-run=false, lag-duration=10}
05:20:32,828 Userystem INFO  [extensions.webscripts.DeclarativeRegistry] Registered 491 Web Scripts (+0 failed), 758 URLs
05:20:32,828 Userystem INFO  [extensions.webscripts.DeclarativeRegistry] Registered 2 Package Description Documents (+0 failed)
05:20:32,828 Userystem INFO  [extensions.webscripts.DeclarativeRegistry] Registered 1 Schema Description Documents (+0 failed)
05:20:32,828 Userystem 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.

[afaust]

Hello,

it looks like schema validation and any operations that occur between schema validation and start of sysadmin subsystem are already costing you around 14 - 16 minutes alone.

These three log statements are interesting:
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]

One thing you can try for starters is to disable schema validation. This is typically only required for upgrade scenarios and not that relevant in the day-to-day operation. Also, I know from personal experience that Oracle can be slow when retrieving database metadata from a shared service (did not figure out why precisely) / larger database server.

Depending on how much that drops your startup time, I suggest you go ahead and add some SQL profiling / logging to your Alfresco system to see what Alfresco is talking with the database. Even if the database is fast, there may be an issue where Alfresco is talking "a lot" with the database which can slow things down depending on network overhead.
SQL logging can be added via P6Spy or other JDBC logging facades, if it is not possible to log / monitor on the DB server side.

One customer of ours once encountered a bug in Alfresco which would created thousands of unnecessary transactions due to bad scoping, which only hurt the customer due to a "larger than normal" network roundtrip time.

Regards
Axel

[andrewjones]

Hi there,

I have same problem - alfresco is ready to work after 48min!

I have no idea how to speed up this process

How exactly I can disable schema validation? I was going through alfresco-global.properties configuration file but no clue there.

Thanks
—

A.J.

[andrewjones]

Hi there,

I have same problem - alfresco is ready to work after 48min!

I have no idea how to speed up this process

How exactly I can disable schema validation? I was going through alfresco-global.properties configuration file but no clue there.

Thanks

[afaust]

See the documentation about <a href="http://docs.alfresco.com/4.2/concepts/maincomponents-disable.html">disabling Alfresco features</a>. Schema validation is part of the schema update feature.

[andrewjones]

Hi Axel,

thanks for fast answer. Just to be 100% sure is it db.schema.update=false? In documentation there is info: " Specifies whether the system bootstrap should create or upgrade the database schema automatically." - I'm not quite sure is it about schema validation?

Thanks

[mrogers]

No that is not schema validation, as far as I can see there is no property to control schema validation.   However schema validation does run after an upgrade so turning off upgrade also turns off the validation after the upgrade.

However you shouldn't be upgrading every time you start alfresco,  that's an abnormal condition.


Are you sure you are seeing exactly the same problem as the OP?   With an old version of alfresco and the same community oracle plug in?

Alfresco startup typically takes a couple of minutes. It can take longer on first start up and during an upgrade when patches are running.
It can also take a long time rebuilding the lucene indexes if an inconsistency is detected.

Anything else is unexpected.   It can for example take far longer if you are trying to run alfresco with too little memory or if there are network connectivity issues.

[andrewjones]

Hi, Thanks for participation in this conversation. I have same issue as OP but in my case startup takes up to 45-50 minutes. I have no Idea what's the cause. I don't know if the data from NAGIOS client  would be helpful - i.e. if I provide You info about moments when respective indicators are set on green (OK) status along with the repository logs?

[afaust]

Hello,

the most useful items for analyzing long startup times are the alfresco.log and any SQL profiling data you can gather. It is important to identify which parts of the startup are taking what percentages of the total time. I.e. there are also some features of Alfresco that pro-actively traverse / cache data structures that may delay startup due to sheer amount of data to process (and potentially cold DB caches), such as IMAP server functionality which as far as I remember caches the folder structure.
I don't believe Nagios will provide much interesting data apart from CPU / memory / network utilisation which might indicate resource bottlenecks in your configuration. But simply when what status changes to green should be too abstract for any meaningful analysis.

Regards
Axel