-
Bug
-
Resolution: Unresolved
-
Neutral
-
None
-
6.2.11
-
None
-
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
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
- Create in pages app a node. This node should then have multiple child and grandchild nodes
- 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
- Create or add a component which is based on the $type: jcrMultiField. Default settings
- Place this component in the created page from step 1
- 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
- Save the component by clicking save on the dialog
- 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
