CMS Diagnostics and Reporting
Bloomreach Content includes built-in, extensible support for application diagnostics and reporting. By default, diagnostics measure and log the execution time (in milliseconds) for different stages of the CMS request cycle. You can enable or disable diagnostics in any environment (development, test, acceptance, or production). Diagnostics can also be restricted to specific client IP addresses to limit logging in production environments.
Diagnostics are managed through Task objects. Each Task can have child tasks and a parent task, forming a hierarchical structure. The diagnostics log displays this hierarchy with indentation. For example:
- cms (247ms): {request=}
|- login (30ms): {}
|- PluginPage.init (50ms): {}
| |- PluginContext.connect (0ms): {}
| |- PluginContext.newCluster (0ms): {}
| `- PluginContext.start (35ms): {pluginClass=org.hippoecm.frontend.plugins.login.SimpleLoginPlugin, pluginConfig=home.cluster.login.plugin.loginPage}
| `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.login.SimpleLoginPlugin}
|- PluginPage.onInitialize (0ms): {}
|- PluginPage.processEvents (0ms): {}
| `- PluginPage.onDetach (0ms): {}
|- PluginPage.render (0ms): {}
| `- AbstractRenderService.render (0ms): {pluginClass=org.hippoecm.frontend.plugins.login.SimpleLoginPlugin, pluginConfig=home.cluster.login.plugin.loginPage}
|- PluginPage.onBeforeRender (3ms): {}
| `- AbstractRenderService.onBeforeRender (2ms): {pluginClass=org.hippoecm.frontend.plugins.login.SimpleLoginPlugin, pluginConfig=home.cluster.login.plugin.loginPage}
|- PluginPage.renderHead (0ms): {}
|- AbstractRenderService.onAfterRender (0ms): {pluginClass=org.hippoecm.frontend.plugins.login.SimpleLoginPlugin, pluginConfig=home.cluster.login.plugin.loginPage}
`- PluginPage.onAfterRender (0ms): {}
The total time for a parent Task is always greater than or equal to the sum of its direct child tasks.
Supported Diagnostic Tasks
By default, Bloomreach Content provides diagnostics for the following tasks:
org.hippoecm.frontend.Main(viaDiagnosticsRequestCycleListener): Measures total CMS request time.org.hippoecm.repository.impl.RepositoryDecorator: Measures login duration.org.hippoecm.repository.impl.QueryDecorator: Measures query execution time.org.hippoecm.frontend.PluginPage: Measures CMS Wicket page rendering.org.hippoecm.frontend.plugin.impl.PluginContext: Tracks lifecycle management and invocation of frontend plugin components.org.hippoecm.frontend.service.render.AbtractRenderService: Measures rendering time for frontend plugin components.org.hippoecm.frontend.service.restproxy.RestProxyServicePlugin: Measures internal server-side REST Proxy Service calls.- Additional tasks as implemented.
The default DiagnosticsRequestCycleListener writes diagnostic logs to the standard cms.log file. The logs display the hierarchical breakdown of request execution time, including tasks such as JCR queries.
Enabling and Configuring Diagnostics
Diagnostics are disabled by default. To enable diagnostics, set the enabled property to true at /hippo:configuration/hippo:modules/diagnostics/hippo:moduleconfig:
/hippo:configuration: /hippo:modules: /diagnostics: /hippo:moduleconfig: enabled: true
If the enabled property is absent, diagnostics remain disabled. When enabled, DiagnosticsRequestCycleListener logs at the INFO level. To view these logs, ensure the log level for org.hippoecm.frontend.diagnosis.DiagnosticsRequestCycleListener is set to INFO or lower. Projects generated from the Maven archetype include the following default Log4j configuration:
<!-- DiagnosticsRequestCycleListener only logs when diagnostics is enabled in the repository at /hippo:configuration/hippo:modules/diagnosis hence can be here on level 'info' --> <Logger name="org.hippoecm.frontend.diagnosis.DiagnosticsRequestCycleListener" level="info"/>
Restricting Diagnostics to Specific Users or IP Addresses
To limit diagnostics logging to specific CMS users, set the multi-valued allowedUsers property:
/hippo:configuration: /hippo:modules: /diagnostics: /hippo:moduleconfig: enabled: true allowedUsers: [ "editor", "author" ]
Diagnostics will only be logged when the CMS user is "editor" or "author".
To restrict diagnostics to specific client IP addresses, use the allowedAddresses property:
/hippo:configuration: /hippo:modules: /diagnostics: /hippo:moduleconfig: enabled: true allowedAddresses: [10.10.100.139, 10.10.100.140]
Diagnostics will only be logged for requests from the specified IP addresses.
You can set both allowedUsers and allowedAddresses. In this case, both the username and IP address must match for diagnostics to be logged.
Logging Only Slow Requests
To log only requests that exceed a specific duration, set the thresholdMillisec property (value in milliseconds):
/hippo:configuration: /hippo:modules: /diagnostics: /hippo:moduleconfig: enabled: true thresholdMillisec: 1000
Only requests taking longer than 1 second (1000 milliseconds) will be logged.
Limiting Task Hierarchy Depth in Logs
To control the depth of the task hierarchy in the diagnostics log, set the depth property. If not set, the full hierarchy is logged. For example, to log only the root task and its direct children:
/hippo:configuration: /hippo:modules: /diagnostics: /hippo:moduleconfig: enabled: true depth: 1
depth: 0logs only the root task.depth: 1logs the root task and its direct children.
Logging Only Tasks Above a Time Threshold
To exclude tasks that complete very quickly, set the unitThresholdMillisec property. Only tasks exceeding this duration (in milliseconds) will appear in the log:
/hippo:configuration: /hippo:modules: /diagnostics: /hippo:moduleconfig: enabled: true unitThresholdMillisec: 1
Adding Custom Diagnostic Tasks
You can add custom diagnostic tasks in your CMS frontend plugin code. Custom tasks are automatically nested under the current active Task. For example, if you want to measure the duration of an expensive operation:
Original method:
public void doSomeExpensiveOperation(final Node node) { traverseAllDescendants(node); }
Add a diagnostic subtask:
public void doSomeExpensiveOperation(final Node node) { try (Task traverseTask = HDC.getCurrentTask().startSubtask("Traverse All Nodes")) { traverseAllNodes(node); } }
To record additional information during recursion, update the current task's attributes:
private void traverseAllNodes(final Node node) { // ... AtomicInteger iterCount = (AtomicInteger) HDC.getCurrentTask().getAttribute("nodeIterationCount"); if (iterCount == null) { HDC.getCurrentTask().setAttribute("nodeIterationCount", new AtomicInteger(1)); } else { iterCount.incrementAndGet(); } for (...) { traverseAllNodes(childNode); } }
Example Diagnostics Output
2015-11-09 13:48:04,604 INFO [http-nio-8080-exec-10] Diagnosis Summary:
- cms (7000ms): {request=}
|- PluginPage.init (4057ms): {}
| |- PluginContext.connect (0ms): {}
| |- PluginContext.newCluster (2ms): {}
| |- PluginContext.start (2202ms): {pluginClass=org.hippoecm.frontend.plugin.loader.PluginClusterLoader, pluginConfig=home.cluster.cms-static.plugin.servicesLoader}
| | `- PluginContext.connect (2200ms): {pluginClass=org.hippoecm.frontend.plugin.loader.PluginClusterLoader}
| | |- PluginContext.newCluster (1ms): {}
| | |- PluginContext.start (4ms): {pluginClass=org.hippoecm.frontend.service.preferences.PreferencesStorePlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.preferencesStoreService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.service.preferences.PreferencesStorePlugin}
| | |- PluginContext.start (2ms): {pluginClass=org.hippoecm.frontend.service.settings.SettingsStorePlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.settingsService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.service.settings.SettingsStorePlugin}
| | |- PluginContext.start (2ms): {pluginClass=org.hippoecm.frontend.service.popup.AjaxPopupService, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.ajaxPopupService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.service.popup.AjaxPopupService}
| | |- PluginContext.start (150ms): {pluginClass=org.hippoecm.frontend.service.restproxy.RestProxyServicePlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hstRestProxyService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.service.restproxy.RestProxyServicePlugin}
| | |- PluginContext.start (14ms): {pluginClass=org.hippoecm.frontend.plugins.cms.admin.password.validation.PasswordValidationServiceImpl, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.passwordValidationService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.cms.admin.password.validation.PasswordValidationServiceImpl}
| | |- PluginContext.start (4ms): {pluginClass=org.hippoecm.frontend.translation.LocaleProviderPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.localeProviderService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.translation.LocaleProviderPlugin}
| | |- PluginContext.start (10ms): {pluginClass=org.hippoecm.frontend.editor.layout.LayoutProviderPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.layoutProvider}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.editor.layout.LayoutProviderPlugin}
| | |- PluginContext.start (2ms): {pluginClass=org.hippoecm.frontend.editor.impl.DefaultEditorFactoryPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.defaultEditorFactory}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.editor.impl.DefaultEditorFactoryPlugin}
| | |- PluginContext.start (2ms): {pluginClass=org.hippoecm.frontend.plugins.reviewedactions.HippostdEditorFactoryPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hippostdEditorFactory}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.reviewedactions.HippostdEditorFactoryPlugin}
| | |- PluginContext.start (20ms): {pluginClass=org.hippoecm.frontend.plugins.richtext.htmlcleaner.HtmlCleanerPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.defaultHtmlCleanerService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.richtext.htmlcleaner.HtmlCleanerPlugin}
| | |- PluginContext.start (38ms): {pluginClass=org.hippoecm.frontend.plugins.richtext.htmlcleaner.HtmlCleanerPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.filteringHtmlCleanerService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.richtext.htmlcleaner.HtmlCleanerPlugin}
| | |- PluginContext.start (4ms): {pluginClass=org.hippoecm.frontend.plugins.standards.diff.HTMLDiffPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.htmlDiffService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.standards.diff.HTMLDiffPlugin}
| | |- PluginContext.start (9ms): {pluginClass=org.hippoecm.frontend.plugins.gallery.processor.ScalingGalleryProcessorPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.galleryProcessorService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.gallery.processor.ScalingGalleryProcessorPlugin}
| | |- PluginContext.start (3ms): {pluginClass=org.hippoecm.frontend.plugins.gallery.NullGalleryProcessorPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.assetProcessorService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.gallery.NullGalleryProcessorPlugin}
| | |- PluginContext.start (71ms): {pluginClass=org.hippoecm.frontend.plugins.yui.upload.validation.ImageUploadValidationPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.imageValidationService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.yui.upload.validation.ImageUploadValidationPlugin}
| | |- PluginContext.start (1ms): {pluginClass=org.hippoecm.frontend.plugins.yui.upload.validation.AssetUploadValidationPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.assetValidationService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.yui.upload.validation.AssetUploadValidationPlugin}
| | |- PluginContext.start (3ms): {pluginClass=org.hippoecm.frontend.translation.TreeNodeIconPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.treeNodeIconService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.translation.TreeNodeIconPlugin}
| | |- PluginContext.start (7ms): {pluginClass=org.onehippo.cms7.channelmanager.plugins.social.PopupSocialMediaService, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.popupSocialMediaService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.channelmanager.plugins.social.PopupSocialMediaService}
| | |- PluginContext.start (1777ms): {pluginClass=org.onehippo.cms7.channelmanager.service.ChannelDocumentUrlService, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.channelDocumentUrlService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.channelmanager.service.ChannelDocumentUrlService}
| | |- PluginContext.start (6ms): {pluginClass=org.hippoecm.frontend.i18n.ConfigTraversingPlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hstEditorConfigTranslator}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.i18n.ConfigTraversingPlugin}
| | |- PluginContext.start (0ms): {pluginClass=org.hippoecm.frontend.service.restproxy.RestProxyServicePlugin, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.hstIntranetRestProxyService}
| | | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.service.restproxy.RestProxyServicePlugin}
| | `- PluginContext.start (32ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.deviceskins.ClassPathDeviceService, pluginConfig=home.cluster.cms-static.plugin.servicesLoader.cluster.cms-services.plugin.defaultDeviceService}
| | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.deviceskins.ClassPathDeviceService}
| |- PluginContext.start (4ms): {pluginClass=org.hippoecm.frontend.i18n.ConfigTraversingPlugin, pluginConfig=home.cluster.cms-static.plugin.configTranslator}
| | `- PluginContext.connect (1ms): {pluginClass=org.hippoecm.frontend.i18n.ConfigTraversingPlugin}
| |- PluginContext.start (1ms): {pluginClass=org.hippoecm.frontend.i18n.SearchingTranslatorPlugin, pluginConfig=home.cluster.cms-static.plugin.searchingTranslator}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.i18n.SearchingTranslatorPlugin}
| |- PluginContext.start (51ms): {pluginClass=org.hippoecm.frontend.plugins.cms.root.RootPlugin, pluginConfig=home.cluster.cms-static.plugin.root}
| | |- query (4ms): {statement=SELECT * FROM hipposys:user WHERE fn:name()='admin'}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.cms.root.RootPlugin}
| |- PluginContext.start (13ms): {pluginClass=org.hippoecm.frontend.plugins.cms.dashboard.DashboardPerspective, pluginConfig=home.cluster.cms-static.plugin.dashboardPerspective}
| | `- PluginContext.connect (3ms): {pluginClass=org.hippoecm.frontend.plugins.cms.dashboard.DashboardPerspective}
| |- PluginContext.start (1587ms): {pluginClass=org.hippoecm.frontend.plugin.loader.PluginClusterLoader, pluginConfig=home.cluster.cms-static.plugin.channelManagerLoader}
| | `- PluginContext.connect (1587ms): {pluginClass=org.hippoecm.frontend.plugin.loader.PluginClusterLoader}
| | |- PluginContext.newCluster (1ms): {}
| | |- PluginContext.start (1539ms): {pluginClass=org.onehippo.cms7.channelmanager.ChannelManagerPerspective, pluginConfig=home.cluster.cms-static.plugin.channelManagerLoader.cluster.hippo-channel-manager.plugin.channel-manager-perspective}
| | | |- RestProxyServicePlugin (34ms): {class=org.hippoecm.hst.rest.ChannelService, method=canUserModifyChannels}
| | | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.channelmanager.ChannelManagerPerspective}
| | |- PluginContext.start (2ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.PlainPropertiesEditor, pluginConfig=home.cluster.cms-static.plugin.channelManagerLoader.cluster.hippo-channel-manager.plugin.templatecomposer-properties-editor}
| | | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.PlainPropertiesEditor}
| | |- PluginContext.start (1ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.PlainVariantAdder, pluginConfig=home.cluster.cms-static.plugin.channelManagerLoader.cluster.hippo-channel-manager.plugin.templatecomposer-variant-adder}
| | | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.PlainVariantAdder}
| | `- PluginContext.start (37ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.deviceskins.DeviceManager, pluginConfig=home.cluster.cms-static.plugin.channelManagerLoader.cluster.hippo-channel-manager.plugin.templatecomposer-device-combo}
| | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.channelmanager.templatecomposer.deviceskins.DeviceManager}
| |- PluginContext.start (14ms): {pluginClass=org.hippoecm.frontend.plugins.cms.browse.BrowserPerspective, pluginConfig=home.cluster.cms-static.plugin.browserPerspective}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.cms.browse.BrowserPerspective}
| |- PluginContext.start (25ms): {pluginClass=org.hippoecm.frontend.plugins.cms.browse.Navigator, pluginConfig=home.cluster.cms-static.plugin.navigator}
| | `- PluginContext.connect (1ms): {pluginClass=org.hippoecm.frontend.plugins.cms.browse.Navigator}
| |- PluginContext.start (3ms): {pluginClass=org.hippoecm.frontend.plugins.yui.layout.WireframePlugin, pluginConfig=home.cluster.cms-static.plugin.navigatorLayout}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.yui.layout.WireframePlugin}
| |- PluginContext.start (8ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.EditorTabsPlugin, pluginConfig=home.cluster.cms-static.plugin.tabbedEditorTabs}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.EditorTabsPlugin}
| |- PluginContext.start (5ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.EditorManagerPlugin, pluginConfig=home.cluster.cms-static.plugin.editorManagerPlugin}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.EditorManagerPlugin}
| |- PluginContext.start (11ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.AutoEditPlugin, pluginConfig=home.cluster.cms-static.plugin.autoEditPlugin}
| | `- PluginContext.connect (10ms): {pluginClass=org.hippoecm.frontend.plugins.cms.edit.AutoEditPlugin}
| | `- query (8ms): {statement=select * from hippostd:publishable where hippostd:state='draft' and hippostd:holder='admin'}
| |- PluginContext.start (5ms): {pluginClass=org.hippoecm.frontend.plugins.cms.root.ControllerPlugin, pluginConfig=home.cluster.cms-static.plugin.controllerPlugin}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.cms.root.ControllerPlugin}
| |- PluginContext.start (29ms): {pluginClass=org.onehippo.cms7.reports.ReportsPerspective, pluginConfig=home.cluster.cms-static.plugin.reportsPerspective}
| | `- PluginContext.connect (0ms): {pluginClass=org.onehippo.cms7.reports.ReportsPerspective}
| |- PluginContext.start (7ms): {pluginClass=org.hippoecm.frontend.plugins.cms.admin.AdminPerspective, pluginConfig=home.cluster.cms-static.plugin.adminLoader}
| | `- PluginContext.connect (0ms): {pluginClass=org.hippoecm.frontend.plugins.cms.admin.AdminPerspective}
| |- PluginContext.start (29ms): {pluginClass=org.hippoecm.frontend.plugin.loader.PluginClusterLoader, pluginConfig=home.cluster.cms-static.plugin.headerbarLoader}
| | `- PluginContext.connect (29ms): {pluginClass=org.hippoecm.frontend.plugin.loader.PluginClusterLoader}
| | |- PluginContext.newCluster (1ms): {}
| | |- PluginContext.start (24ms): {pluginClass=org.onehippo.cms7.autoexport.plugin.CmsAutoExportPlugin, pluginConfig=home.cluster.cms-static.plugin.headerbarLoader.cluster.cms-header-bar.plugin.autoexport}
| | | `- PluginContext.connect (1ms): {pluginClass=org.onehippo.cms7.autoexport.plugin.CmsAutoExportPlugin}
| | `
This output provides a detailed breakdown of the time spent in each part of the CMS request cycle. Use this information to identify performance bottlenecks and optimize your implementation.