Performance of Workflow Event Handlers

We implemented a Workflow Event handler per https://www.onehippo.org/library/concepts/workflow/workflow-events.html While it appears to work fine on localhost, when we place it on a remote server, the authoring experience is extremely poor (blue waiting indicator in top left spinning for a long time, potentially never returning without a page refresh).

  • narrowing down the HippoWorkflowEvent to narrow actions, such as commitEditableInstance
  • logging ellapsed duration around sections of my workflow handler code
  • browser network tracing of XHR requests: IBehaviorListener sometimes returns XML (potentially with JavaScript to evaluate), other times JSON. the one returning the main wicket can take 500ms, but
  • Not sure what is causing the waiting indicator to change state…
  • It might be that loading the CKEDITOR for document HTML is causing the delay, but my event handler doesn’t deal with any HTML fields.
  • Edit performance problems are limited to the document type with my event handler - editing other documents does not exhibit performance problems.

I am running out of options for discovering what is causing the performance issues. What recommended approaches are there to identifying and resolving performance issues in classes that implement DaemonModule? Or are there other things that can affect performance of editing documents?

I think you must first make sure the performance issue is related to your workflow handler or not. Try to put some logging in the handler to see if it completed or not while the waiting indicator is running. More than that, you can even disable the handler to make sure.
According to my experience, each time user do action with `HippoWorkflowEvent’, JCR will try to hold both lock on write and read of the current working space. And if your production database is large, this process can take time. In that case, can you show us the size of your hippo table ?

Hi,

please see:

This should provide some insight into what is happening.

As far as I know, events are not connected to your current action, as those are async and run in a separate thread. What are you doing in your daemon module?

That is true that the handler run in separated thread. So I am thinking your Hippo CMS the commit action basically slow instead of the handler.

just implemented Workflow Events per https://www.onehippo.org/library/concepts/workflow/workflow-events.html

It is possible that the cause of CMS performance issues may not be the event handler. Document creation also has a habit of getting “stuck” in the CMS ui.

How long does it take for the creation action ? and how big your database is ?

Please turn on diagnostics.

Turned diagnostics on, but got feedback from other Bloomreach people that Workflow Events are discouraged. Too bad they documented that approach.

I have no way to get the real size of any tables - it is hosted on Hippo’s infrastructure.

The full production set has approximately 40k articles. However, the are groupped by YYYY/MM folders to limit the number of articles per folder.

And even after deleting all but 1000 articles in a dev environment, I still experience performance issues.

“Workflow Events are discouraged”

who are those people and what are you actually trying to achieve.
We use workflow events throughout our system and bunch of plugins without any problems.

1 Like

You may try to adjust your AccessManager a bit, modify your repository.xml
<Security appName=“Jackrabbit”>
<SecurityManager class=“org.hippoecm.repository.security.SecurityManager”/>
<AccessManager class=“org.hippoecm.repository.security.YourNewAccessManager”/>
<LoginModule class=“org.hippoecm.repository.security.HippoLoginModule”/>
</Security>

In YourNewAccessManager, extends the canRead() method can help, it help us reduce the edit time by 10 times. Debug the code HippoAccessManager.class a bit you may find the way

@ThoLe suggesting to remove security layer is quite bad advice.

Could you share the log with the diagnostics? If you don’t want to do this on a public forum you can also file a formal support request.

I am not about remove the security layer, but after profiling the code in our system I found it is not really affect so we have some update on it and it worked at least on our system.

Thanks for input. The diagnostics was especially helpful. It turns out the performance on servers had degraded prior to workflows - the base document shows front-end lockup on document creation even without and workflow event handlers or derived-data-functions.

My document type has 13 properties + 5 child nodes with another 17 or so properties. Some of the properties are multi-value.

  • 11 of the properties come from value lists
  • 1 multi-value property comes from a custom ValueListProvider
  • 1 multi-value property comes from the related articles plugin

I think I need to research which of these is slowing down editing the article document.

I will attempt to attach some of the diagnostics output later if anyone wants to suggest/prioritize the source of the slowness.

Trimmed down diagnostics log of article creation + reload page since it locked up the cms UI:
Tailing hippo-cms.log
23.08.2018 09:21:08 [Thread-31] WARN [org.onehippo.forge.logviewer.pages.Tail.appendLine():142] IOException ‘ClientAbortException:java.io.IOException: Broken pipe’ while tailing, stopping tail on hippo-cms.log
23.08.2018 09:21:12 [catalina-exec-6] INFO [org.hippoecm.frontend.diagnosis.DiagnosticsRequestCycleListener.onEndRequest():72] Diagnosis Summary:
- cms (1376ms): {request=?1-1.IBehaviorListener.0-root-tabs-panel~container-cards-2-panel-left-sections-list-1-section~view-extension.tree-tree-i-19-contextLink&_=1535037644748}
|- PluginContext.start (956ms): {pluginClass=org.hippoecm.frontend.plugins.standardworkflow.FolderWorkflowPlugin, pluginConfig=home.cluster.cms-static.plugin.navigator.cluster.cms-browser.plugin.documentsTreeLoader.cluster.documents.plugin.documentsBrowser.cluster.frontend_renderer.plugin.standard}
| |- query (52ms): {statement=/jcr:root/hippo:configuration/hippo:queries/hippo:templates/new-efc-article-folder/hippostd:templates/node()}
| |- query (862ms): {statement=//element(,hipposysedit:namespacefolder)/element(,mix:referenceable)/element(*,hipposysedit:templatetype)/hipposysedit:prototypes/element(hipposysedit:prototype,dhiefc:article)}

23.08.2018 09:21:12 [catalina-exec-6] INFO  [org.hippoecm.frontend.diagnosis.DiagnosticsRequestCycleListener.onEndRequest():72] Diagnosis Summary:
- cms (1376ms): {request=?1-1.IBehaviorListener.0-root-tabs-panel~container-cards-2-panel-left-sections-list-1-section~view-extension.tree-tree-i-19-contextLink&_=1535037644748}
  |- PluginContext.start (956ms): {pluginClass=org.hippoecm.frontend.plugins.standardworkflow.FolderWorkflowPlugin, pluginConfig=home.cluster.cms-static.plugin.navigator.cluster.cms-browser.plugin.documentsTreeLoader.cluster.documents.plugin.documentsBrowser.cluster.frontend_renderer.plugin.standard}
  |  |- query (52ms): {statement=/jcr:root/hippo:configuration/hippo:queries/hippo:templates/new-efc-article-folder/hippostd:templates/node()}
  |  |- query (862ms): {statement=//element(*,hipposysedit:namespacefolder)/element(*,mix:referenceable)/element(*,hipposysedit:templatetype)/hipposysedit:prototypes/element(hipposysedit:prototype,dhiefc:article)}

<<keepalive(1)>>
23.08.2018 09:21:31 [catalina-exec-19] INFO  [org.hippoecm.frontend.diagnosis.DiagnosticsRequestCycleListener.onEndRequest():72] Diagnosis Summary:
- cms (1105ms): {request=?1-1.IBehaviorListener.0-dialog-content-form-buttons-0-button}
  |- PluginContext.start (126ms): {pluginClass=org.hippoecm.frontend.editor.editor.EditorPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin}
  |  `- PluginContext.connect (126ms): {pluginClass=org.hippoecm.frontend.editor.editor.EditorPlugin}
  |     `- EditorPlugin.onStart (126ms): {editorModelType=dhiefc:article, editorModelPath=/content/documents/efinancial-careers/english/articles/2018/08/diagnostics-august-23/diagnostics-august-23}
  |        |- PluginContext.start (54ms): {pluginClass=org.onehippo.forge.relateddocs.editor.RelatedDocsPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.relateddocs}
  |- PluginPage.processEvents (73ms): {}
  |- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.editor.AbstractCmsEditor$EditorWrapper, pluginConfig=null}
  |  `- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.EditPerspective, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editPerspective}
  |     |- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.editor.editor.EditorPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin}
  |     |  `- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.plugin.impl.PluginFactory$LayoutPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.root}
  |     |     |- AbstractRenderService.onBeforeRender (75ms): {pluginClass=org.hippoecm.frontend.service.render.ListViewPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.tabMain}
  |     |     |  |- AbstractRenderService.onBeforeRender (60ms): {pluginClass=org.onehippo.forge.relateddocs.editor.RelatedDocsSuggestPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.relateddocssuggest}
  |     |     |- AbstractRenderService.onBeforeRender (203ms): {pluginClass=org.hippoecm.frontend.service.render.ListViewPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.tabAnalytics}
  |     |     |  `- AbstractRenderService.onBeforeRender (134ms): {pluginClass=org.hippoecm.frontend.editor.plugins.field.NodeFieldPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.analytics}
  |     |     |     `- AbstractRenderService.onBeforeRender (134ms): {pluginClass=org.hippoecm.frontend.service.render.ListViewPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.analytics.cluster._default_.plugin.root}
  |     |     |        |- PluginContext.start (82ms): {pluginClass=org.onehippo.forge.selection.frontend.plugin.DynamicDropdownPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.analytics.cluster._default_.plugin.location.cluster._default_.plugin.root}
  |     |     |        |  |- query (79ms): {statement=//element(*,hippotranslation:translated)[hippotranslation:id = 'deda2575-c081-429f-b3db-86dad3c4051c' and hippotranslation:locale = 'en_GB']}

23.08.2018 09:21:31 [catalina-exec-19] INFO  [org.hippoecm.frontend.diagnosis.DiagnosticsRequestCycleListener.onEndRequest():72] Diagnosis Summary:
- cms (1105ms): {request=?1-1.IBehaviorListener.0-dialog-content-form-buttons-0-button}
  |- PluginContext.start (126ms): {pluginClass=org.hippoecm.frontend.editor.editor.EditorPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin}
  |  `- PluginContext.connect (126ms): {pluginClass=org.hippoecm.frontend.editor.editor.EditorPlugin}
  |     `- EditorPlugin.onStart (126ms): {editorModelType=dhiefc:article, editorModelPath=/content/documents/efinancial-careers/english/articles/2018/08/diagnostics-august-23/diagnostics-august-23}
  |        |- PluginContext.start (54ms): {pluginClass=org.onehippo.forge.relateddocs.editor.RelatedDocsPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.relateddocs}
  |- PluginPage.processEvents (73ms): {}
  |- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.editor.AbstractCmsEditor$EditorWrapper, pluginConfig=null}
  |  `- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.EditPerspective, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editPerspective}
  |     |- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.editor.editor.EditorPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin}
  |     |  `- AbstractRenderService.onBeforeRender (303ms): {pluginClass=org.hippoecm.frontend.plugin.impl.PluginFactory$LayoutPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.root}
  |     |     |- AbstractRenderService.onBeforeRender (75ms): {pluginClass=org.hippoecm.frontend.service.render.ListViewPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.tabMain}
  |     |     |  |- AbstractRenderService.onBeforeRender (60ms): {pluginClass=org.onehippo.forge.relateddocs.editor.RelatedDocsSuggestPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.relateddocssuggest}
  |     |     |- AbstractRenderService.onBeforeRender (203ms): {pluginClass=org.hippoecm.frontend.service.render.ListViewPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.tabAnalytics}
  |     |     |  `- AbstractRenderService.onBeforeRender (134ms): {pluginClass=org.hippoecm.frontend.editor.plugins.field.NodeFieldPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.analytics}
  |     |     |     `- AbstractRenderService.onBeforeRender (134ms): {pluginClass=org.hippoecm.frontend.service.render.ListViewPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.analytics.cluster._default_.plugin.root}
  |     |     |        |- PluginContext.start (82ms): {pluginClass=org.onehippo.forge.selection.frontend.plugin.DynamicDropdownPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory.cluster.cms-editor.plugin.editorPlugin.cluster._default_.plugin.analytics.cluster._default_.plugin.location.cluster._default_.plugin.root}
  |     |     |        |  |- query (79ms): {statement=//element(*,hippotranslation:translated)[hippotranslation:id = 'deda2575-c081-429f-b3db-86dad3c4051c' and hippotranslation:locale = 'en_GB']}

<<keepalive(2)>>
23.08.2018 09:21:40 [catalina-exec-4] INFO  [org.apache.jackrabbit.core.persistence.bundle.AbstractBundlePersistenceManager.logCacheStats():872] cachename=defaultBundleCache[ConcurrentCache@17b5088e], elements=17670, usedmemorykb=82942, maxmemorykb=262144, access=159639, miss=17670
23.08.2018 09:21:40 [catalina-exec-4] INFO  [org.apache.jackrabbit.core.persistence.bundle.AbstractBundlePersistenceManager.logCacheStats():872] cachename=defaultBundleCache[ConcurrentCache@17b5088e], elements=17670, usedmemorykb=82942, maxmemorykb=262144, access=159639, miss=17670
23.08.2018 09:22:38 [catalina-exec-13] DEBUG [org.hippoecm.frontend.diagnosis.DiagnosticsRequestCycleListener.onEndRequest():69] Skipping task 'cms' because took only '0' ms.

I guess you can find the second xpath query statement configuration somewhere like at /hippo:configuration/hippo:queries/hippo:templates/new-dhiefc-article/@jcr:statement.
Not sure, but if the second query helps it take that long, could you perhaps give a try after changing it to this?

/jcr:root/hippo:namespaces/dhiefc/article/hipposysedit:prototypes/hipposysedit:prototype[@jcr:primaryType='dhiefc:article']

I’m just wondering if a simpler query statement could help…

Regards,

Woonsan