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

Look into multithreading during the view lifecycle

    Details

    • Type: Task Task
    • Status: Closed Closed
    • Priority: Major Major
    • Resolution: Complete
    • Affects Version/s: None
    • Fix Version/s: 2.4
    • Security Level: Public (Public: Anyone can view)
    • Labels:
      None
    • Similar issues:
      KULRICE-8797Reduce object creation in view lifecycle
      KULRICE-10810Look into transaction view lifecycle
      KULRICE-7220Look into replacing component update process with full view lifecycle
      KULRICE-11062Do POC on changing lifecycle to use reflection
      KULRICE-5571Document the View lifecycle in detail with sequence and mind map
      KULRICE-13147Inefficiencies in view lifecycle and rendering
      KULRICE-11755Look into performance analysis data from Jan 14 F2F
      KULRICE-12934Some classes are duplicated multiple times over if they are added during the lifecycle
      KULRICE-10919RichMessageTest IT failures IllegalStateException: No view lifecycle is active on this thread
      KULRICE-8468Performance: Collect templates through view lifecycle and include once in view rendering
    • Epic Link:
    • Rice Module:
      KRAD
    • Sprint:
      2.4.0-m2 Sprint 2
    • KAI Review Status:
      Not Required
    • KTI Review Status:
      Not Required
    • Include in Release Notes?:
      Yes

      Description

      During the view lifecycle several components are processed. Using multiple threads to build the components could help performance

      1. ComponentFreemarkerTest.java
        5 kB
        Mark Fyffe
      2. kulrice-8798_component_apply_model_poc.patch
        84 kB
        Mark Fyffe
      3. kulrice-8798-freemarker-rendering-poc.patch
        69 kB
        Mark Fyffe
      4. kulrice-8798-sanitytest.patch
        3.77 MB
        Mark Fyffe

        Issue Links

          Activity

          Hide
          Mark Fyffe (Inactive) added a comment -

          The highest number of executions related to component lifecycle is on ViewHelperServiceImpl.performComponentApplyModel(), so this method would appear to be the best candidate for multithreading.

          I set up a process counter for this method on performance medium, which yields a total of 26037 executions, broken down as noted in the monitors below.

          2013-08-12 08:25:39,396 [http-8080-1] u:/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/labs
            at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69)
            at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          Initial Memory Usage: 200.287M/553.437M/910.250M - 36% free
          comp-model:1000:Action..................00:02.105 00:02.105 82.359M -117.926M
          comp-model:1000:LightBox................00:01.507 00:03.612 314.147M 231.787M
          comp-model:1000:Tooltip.................00:00.195 00:03.807 254.086M -60.060M
          comp-model:1000:QuickFinder.............00:00.068 00:03.875 228.346M -25.739M
          comp-model:2000:Action..................00:00.175 00:04.050 172.576M -55.770M
          comp-model:2000:Image...................00:00.305 00:04.355 290.601M 118.025M
          comp-model:3000:Action..................00:00.344 00:04.699 166.367M -124.234M
          comp-model:2000:Tooltip.................00:00.002 00:04.701 166.367M 0
          comp-model:1000:Message.................00:00.009 00:04.710 163.832M -2.535M
          comp-model:1000:Help....................00:00.359 00:05.069 247.750M 83.918M
          comp-model:1000:Label...................00:00.007 00:05.076 245.766M -1.984M
          comp-model:1000:InputField..............00:00.042 00:05.118 231.873M -13.892M
          comp-model:1000:Inquiry.................00:00.001 00:05.119 231.873M 0
          comp-model:1000:FieldValidationMessages.00:00.001 00:05.120 231.873M 0
          comp-model:3000:Image...................00:00.001 00:05.121 231.873M 0
          comp-model:3000:LightBox................00:00.001 00:05.122 231.873M 0
          comp-model:2000:QuickFinder.............00:00.001 00:05.123 231.873M 0
          comp-model:1000:TextControl.............00:00.002 00:05.125 229.888M -1.984M
          Processing Complete.....................00:05.878 00:11.003 356.034M 126.145M
          Monitors:
            comp-model:3765:Action
            comp-model:2:BlockUI
            comp-model:4:BreadcrumbItem
            comp-model:1:Breadcrumbs
            comp-model:24:CollectionGroup
            comp-model:344:Disclosure
            comp-model:24:FieldGroup
            comp-model:1150:FieldValidationMessages
            comp-model:1:FormView
            comp-model:319:Group
            comp-model:343:GroupValidationMessages
            comp-model:1:Growls
            comp-model:172:Header
            comp-model:1177:Help
            comp-model:3447:Image
            comp-model:1150:InputField
            comp-model:1150:Inquiry
            comp-model:1171:Label
            comp-model:3447:LightBox
            comp-model:1150:Link
            comp-model:1237:Message
            comp-model:4:MessageField
            comp-model:1:NavigationGroup
            comp-model:1:PageGroup
            comp-model:1:PageValidationMessages
            comp-model:2297:QuickFinder
            comp-model:3:RichTable
            comp-model:3:SelectControl
            comp-model:1147:TextControl
            comp-model:2500:Tooltip
            comp-model:1:ViewHeader
          Counters:
            bean-property-read: 17190 (00:00.000/00:00.182/00:00.000)
              longest : KradLabsForm:mediumCollection2[0].subList[1]
            comp-model: 26037 (00:00.000/00:00.254/00:00.000)
              longest : u187
            bean-property-write: 27991 (00:00.000/00:00.008/00:00.000)
              longest : FieldValidationMessages:bindingInfo.bindToForm
            comp-nest: 26037 (00:00.000/00:00.001/00:00.000)
              longest : class org.kuali.rice.krad.uif.widget.QuickFinder:u100302:2:1
          

          Individual execution is relatively fast: max time is 254ms. Total execution time involving components appears to be around 3 seconds for performance medium. It is possible that adding an event queue and thread pool could break down this high execution count down into multiple worker threads, but it remains to be seen whether threading and synchronization overhead would negate the benefits.

          From here, I'll work to positively identify the execution pattern of performApplyComponentModel, dig deeper to look for potential thread-safety issues, and assemble a POC to see if nested performComponentApplyModel calls may be queued rather than executed synchronously to improve performance.

          Show
          Mark Fyffe (Inactive) added a comment - The highest number of executions related to component lifecycle is on ViewHelperServiceImpl.performComponentApplyModel(), so this method would appear to be the best candidate for multithreading. I set up a process counter for this method on performance medium, which yields a total of 26037 executions, broken down as noted in the monitors below. 2013-08-12 08:25:39,396 [http-8080-1] u:/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/labs at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) Initial Memory Usage: 200.287M/553.437M/910.250M - 36% free comp-model:1000:Action..................00:02.105 00:02.105 82.359M -117.926M comp-model:1000:LightBox................00:01.507 00:03.612 314.147M 231.787M comp-model:1000:Tooltip.................00:00.195 00:03.807 254.086M -60.060M comp-model:1000:QuickFinder.............00:00.068 00:03.875 228.346M -25.739M comp-model:2000:Action..................00:00.175 00:04.050 172.576M -55.770M comp-model:2000:Image...................00:00.305 00:04.355 290.601M 118.025M comp-model:3000:Action..................00:00.344 00:04.699 166.367M -124.234M comp-model:2000:Tooltip.................00:00.002 00:04.701 166.367M 0 comp-model:1000:Message.................00:00.009 00:04.710 163.832M -2.535M comp-model:1000:Help....................00:00.359 00:05.069 247.750M 83.918M comp-model:1000:Label...................00:00.007 00:05.076 245.766M -1.984M comp-model:1000:InputField..............00:00.042 00:05.118 231.873M -13.892M comp-model:1000:Inquiry.................00:00.001 00:05.119 231.873M 0 comp-model:1000:FieldValidationMessages.00:00.001 00:05.120 231.873M 0 comp-model:3000:Image...................00:00.001 00:05.121 231.873M 0 comp-model:3000:LightBox................00:00.001 00:05.122 231.873M 0 comp-model:2000:QuickFinder.............00:00.001 00:05.123 231.873M 0 comp-model:1000:TextControl.............00:00.002 00:05.125 229.888M -1.984M Processing Complete.....................00:05.878 00:11.003 356.034M 126.145M Monitors: comp-model:3765:Action comp-model:2:BlockUI comp-model:4:BreadcrumbItem comp-model:1:Breadcrumbs comp-model:24:CollectionGroup comp-model:344:Disclosure comp-model:24:FieldGroup comp-model:1150:FieldValidationMessages comp-model:1:FormView comp-model:319:Group comp-model:343:GroupValidationMessages comp-model:1:Growls comp-model:172:Header comp-model:1177:Help comp-model:3447:Image comp-model:1150:InputField comp-model:1150:Inquiry comp-model:1171:Label comp-model:3447:LightBox comp-model:1150:Link comp-model:1237:Message comp-model:4:MessageField comp-model:1:NavigationGroup comp-model:1:PageGroup comp-model:1:PageValidationMessages comp-model:2297:QuickFinder comp-model:3:RichTable comp-model:3:SelectControl comp-model:1147:TextControl comp-model:2500:Tooltip comp-model:1:ViewHeader Counters: bean-property-read: 17190 (00:00.000/00:00.182/00:00.000) longest : KradLabsForm:mediumCollection2[0].subList[1] comp-model: 26037 (00:00.000/00:00.254/00:00.000) longest : u187 bean-property-write: 27991 (00:00.000/00:00.008/00:00.000) longest : FieldValidationMessages:bindingInfo.bindToForm comp-nest: 26037 (00:00.000/00:00.001/00:00.000) longest : class org.kuali.rice.krad.uif.widget.QuickFinder:u100302:2:1 Individual execution is relatively fast: max time is 254ms. Total execution time involving components appears to be around 3 seconds for performance medium. It is possible that adding an event queue and thread pool could break down this high execution count down into multiple worker threads, but it remains to be seen whether threading and synchronization overhead would negate the benefits. From here, I'll work to positively identify the execution pattern of performApplyComponentModel, dig deeper to look for potential thread-safety issues, and assemble a POC to see if nested performComponentApplyModel calls may be queued rather than executed synchronously to improve performance.
          Hide
          Jerry Neal (Inactive) added a comment -

          Mark,

          Great analysis!

          Another area I was hoping you could research is the Freemarker rendering. This might be reaching a bit, but I am wondering about the possibility of building a custom Freemarker directive that would use multiple threads to render templates in parallel. I think doing this for rendering collection groups in parallel is where we can get the best gains and should be safe. This will likely require a custom Freemarker writer as well.

          We have a Freemarker project that contains our customizations. If you want to get into the code more and do some POCs you can access this here:

          https://svn.kuali.org/repos/foundation/trunk/kuali-freemarker

          If you have any questions just let me know.

          thanks,
          Jerry

          Show
          Jerry Neal (Inactive) added a comment - Mark, Great analysis! Another area I was hoping you could research is the Freemarker rendering. This might be reaching a bit, but I am wondering about the possibility of building a custom Freemarker directive that would use multiple threads to render templates in parallel. I think doing this for rendering collection groups in parallel is where we can get the best gains and should be safe. This will likely require a custom Freemarker writer as well. We have a Freemarker project that contains our customizations. If you want to get into the code more and do some POCs you can access this here: https://svn.kuali.org/repos/foundation/trunk/kuali-freemarker If you have any questions just let me know. thanks, Jerry
          Hide
          Mark Fyffe (Inactive) added a comment - - edited

          Assembled a unit test (attached) as POC for rendering a KRAD component independent of view rendering.

          This test case functions properly in the krad-web-framework project when the krad/WEB-INF/ftl/component/message.ftl and the krad/WEB-INF/ftl/lib folder are copied from the krad-web project into src/test/resources in krad-web-framework, and a dependency added to spring-context-support. A full patch to krad-web-framework is also attached.

          This test case demonstrates that a message component can be rendered asynchronously as a String. It is possible that this approach could extend to other components rendered via template.ftl. A simple wait/notify mechanism could then be used to render components in parallel, then inject the results into the template once the thread completes.

          If this works well, freemarker rendering could be fired as soon as applyModel is completed on the component.

          I'll dig deeper into this tomorrow.

          Show
          Mark Fyffe (Inactive) added a comment - - edited Assembled a unit test (attached) as POC for rendering a KRAD component independent of view rendering. This test case functions properly in the krad-web-framework project when the krad/WEB-INF/ftl/component/message.ftl and the krad/WEB-INF/ftl/lib folder are copied from the krad-web project into src/test/resources in krad-web-framework, and a dependency added to spring-context-support. A full patch to krad-web-framework is also attached. This test case demonstrates that a message component can be rendered asynchronously as a String. It is possible that this approach could extend to other components rendered via template.ftl. A simple wait/notify mechanism could then be used to render components in parallel, then inject the results into the template once the thread completes. If this works well, freemarker rendering could be fired as soon as applyModel is completed on the component. I'll dig deeper into this tomorrow.
          Hide
          Mark Fyffe (Inactive) added a comment -

          I spent some time working with ViewHelperServiceImpl.performComponentApplyModel() today. Breaking apart view processing into multiple threads is certainly doable, and based on an initial pass at implementation can results in a significant reduction in rendering time for the TransactionView rendering test.

          http://localhost:8080/krad-dev/kr-krad/transaction?viewId=TransactionView

          A breakdown of the request is below -

          2013-08-18 22:55:21,970 [http-8080-1] u:admin/d: DEBUG org.kuali.rice.krad.datad
          ictionary.uif.UifDictionaryIndex - View TransactionView not in cache - creating 
          and storing to cache
          2013-08-18 22:55:22,236 [http-8080-1] u:admin/d: INFO  org.kuali.rice.krad.uif.s
          ervice.impl.ViewServiceImpl - performing initialize phase for view: TransactionV
          iew
          2013-08-18 22:55:22,392 [http-8080-1] u:admin/d: INFO  org.kuali.rice.krad.uif.s
          ervice.impl.ViewServiceImpl - performing apply model phase for view: Transaction
          View
          2013-08-18 22:55:22,392 [http-8080-1] u:admin/d: INFO  org.kuali.rice.krad.uif.s
          ervice.impl.ViewHelperServiceImpl$ComponentToApply - Component apply model is pe
          nding... 13 children waiting
          2013-08-18 22:55:22,408 [http-8080-2] u:/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /themes/kboot/theme-derived.properties
            at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69)
            at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          Initial Memory Usage: 136.270M/559.562M/910.250M - 24% free
          Processing Complete.....................00:00.000 00:00.000 136.270M 0
          Elapsed Time: 00:00.000
          Memory Usage: 136.270M/559.562M/910.250M - 24% free
          Memory Delta: 0/559.562M/910.250M - 0% free - tot delta: 0
          2013-08-18 22:55:22,423 [krad-comp-apply(7)] u:admin/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker
            at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959)
          Initial Memory Usage: 134.385M/559.562M/910.250M - 24% free
          Processing Complete.....................00:00.000 00:00.000 134.385M 0
          Monitors:
            comp-model:1:Action
            comp-model:1:Disclosure
            comp-model:1:FieldValidationMessages
            comp-model:1:Group
            comp-model:1:GroupValidationMessages
            comp-model:1:Header
            comp-model:1:Help
            comp-model:1:Image
            comp-model:1:Label
            comp-model:1:LightBox
            comp-model:1:Link
            comp-model:1:Message
            comp-model:1:TextControl
            comp-model:7:Tooltip
            comp-model:1:ViewHeader
          Counters:
            comp-model: 21 (00:00.000/00:00.000/00:00.000)
            bean-property-write: 17 (00:00.000/00:00.000/00:00.000)
          Elapsed Time: 00:00.000
          Memory Usage: 134.385M/559.562M/910.250M - 24% free
          Memory Delta: 0/559.562M/910.250M - 0% free - tot delta: 0
          2013-08-18 22:55:22,455 [krad-comp-apply(6)] u:admin/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker
            at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959)
          Initial Memory Usage: 134.385M/559.562M/910.250M - 24% free
          Memory Delta: 0/559.562M/910.250M - 0% free - tot delta: 0
          2013-08-18 22:55:22,455 [krad-comp-apply(6)] u:admin/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker
            at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959)
          Initial Memory Usage: 134.385M/559.562M/910.250M - 24% free
          Processing Complete.....................00:00.032 00:00.032 133.443M -964.906k
          Monitors:
            comp-model:1:Action
            comp-model:1:Disclosure
            comp-model:1:Group
            comp-model:1:Image
            comp-model:1:Inquiry
            comp-model:1:LightBox
            comp-model:1:QuickFinder
          Counters:
            comp-model: 7 (00:00.000/00:00.032/00:00.004)
              longest : class org.kuali.rice.krad.uif.widget.QuickFinder:u100142
            bean-property-write: 11 (00:00.000/00:00.000/00:00.000)
          Elapsed Time: 00:00.032
          Memory Usage: 133.443M/559.562M/910.250M - 23% free
          Memory Delta: -964.906k/559.562M/910.250M - 0% free - tot delta: 0
          2013-08-18 22:55:23,896 [krad-comp-apply(5)] u:admin/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker
            at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959)
          Initial Memory Usage: 139.153M/559.562M/910.250M - 24% free
          Processing Complete.....................00:01.503 00:01.503 118.225M -20.927M
          Monitors:
            comp-model:2:Action
            comp-model:2:BlockUI
            comp-model:4:BreadcrumbItem
            comp-model:1:Breadcrumbs
            comp-model:1:CollectionGroup
            comp-model:6:Disclosure
            comp-model:1:FormView
            comp-model:4:Group
            comp-model:6:GroupValidationMessages
            comp-model:1:Growls
            comp-model:4:Header
            comp-model:4:Help
            comp-model:1:InputField
            comp-model:3:Label
            comp-model:11:Message
            comp-model:3:MessageField
            comp-model:1:PageGroup
            comp-model:1:PageValidationMessages
            comp-model:1:RichTable
            comp-model:5:Tooltip
          Counters:
            comp-model: 62 (00:00.000/00:01.460/00:00.010)
              longest : class org.kuali.rice.krad.uif.container.CollectionGroup:rollupList
            bean-property-write: 148 (00:00.000/00:00.002/00:00.000)
              longest : Action:preSubmitCall
            bean-property-read: 13 (00:00.000/00:00.000/00:00.000)
          Elapsed Time: 00:01.503
          Memory Usage: 118.225M/549.125M/910.250M - 21% free
          Memory Delta: -20.927M/549.125M/910.250M - -3% free - tot delta: -10.437M
          2013-08-18 22:55:23,896 [http-8080-1] u:admin/d: INFO  org.kuali.rice.krad.uif.service.impl.ViewServiceImpl - reindexing after apply model for view: TransactionView
          2013-08-18 22:55:23,901 [http-8080-1] u:admin/d: INFO  org.kuali.rice.krad.uif.service.impl.ViewServiceImpl - performing finalize phase for view: TransactionView
          2013-08-18 22:55:24,017 [http-8080-1] u:admin/d: INFO  org.kuali.rice.krad.uif.service.impl.ViewServiceImpl - processing final indexing for view: TransactionView
          2013-08-18 22:55:24,733 [http-8080-1] u:/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/transaction
            at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69)
            at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          Initial Memory Usage: 313.159M/559.562M/910.250M - 55% free
          view:start:TransactionView..............00:00.313 00:00.313 246.953M -66.206M
          viewlc:init:TransactionView.............00:00.156 00:00.469 140.095M -106.856M
          view-comp-apply:TransactionView.........00:01.504 00:01.973 114.704M -25.390M
          viewlc:reindex:TransactionView..........00:00.005 00:01.978 114.704M 0
          viewlc:finalize:TransactionView.........00:00.116 00:02.094 100.620M -14.083M
          viewlc:finalindex:TransactionView.......00:00.003 00:02.097 100.620M 0
          Processing Complete.....................00:00.712 00:02.809 61.875M -38.743M
          Counters:
            bean-property-read: 368 (00:00.000/00:00.016/00:00.000)
              longest : CollectionGroup:layoutManager.addLineGroup.header.toolTip
            bean-property-write: 17 (00:00.000/00:00.000/00:00.000)
          Elapsed Time: 00:02.809
          Memory Usage: 61.875M/549.125M/910.250M - 11% free
          Memory Delta: -251.283M/549.125M/910.250M - -45% free - tot delta: -10.437M
          

          Performance Medium completes in 2.1s using this POC as well

          2013-08-18 23:00:12,127 [http-8080-3] u:/d: INFO  org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/labs
            at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69)
            at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          Initial Memory Usage: 196.319M/551.187M/910.250M - 35% free
          view:start:Lab-PerformanceMedium........00:00.219 00:00.219 114.663M -81.655M
          viewlc:init:Lab-PerformanceMedium.......00:00.078 00:00.297 96.224M -18.438M
          view-comp-apply:Lab-PerformanceMedium...00:00.188 00:00.485 45.182M -51.041M
          viewlc:finalize:Lab-PerformanceMedium...00:01.546 00:02.031 426.175M 380.993M
          viewlc:finalindex:Lab-PerformanceMedium.00:00.003 00:02.034 426.175M 0
          Processing Complete.....................00:00.098 00:02.132 418.031M -8.144M
          Counters:
            bean-property-read: 775 (00:00.000/00:00.001/00:00.000)
              longest : KradLabsForm:inputField8
            bean-property-write: 18 (00:00.000/00:00.000/00:00.000)
          Elapsed Time: 00:02.132
          Memory Usage: 418.031M/684.937M/910.250M - 61% free
          Memory Delta: 221.711M/684.937M/910.250M - 32% free - tot delta: 133.750M
          

          A patch containing the thread pool implementation used to achieve the timings above is attached.

          Note, however, that this patch is not stable Although most simple views can be rendered in this way without trouble, more complex views are still prone to stability issues - sometimes they render properly, but on some requests rendering is incomplete or a timeout occurs due to a flaw in the wait/notify mechanism. All components apply, however, so the timings are correct. Below is a brief overview of the approach taken:

          1. ViewHelperServiceImpl.performComponentApplyModel() was converted from a call-recursive algorithm to a tail-recursive queueing algorithm. This change alone resulted in no appreciable change in behavior.
          2. Created the ComponentToApply class to represent a call to performComponentApplyModel(), and implemented hashCode and equals to identify components by view/component system identity.
            1. View, model, component, and visited Ids are maintained.
            2. A set of child ComponentToApply instances, and a reference to a parent instance is also maintained.
          3. Created a Runnable ComponentApplyWorker and moved the bulk of the code in performComponentApplyModel() to the run() method of this worker.
          4. Added a static queue and thread pool for managing ComponentApplyWorker execution.
            1. Any time a ComponentToApply instance is added to the queue, a worker will be added to the pool if the number of active workers is less than 1/16th of the size of the queue (this factor would need to be made adjustable by configuration)
          5. Upon execution, each worker:
            1. Removes the next ComponentToApply instance from the queue.
            2. Parent component is pushed to the current component's context.
            3. All steps originally from performComponentApplyModel, from pushAllToContext() to runCompoentModifiers() are executed.
            4. All child components are added to the queue.
            5. The current component is marked as completed:
              1. If all children have completed, the component is flagged as complete and waiting threads are notified. NOTE: At this point, Freemarker rendering could be performed on the completed component.
              2. If the parent is non-null, the completed children count for the component is increased and the parent is marked as completed - the previous step is recursively taken on the parent.
            6. If no more components are queued, then the worker will exit and be retired from the pool.
          6. Rather than process the component inline, when performComponentApplyModel() is executed, the entire ComponentToApply tree for the component is build and the top node of the tree added queued for execution - a worker will be added to the pool if needed.
            1. If the performComponentApplyModel() call is recursively invoked by a worker thread then the component invoking the recursive call will take note of the top-level component and will wait.
            2. Otherwise, the call to performComponentApplyModel will wait until the top level component (the view) has been marked as completed.

          In order to achieve basic functionality enough to prove this approach is possible, I had to expose the GlobalVariables stack for forwarding to the worker threads, and subsequently synchronized GlobalVariables and MessageMap collections.

          Further review of UIF components, and a thorough cleanup of the queueing algorithm noted above would be needed. It will take roughly 20-30 hours for full UIF component analysis and to clean up and stabilize the implementation following this approach. Another 4-8 hours would be required to tie in asynchronous Freemarker execution. It appears based on the timing data from initial tests that once this cleanup has been completed, a 50% or better reduction in rendering time can be expected.

          Mark

          Show
          Mark Fyffe (Inactive) added a comment - I spent some time working with ViewHelperServiceImpl.performComponentApplyModel() today. Breaking apart view processing into multiple threads is certainly doable, and based on an initial pass at implementation can results in a significant reduction in rendering time for the TransactionView rendering test. http://localhost:8080/krad-dev/kr-krad/transaction?viewId=TransactionView A breakdown of the request is below - 2013-08-18 22:55:21,970 [http-8080-1] u:admin/d: DEBUG org.kuali.rice.krad.datad ictionary.uif.UifDictionaryIndex - View TransactionView not in cache - creating and storing to cache 2013-08-18 22:55:22,236 [http-8080-1] u:admin/d: INFO org.kuali.rice.krad.uif.s ervice.impl.ViewServiceImpl - performing initialize phase for view: TransactionV iew 2013-08-18 22:55:22,392 [http-8080-1] u:admin/d: INFO org.kuali.rice.krad.uif.s ervice.impl.ViewServiceImpl - performing apply model phase for view: Transaction View 2013-08-18 22:55:22,392 [http-8080-1] u:admin/d: INFO org.kuali.rice.krad.uif.s ervice.impl.ViewHelperServiceImpl$ComponentToApply - Component apply model is pe nding... 13 children waiting 2013-08-18 22:55:22,408 [http-8080-2] u:/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /themes/kboot/theme-derived.properties at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) Initial Memory Usage: 136.270M/559.562M/910.250M - 24% free Processing Complete.....................00:00.000 00:00.000 136.270M 0 Elapsed Time: 00:00.000 Memory Usage: 136.270M/559.562M/910.250M - 24% free Memory Delta: 0/559.562M/910.250M - 0% free - tot delta: 0 2013-08-18 22:55:22,423 [krad-comp-apply(7)] u:admin/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959) Initial Memory Usage: 134.385M/559.562M/910.250M - 24% free Processing Complete.....................00:00.000 00:00.000 134.385M 0 Monitors: comp-model:1:Action comp-model:1:Disclosure comp-model:1:FieldValidationMessages comp-model:1:Group comp-model:1:GroupValidationMessages comp-model:1:Header comp-model:1:Help comp-model:1:Image comp-model:1:Label comp-model:1:LightBox comp-model:1:Link comp-model:1:Message comp-model:1:TextControl comp-model:7:Tooltip comp-model:1:ViewHeader Counters: comp-model: 21 (00:00.000/00:00.000/00:00.000) bean-property-write: 17 (00:00.000/00:00.000/00:00.000) Elapsed Time: 00:00.000 Memory Usage: 134.385M/559.562M/910.250M - 24% free Memory Delta: 0/559.562M/910.250M - 0% free - tot delta: 0 2013-08-18 22:55:22,455 [krad-comp-apply(6)] u:admin/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959) Initial Memory Usage: 134.385M/559.562M/910.250M - 24% free Memory Delta: 0/559.562M/910.250M - 0% free - tot delta: 0 2013-08-18 22:55:22,455 [krad-comp-apply(6)] u:admin/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959) Initial Memory Usage: 134.385M/559.562M/910.250M - 24% free Processing Complete.....................00:00.032 00:00.032 133.443M -964.906k Monitors: comp-model:1:Action comp-model:1:Disclosure comp-model:1:Group comp-model:1:Image comp-model:1:Inquiry comp-model:1:LightBox comp-model:1:QuickFinder Counters: comp-model: 7 (00:00.000/00:00.032/00:00.004) longest : class org.kuali.rice.krad.uif.widget.QuickFinder:u100142 bean-property-write: 11 (00:00.000/00:00.000/00:00.000) Elapsed Time: 00:00.032 Memory Usage: 133.443M/559.562M/910.250M - 23% free Memory Delta: -964.906k/559.562M/910.250M - 0% free - tot delta: 0 2013-08-18 22:55:23,896 [krad-comp-apply(5)] u:admin/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (component-apply-model): Component Apply Model worker at org.kuali.rice.krad.uif.service.impl.ViewHelperServiceImpl$ComponentApplyWorker.run(ViewHelperServiceImpl.java:959) Initial Memory Usage: 139.153M/559.562M/910.250M - 24% free Processing Complete.....................00:01.503 00:01.503 118.225M -20.927M Monitors: comp-model:2:Action comp-model:2:BlockUI comp-model:4:BreadcrumbItem comp-model:1:Breadcrumbs comp-model:1:CollectionGroup comp-model:6:Disclosure comp-model:1:FormView comp-model:4:Group comp-model:6:GroupValidationMessages comp-model:1:Growls comp-model:4:Header comp-model:4:Help comp-model:1:InputField comp-model:3:Label comp-model:11:Message comp-model:3:MessageField comp-model:1:PageGroup comp-model:1:PageValidationMessages comp-model:1:RichTable comp-model:5:Tooltip Counters: comp-model: 62 (00:00.000/00:01.460/00:00.010) longest : class org.kuali.rice.krad.uif.container.CollectionGroup:rollupList bean-property-write: 148 (00:00.000/00:00.002/00:00.000) longest : Action:preSubmitCall bean-property-read: 13 (00:00.000/00:00.000/00:00.000) Elapsed Time: 00:01.503 Memory Usage: 118.225M/549.125M/910.250M - 21% free Memory Delta: -20.927M/549.125M/910.250M - -3% free - tot delta: -10.437M 2013-08-18 22:55:23,896 [http-8080-1] u:admin/d: INFO org.kuali.rice.krad.uif.service.impl.ViewServiceImpl - reindexing after apply model for view: TransactionView 2013-08-18 22:55:23,901 [http-8080-1] u:admin/d: INFO org.kuali.rice.krad.uif.service.impl.ViewServiceImpl - performing finalize phase for view: TransactionView 2013-08-18 22:55:24,017 [http-8080-1] u:admin/d: INFO org.kuali.rice.krad.uif.service.impl.ViewServiceImpl - processing final indexing for view: TransactionView 2013-08-18 22:55:24,733 [http-8080-1] u:/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/transaction at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) Initial Memory Usage: 313.159M/559.562M/910.250M - 55% free view:start:TransactionView..............00:00.313 00:00.313 246.953M -66.206M viewlc:init:TransactionView.............00:00.156 00:00.469 140.095M -106.856M view-comp-apply:TransactionView.........00:01.504 00:01.973 114.704M -25.390M viewlc:reindex:TransactionView..........00:00.005 00:01.978 114.704M 0 viewlc:finalize:TransactionView.........00:00.116 00:02.094 100.620M -14.083M viewlc:finalindex:TransactionView.......00:00.003 00:02.097 100.620M 0 Processing Complete.....................00:00.712 00:02.809 61.875M -38.743M Counters: bean-property-read: 368 (00:00.000/00:00.016/00:00.000) longest : CollectionGroup:layoutManager.addLineGroup.header.toolTip bean-property-write: 17 (00:00.000/00:00.000/00:00.000) Elapsed Time: 00:02.809 Memory Usage: 61.875M/549.125M/910.250M - 11% free Memory Delta: -251.283M/549.125M/910.250M - -45% free - tot delta: -10.437M Performance Medium completes in 2.1s using this POC as well 2013-08-18 23:00:12,127 [http-8080-3] u:/d: INFO org.kuali.rice.krad.uif.util.ProcessLogger - KRAD Process Trace (request): Servlet Request /kr-krad/labs at org.kuali.rice.krad.uif.util.ProcessLoggingFilter.doFilter(ProcessLoggingFilter.java:69) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) Initial Memory Usage: 196.319M/551.187M/910.250M - 35% free view:start:Lab-PerformanceMedium........00:00.219 00:00.219 114.663M -81.655M viewlc:init:Lab-PerformanceMedium.......00:00.078 00:00.297 96.224M -18.438M view-comp-apply:Lab-PerformanceMedium...00:00.188 00:00.485 45.182M -51.041M viewlc:finalize:Lab-PerformanceMedium...00:01.546 00:02.031 426.175M 380.993M viewlc:finalindex:Lab-PerformanceMedium.00:00.003 00:02.034 426.175M 0 Processing Complete.....................00:00.098 00:02.132 418.031M -8.144M Counters: bean-property-read: 775 (00:00.000/00:00.001/00:00.000) longest : KradLabsForm:inputField8 bean-property-write: 18 (00:00.000/00:00.000/00:00.000) Elapsed Time: 00:02.132 Memory Usage: 418.031M/684.937M/910.250M - 61% free Memory Delta: 221.711M/684.937M/910.250M - 32% free - tot delta: 133.750M A patch containing the thread pool implementation used to achieve the timings above is attached. Note, however, that this patch is not stable Although most simple views can be rendered in this way without trouble, more complex views are still prone to stability issues - sometimes they render properly, but on some requests rendering is incomplete or a timeout occurs due to a flaw in the wait/notify mechanism. All components apply, however, so the timings are correct. Below is a brief overview of the approach taken: ViewHelperServiceImpl.performComponentApplyModel() was converted from a call-recursive algorithm to a tail-recursive queueing algorithm. This change alone resulted in no appreciable change in behavior. Created the ComponentToApply class to represent a call to performComponentApplyModel(), and implemented hashCode and equals to identify components by view/component system identity. View, model, component, and visited Ids are maintained. A set of child ComponentToApply instances, and a reference to a parent instance is also maintained. Created a Runnable ComponentApplyWorker and moved the bulk of the code in performComponentApplyModel() to the run() method of this worker. Added a static queue and thread pool for managing ComponentApplyWorker execution. Any time a ComponentToApply instance is added to the queue, a worker will be added to the pool if the number of active workers is less than 1/16th of the size of the queue (this factor would need to be made adjustable by configuration) Upon execution, each worker: Removes the next ComponentToApply instance from the queue. Parent component is pushed to the current component's context. All steps originally from performComponentApplyModel, from pushAllToContext() to runCompoentModifiers() are executed. All child components are added to the queue. The current component is marked as completed: If all children have completed, the component is flagged as complete and waiting threads are notified. NOTE: At this point, Freemarker rendering could be performed on the completed component. If the parent is non-null, the completed children count for the component is increased and the parent is marked as completed - the previous step is recursively taken on the parent. If no more components are queued, then the worker will exit and be retired from the pool. Rather than process the component inline, when performComponentApplyModel() is executed, the entire ComponentToApply tree for the component is build and the top node of the tree added queued for execution - a worker will be added to the pool if needed. If the performComponentApplyModel() call is recursively invoked by a worker thread then the component invoking the recursive call will take note of the top-level component and will wait. Otherwise, the call to performComponentApplyModel will wait until the top level component (the view) has been marked as completed. In order to achieve basic functionality enough to prove this approach is possible, I had to expose the GlobalVariables stack for forwarding to the worker threads, and subsequently synchronized GlobalVariables and MessageMap collections. Further review of UIF components, and a thorough cleanup of the queueing algorithm noted above would be needed. It will take roughly 20-30 hours for full UIF component analysis and to clean up and stabilize the implementation following this approach. Another 4-8 hours would be required to tie in asynchronous Freemarker execution. It appears based on the timing data from initial tests that once this cleanup has been completed, a 50% or better reduction in rendering time can be expected. Mark
          Hide
          Mark Fyffe (Inactive) added a comment -

          Attached patch file for a sanity test facilitating the loading of views and other components copied from krad-sampleapp.

          Following common-case analysis, this test and related environment can serve as a basis for improving coverage of lifecycle component processing scenarios, to ensure correct operation after multithreading implementation.

          Show
          Mark Fyffe (Inactive) added a comment - Attached patch file for a sanity test facilitating the loading of views and other components copied from krad-sampleapp. Following common-case analysis, this test and related environment can serve as a basis for improving coverage of lifecycle component processing scenarios, to ensure correct operation after multithreading implementation.

            People

            • Assignee:
              Mark Fyffe (Inactive)
              Reporter:
              Jerry Neal (Inactive)
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

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

                  Agile

                    Structure Helper Panel