[MGNLUI-6879] UI not responsive after saving jcrMultiField on a node with a lot of childnodes Created: 21/Sep/21  Updated: 18/Jul/23

Status: Open
Project: Magnolia UI
Component/s: pages app
Affects Version/s: 6.2.11
Fix Version/s: None

Type: Bug Priority: Neutral
Reporter: Johannes Kessler Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu 11.0.11 (build 11.0.11+9-Ubuntu-0ubuntu2.20.04)
Magnolia DX Core 6.2.11
Jackrabbit 2.20
Mysql 8.0
Apache Tomcat 9
OpenJDK 11


Attachments: PNG File Selection_001.png     PNG File Selection_002.png     PNG File debug_step_1.png     PNG File debug_step_2.png     PNG File debug_step_3.png     File test.log.tar.gz    
Issue Links:
Relates
Template:
Acceptance criteria:
Empty
Task DoD:
[ ]* Doc/release notes changes? Comment present?
[ ]* Downstream builds green?
[ ]* Solution information and context easily available?
[ ]* Tests
[ ]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Bug DoR:
[ ]* Steps to reproduce, expected, and actual results filled
[ ]* Affected version filled
Date of First Response:
Epic Link: FieldsMaintenance
Team: Nucleus

 Description   

This ticket is a result of this support ticket: https://jira.magnolia-cms.com/browse/SUPPORT-13664

Hello everyone.

I experience a heavy perfomance loss, UI not responsive to the current session, while using the jcrMultiField.

In steps to reproduce I describe the steps and the details to look out for. After I describe the situation, logs and my humble debug results.

Steps to reproduce

  1. Create in pages app a node. This node should then have multiple child and grandchild nodes
  2. Add org.apache.jackrabbit set to DEBUG to the loggers. This shows the method calls in the logs. But the behaviour does also accur if the logs are off
  3. Create or add a component which is based on the $type: jcrMultiField. Default settings
  4. Place this component in the created page from step 1
  5. Add items to the jcrMultiField. More then one, but it does not really depend on how much. The problem accours already with one and multiplies with each item
  6. Save the component by clicking save on the dialog
  7. The logs show a lot of Performing nodeExists:
Performing nodeExists(/nodeWithMultifieldComponent/main/0/jcrMultiFieldName/__TMP_NAME_PREFIXjcrMultiFieldName0)
Performed nodeExists(/nodeWithMultifieldComponent/main/0/jcrMultiFieldName/__TMP_NAME_PREFIXjcrMultiFieldName0)
Performing nodeExists(/nodeWithMultifieldComponent/main/0/jcrMultiFieldName/__TMP_NAME_PREFIXjcrMultiFieldName0/childnode1)
Performed nodeExists(/nodeWithMultifieldComponent/0/jcrMultiFieldName/__TMP_NAME_PREFIXjcrMultiFieldName0/childnode2)
Performing nodeExists(/nodeWithMultifieldComponent/main/0/jcrMultiFieldName/__TMP_NAME_PREFIXjcrMultiFieldName0/childnode3)
Performing nodeExists(/nodeWithMultifieldComponent/main/0/jcrMultiFieldName/__TMP_NAME_PREFIXjcrMultiFieldName0/childnode3/grandchild1)
Performing nodeExists(/nodeWithMultifieldComponent/main/0/jcrMultiFieldName/__TMP_NAME_PREFIXjcrMultiFieldName0/childnode3/grandchild2)

My humble debug results and more information

Attachment Selection_001.png and Selection_002.png show the placement of the jcrMultiField and the node structure in our system

Attachment test.log.tar.gz is a result with debug mode on and the save process from a local installation. There I've modified the default DefaultJcrNodeOrderHandler to print some log lines.

Now take a look at the log file from test.log.tar.gz. In line 1457275 you find the first custom log entry which marks the start and execution of the order action which is triggered from the save

2021-09-14 09:29:45,436 INFO e.bechtle.editor.BechtleDefaultJcrNodeOrderHandler: applyOrder [requesturi:/cmsauthor/.magnolia/admincentral/UIDL/]

Line 1491486 marks the end of the order process

2021-09-14 09:29:46,019 INFO e.bechtle.editor.BechtleDefaultJcrNodeOrderHandler: applyOrder tmp rename to new loop end [requesturi:/cmsauthor/.magnolia/admincentral/UIDL/]

Now comes the "problematic part". Starting with line 1491598,

2021-09-14 09:29:46,025 DEBUG org.apache.jackrabbit.core.session.SessionState : Performing nodeExists(/www.bechtle.com/main/01/products/__TMP_NAME_PREFIXproducts0) [requesturi:/cmsauthor/.magnolia/admincentral/UIDL/]

there are now a lot of entries which look like this:

Performing nodeExists(/www.bechtle.com/main/01/products/__TMP_NAME_PREFIXproducts0/

Correctly using the two items from the jcrMultifield but adding the page childnodenames from the parent node /www.bechtle.com as a suffix like this:

Performed nodeExists(/www.bechtle.com/main/01/products/__TMP_NAME_PREFIXproducts0/it-solutions

This repeats until all the items from the jcrMultifield are processed (in this case two items) and for each item for all the page childnodes from /www.bechtle.com

The only code I can find which uses the string __TMP_NAME_PREFIX is the DefaultJcrNodeOrderHandler and this only happends if I save this component. All other components in the main area of www.bechtle.com do not cause this effect. All the data is saved correctly but the system is only usable again after this process is finished. This happens at line 1817867

2021-09-14 09:29:53,721 DEBUG org.apache.jackrabbit.core.session.SessionState : Performed item.getPath() in 2904ns [requesturi:/cmsauthor/.magnolia/admincentral/UIDL/]

 

Here are two log lines from the production system from the first accurence of __TMP_NAME_PREFIX and last one. Without any class extension or custom log entries. Just enabled the debug mode for jackrabbit
As you can see there are 20min in between.

{"timestamp":"2021-09-10T15:05:56.505+0200","app":"magnolia","level":"DEBUG","logger_name":"org.apache.jackrabbit.core.session.SessionState","thread_name":"http-nio-8080-exec-11","message":"Performing nodeExists(/www.bechtle.com/main/0/products/__TMP_NAME_PREFIX0)","X-CID":"9fc8ab587504450ea8e2641c65f7c404","X-BID":"bbb3aa09d6d94eea973f59dc910b255a_1631278808499_47d1c549e4ce74ed8f9597d1f9dd29f9","X-LOCALE-COUNTRY":"de","X-LOCALE-LANGUAGE":"de","X-SECO":"true","X-FORWARDED-PROTO":"https","X-FORWARDED-HOST":"dev.bechtle.com","instance":"magnolia-author-9d7c6696f-5kwjd","http_host":"dev.bechtle.com","beus-id":"","http_referer":"https://dev.bechtle.com/backend/cms/.magnolia/admincentral","http_user_agent":"Mozilla/5.0 (X11; Linux x86_64; rv:92.0) Gecko/20100101 Firefox/92.0","http_uri":"/backend/cms/.magnolia/admincentral/UIDL/","duration":"","X-VID":"1ba5b8094d824b3b865923dbc62c2bd5","http_method":"POST","X-TENANT":"bechtle","http_status":"200","SessionId":"81567210B492BF6B704B38EB5F74C4B5"}
{"timestamp":"2021-09-10T15:25:28.623+0200","app":"magnolia","level":"INFO","logger_name":"log-audit","thread_name":"http-nio-8080-exec-11","message":", move, 1631280312792000, johannes.kessler, website, /www.bechtle.com/main/0/products/__TMP_NAME_PREFIXproducts12, /www.bechtle.com/main/0/products/products12","X-CID":"9fc8ab587504450ea8e2641c65f7c404","X-BID":"bbb3aa09d6d94eea973f59dc910b255a_1631278808499_47d1c549e4ce74ed8f9597d1f9dd29f9","X-LOCALE-COUNTRY":"de","X-LOCALE-LANGUAGE":"de","X-SECO":"true","X-FORWARDED-PROTO":"https","X-FORWARDED-HOST":"dev.bechtle.com","instance":"magnolia-author-9d7c6696f-5kwjd","http_host":"dev.bechtle.com","beus-id":"","http_referer":"https://dev.bechtle.com/backend/cms/.magnolia/admincentral","http_user_agent":"Mozilla/5.0 (X11; Linux x86_64; rv:92.0) Gecko/20100101 Firefox/92.0","http_uri":"/backend/cms/.magnolia/admincentral/UIDL/","duration":"","X-VID":"1ba5b8094d824b3b865923dbc62c2bd5","http_method":"POST","X-TENANT":"bechtle","http_status":"200","SessionId":"81567210B492BF6B704B38EB5F74C4B5"}

Now is the question why and where does those "Performed nodeExists" with the childnodenames come from?
I've debugged (in Intellij live debug) the move() call as shown in screenshot debug_step_1.png, came by the updateLastModifed() call in screenshot debug_step_2.png and ended in the recursiveDown code block as shown in screenshot debug_step_3.png
And there all the childnodes from www.bechtle.com (in which the jcrMultiField) is placed are looped over and creating those log lines:

....
Performed nodeExists(/www.bechtle.com/main/01/products/__TMP_NAME_PREFIXproducts0/it-solutions
Performed nodeExists(/www.bechtle.com/main/01/products/__TMP_NAME_PREFIXproducts0/about-bechtle
.... 

I hope it is more clear now. Otherwise please feel free to ask as many questions you need.

 

 

Expected results

Only the childnodes of the jcrMultiFieldnode should show up in the order and move() process, since they are sorted.

Actual results

The childnodes of the jcrMultiFieldnode should show up, since they are sorted AND all the nodes of the page in which the component is saved show up on the move call and checked if they exists.

Workaround

To avoid ordering nodes and UI unresponsiveness use the following orderHandler:

orderHandler:
        class: info.magnolia.ui.editor.MultiFormDefinition$OrderHandlerDefinition$Noop

Development notes


Generated at Mon Feb 12 09:40:55 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.