Very long startup time with 100% CPU on 3.3g

[cmgray]

We just upgraded to 3.3g and now each time we need to restart the Alfresco app, startup takes forever, usually longer than an hour.

Startup was quick, just a couple of minutes on 3.2.

It get to this point in the startup process

06:04:56,419 INFO  [org.alfresco.service.descriptor.DescriptorService] Alfresco started (Community): Current version 3.3.0 (2765) schema 4009 - Originally installed version 3.2.0 (r2 2440) schema 3300
06:05:00,593 INFO  [org.alfresco.util.OpenOfficeConnectionTester] The OpenOffice connection was re-established.‍‍

And then sits for up to an hour with the CPU's pegged and uses up every last bit of memory we throw at it.  (Up to 12GB now)

Eventually it starts, but a 1 hour restart is unpleasant.

Is anyone else seeing this?

[mrogers]

Is that just the first restart or does it happen every time?  

And in general Java will use all the memory that is allocated to it.  Was there anything that made you think there was a problem?

[bnice]

What does your log say?

[cmgray]

Is that just the first restart or does it happen every time?  

And in general Java will use all the memory that is allocated to it.  Was there anything that made you think there was a problem?

It is happening every time.  This morning I needed to restart and it took nearly an hour and half to get from the first line in this log to the final one when the web app was finally available to users.

07:23:01,228 INFO  [org.alfresco.util.OpenOfficeConnectionTester] The OpenOffice connection was re-established.
08:40:34,958 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 342 Web Scripts (+0 failed), 577 URLs
08:40:34,958 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 2 Package Description Documents (+0 failed) 
08:40:34,958 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 1 Schema Description Documents (+0 failed) 
08:40:34,960 INFO  [org.springframework.extensions.webscripts.AbstractRuntimeContainer] Initialised Repository Web Script Container (in 3887844.0ms)
08:40:34,960 INFO  [org.springframework.extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
08:40:34,961 INFO  [org.springframework.extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
08:40:40,304 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 225 Web Scripts (+0 failed), 232 URLs
08:40:40,306 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 8 Package Description Documents (+0 failed) 
08:40:40,306 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 0 Schema Description Documents (+0 failed) 
08:40:40,352 INFO  [org.springframework.extensions.webscripts.AbstractRuntimeContainer] Initialised Spring Surf Container Web Script Container (in 1276.385ms)
08:40:40,404 INFO  [org.springframework.extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
08:40:40,470 INFO  [org.springframework.extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
08:40:40,521 INFO  [org.springframework.extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
08:40:40,525 INFO  [org.springframework.extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
08:40:40,578 INFO  [org.springframework.extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
08:40:40,582 INFO  [org.springframework.extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
08:40:44,557 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 51 Web Scripts (+0 failed), 58 URLs
08:40:44,558 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 8 Package Description Documents (+0 failed) 
08:40:44,558 INFO  [org.springframework.extensions.webscripts.DeclarativeRegistry] Registered 0 Schema Description Documents (+0 failed) 
08:40:44,567 INFO  [org.springframework.extensions.webscripts.AbstractRuntimeContainer] Initialised Spring Surf Container Web Script Container (in 597.23596ms)
08:40:44,727 INFO  [org.springframework.extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
08:40:44,807 INFO  [org.springframework.extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
08:40:44,823 INFO  [org.springframework.extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
08:40:44,827 INFO  [org.springframework.extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
08:40:44,842 INFO  [org.springframework.extensions.webscripts.TemplateProcessorRegistry] Registered template processor freemarker for extension ftl
08:40:44,846 INFO  [org.springframework.extensions.webscripts.ScriptProcessorRegistry] Registered script processor javascript for extension js
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I have a 2 GB max set for the Java heap and I understand that Java will allocate most/all of that right away but the machine has 12GB of memory allocated to it.  Java uses its 2GB and something else (openoffice possibly) is sucking up the rest. 

There are no errors in the log or anything that I can see.  It just goes through normal startup, gets to the line where it says the OpenOffice connection was re-established.  Then the CPU usage goes to 100% and it does something for over an hour then finishes starting up.  The behavior is very repeatable.

[cmgray]

Another side-effect that we during this period of 100% cpu usage is that the number of open files is huge.  We usually go over 8000 open files during this time.  And then once the app finishes starting and the CPU's settle down, the number of open files drops to a few hundred.

The majority of the open files appear to be lucene-index files.

[cmgray]

I may have solved this.

Turns out that the user that starts alfresco no longer had access to a few folders within the lucene-indexes folder.  This was apparently causing the delay on startup because after fixing this it started up in just about 3 minutes instead of the 1.5 hours it had been taking.

So for now things look back to normal.