topic Re: Afresco startup too slow in Alfresco Forum

Afresco startup too slow

luca — Wed, 15 Mar 2017 15:43:02 GMT

Hi All,I have some problems because Alfresco is taking too much to startup, actually it is taking 4 hours to complete.I'm using Alfresco CE 4.2.d and we currently have approximately 700K documents that takes 600GB in total.Can you help me why Alfresco is taking so much during startup?Monitoring the

Re: Afresco startup too slow

mehe — Wed, 15 Mar 2017 17:00:23 GMT

Hi Luca,

are you monitoring memory consumption on your system? But I don't know why alfresco tries to cache all the nodes...

We are using solr and are not encountering such boot times - normally alfresco boots within 5 minutes (about 1.000.000 docs). But if you depend heavily on transactional consistency on your index, you would have to brush up your code - solr works with eventual consistency, wich means simplified "if you do something, you won't find it immediately in your index, but later everything is fine".

My repository needs about 16GB of RAM for that amount of content, but solr also consumes a lot.

Have you tried to grant more memory to the JVM (and left enough for the OS)?

Is there something left in alfresco-global.properties that causes a full reindex on startup?

Is alfresco slow after the startup?

wishing the best for you

Re: Afresco startup too slow

luca — Wed, 15 Mar 2017 17:29:28 GMT

Hi Martin,

I have added a report that shows you that the the machine is ok, as far as I see.

That machine has 16GB of RAM and Alfresco is using 6GB of it.

The index recovery is set to index.recovery.mode=AUTO, so there shouldn't be a reindex at startup.

After startup Alfresco is not slow, I noticed only a problem when I try to configure an advanced workflow when I search for groups the service goes in timeout (log: WARN [org.alfresco.authorityTransactionalCache] [ajp-apr-8010-exec-1] Transactional update cache 'org.alfresco.authorityTransactionalCache' is full (10000).).

Could this be culprit of cache?

I tried to double the cache of nodes setting this:

cache.node.nodesSharedCache.tx.maxItems=250000

cache.node.nodesSharedCache.maxItems=2500000

But Alfresco became 30min slower 😞

Re: Afresco startup too slow

mehe — Wed, 15 Mar 2017 18:08:07 GMT

"Cache is full" is only a warning - so it's not the cause of your problem, but another symptom. Have you tried to decrease the cache size? If you say Alfresco is using 6GB, is it really using them or did you configure 6GB for the JVM?

Try to configure 8GB JVM memory then.

But everything smells like an Index problem. How long would it take to rebuild the complete index?

Personally I would switch to Solr in any case...

have to take some questions back, didn't realize the attached report on mobile...

Re: Afresco startup too slow

afaust — Wed, 15 Mar 2017 21:24:23 GMT

Luca _ wrote:
The index recovery is set to index.recovery.mode=AUTO, so there shouldn't be a reindex at startup.

Actually, the AUTO recovery mode will perform a FULL re-index if it finds that the index does not have a valid index when that index does not even properly contain the initial transactions.

Regarding the caches: having transactional caches reported as full is not a catastrophic problem but it can have very serious problems to system performance.

Also, the correct solution for this would NOT be to increase the cache sizes (that kind of lazy suggestion I see all the time), but to identify the operation that is causing that much data to be loaded into caches in the first place. No default operation in Alfresco out-of-the-box should overwhelm the caches provided your data structure is sane (e.g. no overly excessive use of groups or secondary child associations) and you don't do queries for insanely large amounts of data in jobs / actions / any other kind of operation within a single transaction.

Setting nodesSharedCache to 2.5 million is a bold move, especially with the Alfresco default caches. I hope you haven't also increased the nodeAspectsShareCache and/or nodePropertiesSharedCache... This would dramatically increase the amount of heap used just for caching and can choke other processes in terms of "working memory".

Maybe you could provide your entire alfresco-global.properties configuration (anonymise sensitive data!) and list what kind of 3rd party addons / customisations you have applied to the system.

Re: Afresco startup too slow

mehe — Thu, 16 Mar 2017 06:19:00 GMT

To identify the root-problem of your slow startup:

- did Alfresco take a long time for startup since the beginning (after containing a reasonable count of docs) ?

- if not, what did you change in your configuration that may have caused the issue?

- was there a kind of "mass changing" meta data or access rights or moving around large amounts of documents, resulting in huge transactions?

Another option: For offline analysing a copy of your lucene index, you can use Luke (getopft.org/luke).

Re: Afresco startup too slow

luca — Thu, 16 Mar 2017 09:22:54 GMT

Hi Axel,

yesterday I restored the default cache configuration and give more memory to Alfresco raising it to 8GB, but the result is that this morning Alfresco took 4h 40min to startup, another 20min more than yesterday!! I didn't mention that Alfresco is shutten down at 2:55AM every night and restarted at 3:05AM using shutdown.sh and startup.sh scripts, could be that the indexes are not closed correctly? How can I check it?

I have added only the alfresco-trashcan-cleaner addon to empty the trashcan, but it is scheduled to run in the evening and an authentication filter based on shibbolet.

Also we have a lot of groups (49457 authorityContainer in DB, don't know if they are really groups) and users (about 13K).

I have attached also the alfresco-global.properties

Re: Afresco startup too slow

luca — Thu, 16 Mar 2017 09:42:05 GMT

Hi Martin,

I added some other details in response to Axel.

This slow startup is an old problem that we ignored because if was restarting in the night when noone was working, but now I have some time to take a look at it. As far as I know there is not any action that I made that caused it suddendly, but it raised constantly.

For example these are some startup times that I registered:

24/08/2016 - 1h 50min
14/03/2017 - 3h 42min
15/03/2017 - 4h 19min - restart with nodesSharedCache raised
16/03/2017 - 4h 35min - restart with default cache and 8GB of mem

I will try to inspect indexes, the /opt/alf_data/lucene-indexes/archive/Spacestore folder is 497MB big, instead /opt/alf_data/lucene-indexes/workspace/spaceStore is 5GB big.

What I have to analize?

Re: Afresco startup too slow

afaust — Thu, 16 Mar 2017 09:49:04 GMT

If you have a lot of sites then you can end up with quite a number of groups, even if you effectively don't use all/most of them. Each site will create 5 groups.

The alfresco-global.properties does not show anything unusual so far - some configuration can be in other alfresco-global.properties though, but only if you have custom/3rd party modules installed which you say you only have the trashcan cleaner.

You can do several things to find out what is happening during those hours of startup:

increase log levels to debug, though this might potentially cause the log file to grow extremely fast
use jstack to capture thread dumps of the startup process (may be automated to run every couple of seconds to have multiple dumps / snapshot views)
run profiling agents that may record what operations are being executed and how long they take

Unless you somehow delete / tough the index during the downtime each night there should normally be no reason for the index to be corrupt and have to be rebuilt from scratch on every restart. I am not aware of any issue that would leave the index corrupted when you properly shut down Tomcat - only if you resort to SIGKILL might there be some issues.

Re: Afresco startup too slow

luca — Thu, 16 Mar 2017 11:08:43 GMT

I have just see that the DB is heavily used in the startup period, I will take a look deeper to find what it is happening.

Re: Afresco startup too slow

luca — Mon, 20 Mar 2017 16:36:02 GMT

I have taken a look in the database and I saw this:

3:05 Alfresco start
Starting sysAdmin, Authentication subsystem
3:19 no more log in catalina.out till 5:29!
3:28 Here it starts doing the query below till 7:47
5:29 restart log: Startup of Search, thirdparty, OOoDirect, Transformers subsystems
5:40 no more log in catalina.out again till 7:47!
7:47 restart log: Starting fileServers, imap, email, Subscriptions subsystems
7:48 Alfresco startup completed

The query is this:

select
            node.id                 as node_id,
            node.version            as node_version,
            prop.qname_id           as qname_id,
            prop.locale_id          as locale_id,
            prop.list_index         as list_index,
            prop.actual_type_n      as actual_type_n,
            prop.persisted_type_n   as persisted_type_n,
            prop.boolean_value      as boolean_value,
            prop.long_value         as long_value,
            prop.float_value        as float_value,
            prop.double_value       as double_value,
            prop.string_value       as string_value,
            prop.serializable_value as serializable_value
        from
            alf_node node
            join alf_node_properties prop on (prop.node_id = node.id)
         WHERE  node_id in 
                ( $1, ..., $256 )

Why is it doing so many queries like that? It is possible that it is reindexing all the documents?
What can I do to understand what is it doing?

Re: Afresco startup too slow

afaust — Mon, 20 Mar 2017 20:06:53 GMT

This type of query is typical for preloading a set of nodes into caches. That is usually a part of doing any kind of queries e.g. against SOLR.

Re: Afresco startup too slow

luca — Tue, 21 Mar 2017 07:48:18 GMT

Ok, so you are telling me that Alfresco is loading nodes in the cache and this could be the reason that I see these logs:

 2017-03-16 03:21:15,658  WARN  [cache.node.nodesTransactionalCache] [localhost-startStop-1] Transactional update cache 'org.alfresco.cache.node.nodesTransactionalCache' is full (125000).  2017-03-16 03:21:40,089  WARN  [cache.node.aspectsTransactionalCache] [localhost-startStop-1] Transactional update cache 'org.alfresco.cache.node.aspectsTransactionalCache' is full (65000).  2017-03-16 03:21:43,413  WARN  [cache.node.propertiesTransactionalCache] [localhost-startStop-1] Transactional update cache 'org.alfresco.cache.node.propertiesTransactionalCache' is full (65000).

But I don't undestand why it is doing this, what do you mean by "That is usually a part of doing any kind of queries e.g. against SOLR."?

By the way, I'm not using SOLR, do you think that could solve my problems?

Re: Afresco startup too slow

afaust — Tue, 21 Mar 2017 09:50:30 GMT

With that I mean that this type of query is usually only done when some code / component is doing a query using the SearchService.query() operation, which most of the time involves a SOLR (or Lucene) query.

By default Alfresco should not do any intensive queries during startup on its own, so this might be triggered by some kind of custom code or 3rd party addon.

Re: Afresco startup too slow

luca — Mon, 27 Mar 2017 16:18:32 GMT

We have only a custom authentication filter based on Shibbolet and the alfresco-trashcan-cleaner module that is scheduled to run only in the evening.

I have disabled the alfresco-trashcan-cleaner module to be sure, but we don't have any other 3rd party addon.

What is the best way to check what Alfresco is doing on startup? Where can I put some debug point to understand better what is happening?

Re: Afresco startup too slow

mehe — Mon, 27 Mar 2017 16:59:45 GMT

Hi Luca (I'm suffering with you),

have you already tried to increase the log levels?

Maybe

log4j.logger.org.alfresco.repo.node.index.AbstractReindexComponent=DEBUG

log4j.logger.org.alfresco.repo.node.index.FullIndexRecoveryComponent=DEBUG

log4j.logger.org.alfresco.repo.node.index.IndexTransactionTracker=DEBUG

can show what is happening inside...

But there are a lot of log4j entries that could help and experimenting with them is a pain with such long boot times.

Re: Afresco startup too slow

luca — Fri, 05 May 2017 08:09:44 GMT

Great news, I succesfully bring back the startup times to 21 min thanks to a tiny modifications to a single query!

The query is the one that I pointed out in a previous post and the complete explanation of the problem is described here: https://issues.alfresco.com/jira/browse/MNT-15576

Thank to all who helped me!

Re: Afresco startup too slow

sakbar — Wed, 21 Sep 2022 04:49:30 GMT

I'm having the same issue (slow startup). The link you provided returns 404, I would appreciate if you can help me resolve this issue.

Re: Afresco startup too slow

AidenZ — Thu, 25 Jan 2024 03:36:55 GMT

Hi Luca,

I am also facing a similar problem now. Cloud you share your modification process?

Unfortunately, the link you shared is already 404

Thanks,
Aiden

Re: Afresco startup too slow

hr61369256 — Fri, 05 Apr 2024 11:53:37 GMT

Sometimes it's really frustrating how people behave 😞 ... why does he not correct the link after several requests doing that?