Kuali Rice Development
  1. Kuali Rice Development
  2. KULRICE-12988

KC app startup time really slow with the latest rice 2.5 revision

    Details

    • Type: Task Task
    • Status: Closed Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 2.5
    • Fix Version/s: 2.5
    • Component/s: Data Dictionary
    • Security Level: Public (Public: Anyone can view)
    • Labels:
      None
    • 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-4856KR/KC Help Integration
      KULRICE-531development slowness
      KULRICE-13037Krad Sampleapp startup failing due to npe with max incrementer factory
      KULRICE-4392Update sample applications to latest version of rice
      KULRICE-11074Revise QA Hub wiki page
      KULRICE-14247Identify and apply Rice server changes from kc-rice to 2.5 branch
    • 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.

        Issue Links

          Activity

          Hide
          Travis Schneeberger added a comment -

          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.

          Show
          Travis Schneeberger added a comment - 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.
          Hide
          Kristina Taylor (Inactive) added a comment -

          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.

          Show
          Kristina Taylor (Inactive) added a comment - 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.
          Hide
          Kristina Taylor (Inactive) added a comment -

          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.

          Show
          Kristina Taylor (Inactive) added a comment - 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.
          Hide
          Kristina Taylor (Inactive) added a comment - - edited

          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.

          Show
          Kristina Taylor (Inactive) added a comment - - edited 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.
          Hide
          Gayathri Athreya added a comment - - edited

          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.

          Show
          Gayathri Athreya added a comment - - edited 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.
          Hide
          Kristina Taylor (Inactive) added a comment -

          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?

          Show
          Kristina Taylor (Inactive) added a comment - 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?
          Hide
          Kristina Taylor (Inactive) added a comment -

          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.

          Show
          Kristina Taylor (Inactive) added a comment - 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.

            People

            • Assignee:
              Kristina Taylor (Inactive)
              Reporter:
              Gayathri Athreya
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

                Estimated:
                Original Estimate - 4 hours
                4h
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 4 hours
                4h

                  Agile

                    Structure Helper Panel