Uploaded image for project: 'Kuali Rice Development'
  1. Kuali Rice Development
  2. KULRICE-8798

Look into multithreading during the view lifecycle

    Details

    • Type: Task
    • Status: Closed
    • Priority: Major
    • Resolution: Complete
    • Affects Version/s: None
    • Fix Version/s: 2.4
    • Security Level: Public (Public: Anyone can view)
    • Labels:
      None
    • 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

        Attachments

          Issue Links

            Activity

            Hide
            mwfyffe 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
            mwfyffe 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
            jkneal 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
            jkneal 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
            mwfyffe 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
            mwfyffe 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
            mwfyffe 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
            mwfyffe 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
            mwfyffe 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
            mwfyffe 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:
                mwfyffe Mark Fyffe (Inactive)
                Reporter:
                jkneal 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