[MGNLUI-4873] Starting bundle 6.0 is very slow Created: 05/Dec/18  Updated: 16/Jan/19  Resolved: 14/Dec/18

Status: Closed
Project: Magnolia UI
Component/s: None
Affects Version/s: 6.0
Fix Version/s: None

Type: Bug Priority: Neutral
Reporter: Hieu Nguyen Duc Assignee: Unassigned
Resolution: Workaround exists Votes: 1
Labels: None
Remaining Estimate: 0d
Time Spent: 1h
Original Estimate: Not Specified
Environment:

magnolia-enterprise-6.0


Attachments: File catalina-rich.out     File hieu_catalina.out     File hieu_ce_catalina.out    
Issue Links:
Relates
relates to DOCU-1823 New known issue "slow startup time ->... Closed
duplicate
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:

 Description   

I'm sorry but starting a bundle has never been this suffering. Tried several times and it was sluggish.

See hieu_catalina.out. It takes over 21 minutes.

See hieu_ce_catalina.out. It takes 10 minutes.

(Feel free to edit the description or move this ticket if it's not related to UI)

 



 Comments   
Comment by Richard Gange [ 05/Dec/18 ]

Hmm... I just tried and it was less than a minute (53 secs). Maybe there is more to the story here? I will attach my log to have something to compare to: catalina-rich.out

Comment by Richard Gange [ 10/Dec/18 ]

I can see in hieu_catalina.out it takes nearly 5 minutes just to load the JCR. I have seen this problem in some of my startups as well.

2018-12-05 22:09:50,257 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading JCR
2018-12-05 22:09:50,263 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading JCR magnolia
2018-12-05 22:09:50,305 INFO  info.magnolia.jackrabbit.ProviderImpl             : Loading repository at /Users/hieuhay/Downloads/QA/Releases/magnolia-enterprise-6.0/apache-tomcat-9.0.10/webapps/magnoliaPublic/repositories/magnolia (config file: /Users/hieuhay/Downloads/QA/Releases/magnolia-enterprise-6.0/apache-tomcat-9.0.10/webapps/magnoliaPublic/WEB-INF/config/repo-conf/jackrabbit-bundle-h2-search.xml) - cluster id: "<unset>"
2018-12-05 22:11:23,024 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering prefix [mgnl] with URI http://www.magnolia.info/jcr/mgnl
2018-12-05 22:11:23,041 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}metaData on repository magnolia
2018-12-05 22:11:23,121 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}lastModified on repository magnolia
2018-12-05 22:11:23,131 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}activatable on repository magnolia
2018-12-05 22:11:23,144 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}renderable on repository magnolia
2018-12-05 22:11:23,153 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}created on repository magnolia
2018-12-05 22:11:23,165 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}versionable on repository magnolia
2018-12-05 22:11:23,178 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}deleted on repository magnolia
2018-12-05 22:11:23,189 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}content on repository magnolia
2018-12-05 22:11:23,203 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}contentNode on repository magnolia
2018-12-05 22:11:23,213 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}folder on repository magnolia
2018-12-05 22:11:23,228 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}resource on repository magnolia
2018-12-05 22:11:23,239 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}reserve on repository magnolia
2018-12-05 22:11:23,248 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}page on repository magnolia
2018-12-05 22:11:23,261 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}area on repository magnolia
2018-12-05 22:11:23,267 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}component on repository magnolia
2018-12-05 22:11:23,277 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}user on repository magnolia
2018-12-05 22:11:23,285 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}role on repository magnolia
2018-12-05 22:11:23,293 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}group on repository magnolia
2018-12-05 22:11:23,300 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}hasVersion on repository magnolia
2018-12-05 22:14:24,231 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace mgnlVersion (logical name magnolia-mgnlVersion).
2018-12-05 22:14:24,233 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace default (logical name default).
2018-12-05 22:14:24,236 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace mgnlSystem (logical name magnolia-mgnlSystem).

Then nearly 7 minutes to load the workspaces.

2018-12-05 22:18:17,669 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace resources (logical name resources).
2018-12-05 22:18:47,849 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/magnolia-dam-nodetypes.xml
2018-12-05 22:18:47,850 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}asset on repository magnolia
2018-12-05 22:21:03,415 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace dam (logical name dam).
2018-12-05 22:21:33,626 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace imaging (logical name imaging).
2018-12-05 22:22:03,821 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/magnolia-message-nodetypes.xml
2018-12-05 22:22:03,823 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}systemMessage on repository magnolia
2018-12-05 22:22:03,871 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace messages (logical name messages).
2018-12-05 22:22:34,035 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/magnolia-favorite-nodetypes.xml
2018-12-05 22:22:34,037 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}favorite on repository magnolia
2018-12-05 22:22:34,053 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}favoriteGroup on repository magnolia
2018-12-05 22:22:34,061 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace profiles (logical name profiles).
2018-12-05 22:23:04,235 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace scripts (logical name scripts).
2018-12-05 22:23:34,383 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/magnolia-keystore-nodetypes.xml
2018-12-05 22:23:34,385 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}password on repository magnolia
2018-12-05 22:23:34,408 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace keystore (logical name keystore).
2018-12-05 22:24:04,554 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/tasks-nodetypes.xml
2018-12-05 22:24:04,554 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}task on repository magnolia
2018-12-05 22:24:04,567 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace tasks (logical name tasks).
2018-12-05 22:24:34,750 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/magnolia-contacts-nodetypes.xml
2018-12-05 22:24:34,751 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}contact on repository magnolia
2018-12-05 22:24:34,763 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace contacts (logical name contacts).
2018-12-05 22:25:04,943 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/magnolia-personalization-nodetypes.xml
2018-12-05 22:25:04,944 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}variant on repository magnolia
2018-12-05 22:25:04,956 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}hasVariant on repository magnolia
2018-12-05 22:25:04,965 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}variants on repository magnolia
2018-12-05 22:25:04,975 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/magnolia-privacy-nodetypes.xml
2018-12-05 22:25:04,976 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}visitorReference on repository magnolia
2018-12-05 22:25:04,985 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}consent on repository magnolia
2018-12-05 22:25:04,995 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}visitor on repository magnolia
2018-12-05 22:25:05,004 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace visitors (logical name visitors).
2018-12-05 22:25:35,185 INFO  info.magnolia.jackrabbit.ProviderImpl             : Custom node types registered using /mgnl-nodetypes/workflow-jbpm-nodetypes.xml
2018-12-05 22:25:35,187 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}workItem on repository magnolia
2018-12-05 22:25:35,204 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}processInstance on repository magnolia
2018-12-05 22:25:35,216 INFO  info.magnolia.jackrabbit.ProviderImpl             : Registering nodetype {http://www.magnolia.info/jcr/mgnl}session on repository magnolia
2018-12-05 22:25:35,227 INFO  info.magnolia.repository.DefaultRepositoryManager : Loading workspace workflow (logical name workflow).
Comment by Adrien Manzoni [ 10/Dec/18 ]

I have two different workspaces in IntelliJ. One is just working fine, the other takes systematically 20 min to start.

When I deploy them on AWS, both are working fine.

I start thinking it has something to do with the IntelliJ settings...

Comment by Richard Gange [ 10/Dec/18 ]

I think this issue might be related to the JR update we did in 5.7.

Here is what I know:

  • I have observed this problem as well. But not every time (obviously catalina-rich.out)
  • In 5.7 we updated JR to 2.16.1, which updated Tika from 1.14 (5.6) to 1.17 (5.7)
  • Now we can see above that there is a lot of slow down when loading the repo and the workspaces. Tika is tied to the workspaces through indexing. Perhaps tika has some bug fix that is now effecting us.

I start thinking it has something to do with the IntelliJ settings

I have also seen this issue in Eclispe. I'm not saying it's not possible but it would seem more likely that it's a library upgrade. But I don't know for sure. I have seen this slow start problem but not with any pattern.

Comment by Richard Gange [ 10/Dec/18 ]

Also here is the 2.16 release notes.

To me it seems most likely we will find the culprit somewhere with JR.

Comment by Mikaël Geljić [ 11/Dec/18 ]

Just to move that one aside, hieu.nguyen are you sure you don't run into that MacOS hostname resolution issue?
https://thoeni.io/post/macos-sierra-java/

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