Why does init take so long to complete after document indexing?

andreas-fresh-mesa · February 21, 2025, 12:03pm

We have an application based on the project template deployed using the A12 charts. The dataservices init job takes very long to complete after it loaded documents for the search index. Does anybody know what the init does during this time. The log output is:

2025-02-21T11:40:30.572Z  INFO 1 --- [           main] c.m.a.d.search.SearchIndexLoader         : [376] Documents of model [Position-DM] has been updated in [205] ms
2025-02-21T11:40:30.820Z  INFO 1 --- [           main] c.m.a.d.search.SearchIndexLoader         : Loading [0] document ids for model [FragmentDM] took [ 219 ms ]
2025-02-21T11:40:45.493Z  INFO 1 --- [           main] c.h.i.p.impl.PartitionStateManager       : [<INTERNAL_IP>]:5701 [dev] [5.4.0] Initializing cluster partition table arrangement...
2025-02-21T11:40:45.506Z  INFO 1 --- [ration.thread-4] c.h.c.i.session.RaftSessionService       : [<INTERNAL_IP>]:5701 [dev] [5.4.0] Created new session: 1 in CPGroupId{name='cddUpdate-ComposeBuffet-DM/Buffet-DM/74faa3cf-8efd-4511-892c-3ab3174fef28', seed=0, groupId=68} for SERVER -> [<INTERNAL_IP>]:5701
2025-02-21T11:40:55.268Z  INFO 1 --- [ration.thread-5] c.h.c.i.session.RaftSessionService       : [<INTERNAL_IP>]:5701 [dev] [5.4.0] Created new session: 1 in CPGroupId{name='cddUpdate-ComposeBuffet-DM/Buffet-DM/c5ff8fd5-40d6-419a-afae-d62b454add55', seed=0, groupId=197} for SERVER -> [<INTERNAL_IP>]:5701
2025-02-21T11:41:04.438Z  INFO 1 --- [ration.thread-8] c.h.c.i.session.RaftSessionService       : [<INTERNAL_IP>]:5701 [dev] [5.4.0] Created new session: 1 in CPGroupId{name='cddUpdate-ComposeBuffet-DM/Buffet-DM/eea8dcba-7a88-4e2b-80b7-3ae4f1dd14da', seed=0, groupId=152} for SERVER -> [<INTERNAL_IP>]:5701

The log output from RaftSessionService appears nearly exactly every 5 seconds. ComposeBuffet-DM is a CDM. Is it doing something with the CDDs one-by-one? And why does it take 5s per CDD?

EDIT
The init completed with the following log output:

2025-02-21T12:03:34.960Z  INFO 1 --- [ration.thread-4] c.h.c.i.session.RaftSessionService       : [<INTERNAL_IP>]:5701 [dev] [5.4.0] Created new session: 1 in CPGroupId{name='cddUpdate-ComposeCheckout-DM/Checkout-DM/e38b5958-1714-4c59-b706-bcf26814e136', seed=0, groupId=4} for SERVER -> [<INTERNAL_IP>]:5701
2025-02-21T12:03:39.024Z  INFO 1 --- [ration.thread-2] c.h.c.i.session.RaftSessionService       : [<INTERNAL_IP>]:5701 [dev] [5.4.0] Created new session: 1 in CPGroupId{name='cddUpdate-ComposeCheckout-DM/Checkout-DM/a7f2011d-4303-476e-a420-e9f0b31975ec', seed=0, groupId=194} for SERVER -> [<INTERNAL_IP>]:5701
2025-02-21T12:03:40.129Z  INFO 1 --- [           main] c.m.a.d.search.SearchIndexLoader         : Index rebuilt in 1415214 ms

24mins for indexing a database with just a few hundred docs is quite bad

andreas-fresh-mesa · February 21, 2025, 12:09pm

Taking a further look into the logs of the job I found

2025-02-21T11:40:10.157Z  INFO 1 --- [           main] c.m.a.d.search.SearchIndexLoader         : [170] Documents of model [Buffet-DM] has been updated in [315] ms

And the log outputs like

2025-02-21T11:40:45.506Z  INFO 1 --- [ration.thread-4] c.h.c.i.session.RaftSessionService       : [<INTERNAL_IP>]:5701 [dev] [5.4.0] Created new session: 1 in CPGroupId{name='cddUpdate-ComposeBuffet-DM/Buffet-DM/74faa3cf-8efd-4511-892c-3ab3174fef28', seed=0, groupId=68} for SERVER -> [<INTERNAL_IP>]:5701

repeat 170 times. ComposeBuffet-DM is a CDM that has Buffet-DM as its root.

What does take 5 seconds about indexing a single CDD? Or is there some unnecessary wait time included?

tomas-thin-gale · February 25, 2025, 10:35am

Hi @andreas-fresh-mesa,

CDD re-indexing is a known performance bottleneck. All documents of the system are queued, and queue consumer picks them one by one and construct expensive queries to detect if they belong to some CDM or not. In case they do, we need to load all CDDs in which they participate. After this is done, another document gets processed. This means that one CDD will get recalculated as many times as the number of documents it contains.

Can you please create A12 ticket with the models that you use and number of documents per-document model if you need improvement right now? Are you using 2024.06-ext3 or older version? We can take a look of what can be done about this, but the root cause is that we do not have traversal queries. This is causing too many SQL statements to be issued against Postgres, and we need to recalculate over and over what might have been already calculated because we do not know what was updated before.

To mitigate all of those problems, DS will drop index for CDDs in 2025.06, and we will construct CDDs during query time.

This answer is valid from DS version 37.2.0 and below