[KULRICE-12988] KC app startup time really slow with the latest rice 2.5 revision Created: 17/Jul/14  Updated: 24/Sep/14  Resolved: 18/Jul/14

Status: Closed
Project: Kuali Rice Development
Component/s: Data Dictionary
Affects Version/s: 2.5
Fix Version/s: 2.5
Security Level: Public (Public: Anyone can view)

Type: Task Priority: Blocker
Reporter: Gayathri Athreya Assignee: Kristina Taylor (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: 0 minutes
Time Spent: 4 hours
Original Estimate: 4 hours

Issue Links:
Fix
Relate
relates to KULRICE-12991 Application startup time slow after S... Closed
Similar issues:
KULRICE-12991Application startup time slow after Spring 4.0.x upgrade
KULRICE-4990fixing log4j errors in rice on tomcat startup
KULRICE-13070Pages load really slow after rice upgrade
KULRICE-4070XmlHelper.appendXml(Node, String) can be really slow. (i.e. takes minutes)
KULRICE-13037Krad Sampleapp startup failing due to npe with max incrementer factory
KULRICE-531development slowness
KULRICE-4392Update sample applications to latest version of rice
KULRICE-13687Sample App Gap Analysis - 2.5.0-m4 QA Sprint 1
KULRICE-13719Sample App Gap Analysis - QA 2.5.0-m5 QA Sprint 1
KULRICE-13744Sample App Gap Analysis - QA 2.5.0-m5 QA Sprint 2
Rice Module:
KRAD
Application Requirement:
KC
Sprint: Core 2.5.0-m5 Sprint 2
KAI Review Status: Not Required
KTI Review Status: Not Required
Code Review Status: Not Required
Include in Release Notes?:
Yes

 Description   

While upgrading to Rice 2.5.0-M5-r47560, we are noticing really slow start up times. Here is the relevant logs for the issue

LOG
2014-07-17 11:26:35,490 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryEntryBase - No metadata provider exists which handles: class org.kuali.kra.irb.actions.submit.ValidProtocolActionAction
2014-07-17 11:26:35,490 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryEntryBase - No metadata provider exists which handles: class org.kuali.kra.irb.actions.submit.ValidProtoSubRevType
2014-07-17 11:26:35,490 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryEntryBase - No metadata provider exists which handles: class org.kuali.kra.irb.actions.submit.ValidProtoSubTypeQual
2014-07-17 11:26:35,490 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryEntryBase - No metadata provider exists which handles: class org.kuali.kra.award.home.ValidRates
2014-07-17 11:26:35,490 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryEntryBase - No metadata provider exists which handles: class org.kuali.coeus.common.framework.compliance.core.ValidSpecialReviewApproval
2014-07-17 11:26:35,490 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryEntryBase - No metadata provider exists which handles: class org.kuali.coeus.common.framework.print.watermark.Watermark
2014-07-17 11:26:35,490 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Starting DD Index Building
2014-07-17 11:26:36,096 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Completed DD Index Building
2014-07-17 11:26:36,096 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Started DD Inactivation Blocking Index Building
2014-07-17 11:26:36,295 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Completed DD Inactivation Blocking Index Building
2014-07-17 11:33:50,045 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Starting View Index Building
2014-07-17 11:33:50,153 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Completed View Index Building
2014-07-17 11:33:50,153 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionary - Completed Data Dictionary Post Processing
2014-07-17 11:33:50,282 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.config.KRADConfigurer - KRAD Configurer - Validating DD
2014-07-17 11:33:50,542 [RMI TCP Connection(2)-127.0.0.1] u:/d: WARN  org.kuali.rice.krad.data.provider.impl.ProviderBasedDataObjectService - Non KRAD Data object

as you can see, this slow down is right after the

Completed DD Inactivation Blocking Index Building and it takes close to 7 minutes. I noticed that the code that takes the longest to complete are the following two:

DataDictionary.java
generateMissingInquiryDefinitions();
generateMissingLookupDefinitions();

when I comment these lines out, the app starts up in no time however there are issues with lookups. This code seems to call into some spring methods and I am guessing this slowness is because of the spring 4.x upgrade. I have tried various revisions after the spring 4.x upgrade and it is slow in all of those.



 Comments   
Comment by Travis Schneeberger [ 17/Jul/14 ]

Please note that Gayathri has a very powerful computer but not all on our development team do. For comparison, I have a top of the line Macbook Pro with 16GB of RAM. This portion of startup used to take me ~30seconds and now takes me ~5 minutes.

Comment by Kristina Taylor (Inactive) [ 17/Jul/14 ]

This seems like exactly the same 10x slowdown as reported in https://jira.spring.io/browse/SPR-8318, but Rice has patched this in the revision that Gayathri Athreya reported KC was using for their latest update. No matter what the power the computer, the slowdown is definitely unacceptable.

Comment by Kristina Taylor (Inactive) [ 17/Jul/14 ]

Here's what I'm seeing in just Rice.

Rice 2.4: 14 second lag

2014-07-17 13:28:03,193 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Started DD Inactivation Blocking Index Building
2014-07-17 13:28:03,421 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Completed DD Inactivation Blocking Index Building
2014-07-17 13:28:11,071 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Starting View Index Building
2014-07-17 13:28:11,377 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Completed View Index Building

Pre Spring 4.0.5 bug fix: 22 second lag

2014-07-17 13:15:55,576 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Started DD Inactivation Blocking Index Building
2014-07-17 13:15:55,760 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Completed DD Inactivation Blocking Index Building
2014-07-17 13:16:17,522 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Starting View Index Building
2014-07-17 13:16:17,726 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Completed View Index Building

Post Spring 4.0.5 bug fix: 30 second lag

2014-07-17 13:10:23,435 [RMI TCP Connection(4)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Started DD Inactivation Blocking Index Building
2014-07-17 13:10:23,687 [RMI TCP Connection(4)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Completed DD Inactivation Blocking Index Building
2014-07-17 13:10:53,959 [RMI TCP Connection(4)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Starting View Index Building
2014-07-17 13:10:54,157 [RMI TCP Connection(4)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Completed View Index Building

With Spring 4.0.7 fix: 26 second lag

2014-07-17 13:20:56,550 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Started DD Inactivation Blocking Index Building
2014-07-17 13:20:56,789 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.DataDictionaryIndex - Completed DD Inactivation Blocking Index Building
2014-07-17 13:21:22,775 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Starting View Index Building
2014-07-17 13:21:22,934 [RMI TCP Connection(2)-127.0.0.1] u:/d: INFO  org.kuali.rice.krad.datadictionary.uif.UifDictionaryIndex - Completed View Index Building

It does seem like the Spring upgrade is the bulk of the problem, but I'm only seeing on average a 2x slowdown, not the 10x reported.

Comment by Kristina Taylor (Inactive) [ 17/Jul/14 ]

I had a jam session with Eric and Jerry, and the consensus is that these two calls are considered experimental and should be able to be turned off in the config and should also be turned off by default (named something like rice.krad.automaticUifGenerationEnabled). I think we probably have to inform the members of the Rice and Apps chat next week to help them with this change (if applicable). If you are having trouble with the lookups, you may want to not rely on the Uif annotations (example: UifAutoCreateViewType is marked as @Beta) and generate views on your own until we can get the performance problem figured out. After we put that in, we will create another Jira to address the problem with the beta feature.

Comment by Gayathri Athreya [ 17/Jul/14 ]

The two calls, as in the generateMissingInquiryDefinitions(); and
generateMissingLookupDefinitions(); ? When I did that, our lookups were throwing stack traces. I am guessing we have to make more changes if we turn these off? We have a dev team F2F scheduled next week before which we were hoping to get the rice upgrade in since we have quite a few blockers and criticals out there but cannot because of this issue.

Comment by Kristina Taylor (Inactive) [ 17/Jul/14 ]

Yes, essentially if you are using annotations to auto-generate pieces of your views, turning this beta feature off will require you to define what they are generating in your XML. Can you give an example of the stack traces you are getting?

Comment by Kristina Taylor (Inactive) [ 17/Jul/14 ]

I put the hotfix in for this. The configuration parameter rice.krad.views.autoGeneration.enabled is set to false by default but is turned on in both Rice sample applications. I need to still verify that the fix will work with KC and inform the other applications about this change.

Generated at Sat Jun 06 07:59:50 CDT 2020 using JIRA 6.1.5#6160-sha1:a61a0fc278117a0da0ec9b89167b8f29b6afdab2.