Details

    • Type: Improvement
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.3.1
    • Security Level: Public (Public: Anyone can view)
    • Labels:
      None
    • Epic Link:
    • Rice Module:
      KRAD
    • Sprint:
      2.3.1 Sprint 2
    • KAI Review Status:
      Not Required
    • KTI Review Status:
      Not Required
    • Code Review Status:
      Not Required
    • Include in Release Notes?:
      Yes

      Description

      Based on analysis recorded in KULRICE-10260, FreeMarker rendering of complex views is in part impacted by excessive BeansWrapper method invocation centered around high-traffic macros such as script and template.

      To reduce this introspection overhead and improve overall performance of view rendering at the FreeMarker phase, provide a mechanism for passing FreeMarker rendering control to inline Java code then convert targeted macros to use this inline mechanism instead of handling expensive internal rendering logic through the exclusive use of .ftl template code.

      Initial targeted Macros are script.ftl and template.ftl. Once these have been converted, an additional pass at analysis and identification of targeted macros using Performance Medium should lead to further opportunities to improve performance.

      Original estimate:

      • 4h - Implementation of FreeMarker extensions to support inline processing.
      • 3h - Conversion of script and template to inline.
      • 4h - Repeat analysis and identification of additional targeted macros.
      • 2h - Conversion of additional macros to inline.
      • 2h - Code clean up and prep for release.

      Mark

        Attachments

          Issue Links

            Activity

            Hide
            mwfyffe Mark Fyffe (Inactive) added a comment -

            Committed inline processing extensions to kuali-freemarker

            Show
            mwfyffe Mark Fyffe (Inactive) added a comment - Committed inline processing extensions to kuali-freemarker
            Hide
            mwfyffe Mark Fyffe (Inactive) added a comment -

            Attached patch for conversion of script.ftl and template.ftl to inline processing.

            Show
            mwfyffe Mark Fyffe (Inactive) added a comment - Attached patch for conversion of script.ftl and template.ftl to inline processing.
            Hide
            mwfyffe Mark Fyffe (Inactive) added a comment -

            Converted collectionGroup and stacked templates to inline processing based on repeat analysis.

            After removing internal profiling, I'm now observing local Performance Medium runs as fast as 2.5s total request time - FreeMarker rendering time observed locally is down to 500ms-800ms.

            2013-09-03 08:02:09,285 [http-8080-2] u:/d: INFO  org.kuali.rice.krad.uif.util.P
            rocessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/labs
              at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFi
            lter.java:69)
              at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicatio
            nFilterChain.java:235)
            Initial Memory Usage: 399.912M/935.750M/935.750M - 42% free
            pre-handle..............................00:00.000 00:00.000 399.912M 0
            build-view:Lab-PerformanceMedium........00:00.125 00:00.125 344.940M -54.970M
            build-view-params:Lab-PerformanceMedium.00:00.000 00:00.125 344.940M 0
            build-view-backup-params:Lab-Performance00:00.000 00:00.125 344.940M 0
            perform-lifecycle:Lab-PerformanceMedium.00:00.000 00:00.125 344.940M 0
            apply-model:Lab-PerformanceMedium.......00:00.063 00:00.188 475.445M 130.504M
            apply-comp-model:Lab-PerformanceMedium..00:00.000 00:00.188 475.445M 0
            apply-model-end:Lab-PerformanceMedium...00:01.031 00:01.219 232.450M -242.995M
            perform-lifecycle-after-model:Lab-Perfor00:00.000 00:01.219 232.450M 0
            perform-lifecycle-model-reindex:Lab-Perf00:00.000 00:01.219 228.941M -3.508M
            perform-lifecycle-finalize:Lab-Performan00:00.687 00:01.906 232.375M 3.434M
            perform-lifecycle-final-reindex:Lab-Perf00:00.016 00:01.922 228.809M -3.566M
            perform-lifecycle-final:Lab-PerformanceM00:00.000 00:01.922 228.809M 0
            validate-view:Lab-PerformanceMedium.....00:00.000 00:01.922 228.809M 0
            post-handle.............................00:00.000 00:01.922 228.809M 0
            after-completion........................00:00.672 00:02.594 238.001M 9.192M
            after-completion-end....................00:00.031 00:02.625 237.676M -333.460k
            Processing Complete.....................00:00.000 00:02.625 237.676M 0
            Counters:
              bean-property-read: 18090 (00:00.000/00:00.016/00:00.000)
                longest : KradLabsForm:mediumCollection2[1].subList[0]
              bean-property-write: 29665 (00:00.000/00:00.016/00:00.000)
                longest : Disclosure:bindingInfo.bindToForm
            Elapsed Time: 00:02.625
            Memory Usage: 237.676M/868.062M/910.250M - 27% free
            Memory Delta: -162.234M/868.062M/910.250M - -18% free - tot delta: -67.687M
            

            Will work next weekend to clean up and commit this effort.

            Mark

            Show
            mwfyffe Mark Fyffe (Inactive) added a comment - Converted collectionGroup and stacked templates to inline processing based on repeat analysis. After removing internal profiling, I'm now observing local Performance Medium runs as fast as 2.5s total request time - FreeMarker rendering time observed locally is down to 500ms-800ms. 2013-09-03 08:02:09,285 [http-8080-2] u:/d: INFO org.kuali.rice.krad.uif.util.P rocessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/labs at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFi lter.java:69) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Applicatio nFilterChain.java:235) Initial Memory Usage: 399.912M/935.750M/935.750M - 42% free pre-handle..............................00:00.000 00:00.000 399.912M 0 build-view:Lab-PerformanceMedium........00:00.125 00:00.125 344.940M -54.970M build-view-params:Lab-PerformanceMedium.00:00.000 00:00.125 344.940M 0 build-view-backup-params:Lab-Performance00:00.000 00:00.125 344.940M 0 perform-lifecycle:Lab-PerformanceMedium.00:00.000 00:00.125 344.940M 0 apply-model:Lab-PerformanceMedium.......00:00.063 00:00.188 475.445M 130.504M apply-comp-model:Lab-PerformanceMedium..00:00.000 00:00.188 475.445M 0 apply-model-end:Lab-PerformanceMedium...00:01.031 00:01.219 232.450M -242.995M perform-lifecycle-after-model:Lab-Perfor00:00.000 00:01.219 232.450M 0 perform-lifecycle-model-reindex:Lab-Perf00:00.000 00:01.219 228.941M -3.508M perform-lifecycle-finalize:Lab-Performan00:00.687 00:01.906 232.375M 3.434M perform-lifecycle-final-reindex:Lab-Perf00:00.016 00:01.922 228.809M -3.566M perform-lifecycle-final:Lab-PerformanceM00:00.000 00:01.922 228.809M 0 validate-view:Lab-PerformanceMedium.....00:00.000 00:01.922 228.809M 0 post-handle.............................00:00.000 00:01.922 228.809M 0 after-completion........................00:00.672 00:02.594 238.001M 9.192M after-completion-end....................00:00.031 00:02.625 237.676M -333.460k Processing Complete.....................00:00.000 00:02.625 237.676M 0 Counters: bean-property-read: 18090 (00:00.000/00:00.016/00:00.000) longest : KradLabsForm:mediumCollection2[1].subList[0] bean-property-write: 29665 (00:00.000/00:00.016/00:00.000) longest : Disclosure:bindingInfo.bindToForm Elapsed Time: 00:02.625 Memory Usage: 237.676M/868.062M/910.250M - 27% free Memory Delta: -162.234M/868.062M/910.250M - -18% free - tot delta: -67.687M Will work next weekend to clean up and commit this effort. Mark
            Hide
            mwfyffe Mark Fyffe (Inactive) added a comment - - edited

            Modified freemarker extensions related to this issue:

            • Changed #krad_inline directive to #inline
            • Changed names of FM extension classes:
              • InlineKradElement -> InlineTemplateElement
              • InlineKradAdaptor -> InlineTemplateAdaptor
              • KualiTemplateUtils -> InlineTemplateUtils

            Added this change locally as 2.3.20-patch2, and modified local Rice 2.4 working copy to use updated names for directives and inline utilities. I'll be working this evening and tomorrow to clean up the a final version of krad-web-framework and krad-web for commit.

            Mark

            Show
            mwfyffe Mark Fyffe (Inactive) added a comment - - edited Modified freemarker extensions related to this issue: Changed #krad_inline directive to #inline Changed names of FM extension classes: InlineKradElement -> InlineTemplateElement InlineKradAdaptor -> InlineTemplateAdaptor KualiTemplateUtils -> InlineTemplateUtils Added this change locally as 2.3.20-patch2, and modified local Rice 2.4 working copy to use updated names for directives and inline utilities. I'll be working this evening and tomorrow to clean up the a final version of krad-web-framework and krad-web for commit. Mark
            Hide
            mwfyffe Mark Fyffe (Inactive) added a comment -

            Updated rice pom.xml to point at freemarker-2.3.20-patch2

            Converted groupWrap.ftl to inline to reduce duplication between inline and interpreted templates.

            This issue should now be resolved.

            Show
            mwfyffe Mark Fyffe (Inactive) added a comment - Updated rice pom.xml to point at freemarker-2.3.20-patch2 Converted groupWrap.ftl to inline to reduce duplication between inline and interpreted templates. This issue should now be resolved.
            Hide
            mwfyffe Mark Fyffe (Inactive) added a comment -

            Code review for inline template processing code changes:

            https://fisheye.kuali.org/cru/rice-287

            Show
            mwfyffe Mark Fyffe (Inactive) added a comment - Code review for inline template processing code changes: https://fisheye.kuali.org/cru/rice-287

              People

              • Assignee:
                mwfyffe Mark Fyffe (Inactive)
                Reporter:
                mwfyffe Mark Fyffe (Inactive)
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - 1 day, 6 hours Original Estimate - 1 day, 6 hours
                  1d 6h
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 2 days
                  2d