[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) |
||
| Attachments: |
|
||||
| Issue Links: |
|
||||
| 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: | |||||
| 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
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 informationAttachment 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
{"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? .... 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 resultsOnly the childnodes of the jcrMultiFieldnode should show up in the order and move() process, since they are sorted. Actual resultsThe 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. WorkaroundTo avoid ordering nodes and UI unresponsiveness use the following orderHandler:
orderHandler:
class: info.magnolia.ui.editor.MultiFormDefinition$OrderHandlerDefinition$Noop
Development notes |