Performance of Workflow Event Handlers

itGumby · August 13, 2018, 10:39pm

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?

ThoLe · August 14, 2018, 2:28am

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 ?

jasper.floor · August 14, 2018, 8:25am

Hi,

please see:

This should provide some insight into what is happening.

machak · August 14, 2018, 8:44am

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?

ThoLe · August 14, 2018, 9:01am

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.

itGumby · August 14, 2018, 8:49pm

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

itGumby · August 15, 2018, 3:55pm

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.

ThoLe · August 16, 2018, 4:10am

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

jasper.floor · August 16, 2018, 8:36am

Please turn on diagnostics.

itGumby · August 16, 2018, 1:17pm

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

itGumby · August 16, 2018, 1:19pm

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.

machak · August 16, 2018, 1:35pm

“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.

ThoLe · August 16, 2018, 1:48pm

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

machak · August 16, 2018, 2:02pm

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

jasper.floor · August 16, 2018, 2:15pm

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.

ThoLe · August 16, 2018, 2:16pm

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.

itGumby · August 23, 2018, 3:15pm

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.

itGumby · August 23, 2018, 3:28pm

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.

woonsanko · August 23, 2018, 6:02pm

itGumby:

  |  |- 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)}

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

Topic		Replies	Views
Document workflow events in CMS get triggered with a delay causing issues with event listener implementation	0	307	August 24, 2022
Updating documents using data from a third-party API Experience Manager (PaaS/OnPrem)	3	490	March 25, 2019
Lost scheduled trigger requests Experience Manager (PaaS/OnPrem)	12	1271	July 25, 2018
Issue to update the document property through program Experience Manager (PaaS/OnPrem)	5	628	November 28, 2019
Junit for eventhandler (HippoWorkflowEvent) Experience Manager (PaaS/OnPrem)	2	496	August 14, 2018

Performance of Workflow Event Handlers

Related topics