Debug Phase Listener Timer

This listener will log on the server time spent for each JSF phase processing.

This listener is not thread-safe: timing will be meaningful only in a controlled environment (e.g. only one user displaying pages of a given application)

To activate it, add the following configuration to the $SERVER/lib/log4j.xml configuration:

<category name="org.nuxeo.ecm.platform.ui.web.rest.JSFDebugPhaseListener">
  <priority value="DEBUG" />
</category>

Sample output:

18:16:21,457 DEBUG [JSFDebugPhaseListener] RESTORE_VIEW 1: 60 ms
18:16:25,030 DEBUG [JSFDebugPhaseListener] RENDER_RESPONSE 6: 3378 ms

JSF Tags and Layout/Widget Timer

Some additional timers have been defined on Nuxeo custom tags and tag handlers. This can help understanding which parts of a given page are heavy to process and render.

Tags are included inside each other: a given tag timing will show this tag processing timing, added to all of its children tags timings.

To activate it, add the following configuration to the $SERVER/lib/log4j.xml configuration:

<category name="org.nuxeo.ecm.platform.ui.web.util.FaceletDebugTracer">
  <priority value="DEBUG" />
</category>

Also, you have to specify some minimal threshold for this timer to show a log on the server, so that it is easier to show debug logs for the slowest rendering. The following contribution, named enable-debug-jsf-tags-config.xml, can be placed inside the $SERVER/nxserver/config directory:

<?xml version="1.0"?>
<component name="org.nuxeo.ecm.platform.enable.jsf.debug.tags.config">

  <require>org.nuxeo.ecm.platform.ui.web.configuration.default</require>

  <extension target="org.nuxeo.runtime.ConfigurationService"
    point="configuration">
    <property name="nuxeo.jsf.debug.log_min_duration_ms">20</property>
  </extension>

</component>

This will log only rendering that take more than 20 milliseconds.

Sample output:

8:16:23,490 DEBUG [FaceletDebugTracer] 'alias' at '/incl/action/generic_mode_action_template.xhtml @58,31 <nxl:widgetType>' took: 53 ms.
18:16:23,490 DEBUG [FaceletDebugTracer] 'defActionWidgetName' at '/incl/action/generic_mode_action_template.xhtml @22,116 <nxu:set>' took: 54 ms.
18:16:23,492 DEBUG [FaceletDebugTracer] 'nxuRepeat_items' at '/widgets/actions/actions_widget_template.xhtml @150,66 <nxu:repeat>' took: 152 ms.
18:16:23,492 DEBUG [FaceletDebugTracer] 'clickedActionId' at '/widgets/actions/actions_widget_template.xhtml @26,27 <nxu:valueHolder>' took: 170 ms.
18:16:23,492 DEBUG [FaceletDebugTracer] 'actionStyleClass' at '/widgets/actions/actions_widget_template.xhtml @14,16 <nxu:set>' took: 170 ms.
18:16:23,492 DEBUG [FaceletDebugTracer] 'actionContextDocument' at '/widgets/actions/document_actions_with_forms_widget_template.xhtml @11,16

Note that the timer is displayed after the rendering: included tags timings are printed before their parents.

Action Service Timers

Slow page rendering can be linked to heavy filtering processing on actions and/or linked filters.

To activate it, add the following configuration to the $SERVER/lib/log4j.xml configuration:

<category name="org.nuxeo.ecm.platform.actions.ActionService">
  <priority value="DEBUG" />
</category>

Also, you have to specify some minimal threshold for this timer to show a log on the server, so that it is easier to show debug logs for the slowest rendering. The following contribution, named enable-debug-jsf-actions-config.xml, can be placed inside the $SERVER/nxserver/config directory:

<?xml version="1.0"?>
<component name="org.nuxeo.ecm.platform.enable.jsf.debug.actions.config">

  <require>org.nuxeo.ecm.platform.actions.ActionService.properties</require>

  <extension target="org.nuxeo.runtime.ConfigurationService"
    point="configuration">
    <property name="nuxeo.actions.debug.log_min_duration_ms">5</property>
  </extension>

</component>

This will log only rendering that take more than 5 milliseconds.

Sample output:

8:16:23,159 DEBUG [ActionService] Resolving actions for category 'LIVEEDIT_CREATE_ACTIONS' took: 6.30 ms
18:16:23,222 DEBUG [FaceletDebugTracer] '[document_header]' at '/view_documents.xhtml @25,36 <nxl:documentLayout>' took: 26 ms.
18:16:23,243 DEBUG [ActionService] Resolving filters [canRemoveFromFavorites] took: 10.55 ms
18:16:23,258 DEBUG [ActionService] Resolving filters [mutable_document, can_lock] took: 15.02 ms
18:16:23,267 DEBUG [ActionService] Resolving filters [hasNoSubscriptions, canSubscribe, isNotVersion] took: 7.80 ms
18:16:23,288 DEBUG [ActionService] Resolving filters [view_preview, not_folder, not_anonymous] took: 18.47 ms
18:16:23,321 DEBUG [ActionService] Resolving filters [hasVisibleRenditions] took: 33.26 ms
18:16:23,321 DEBUG [ActionService] Resolving actions for category 'DOCUMENT_UPPER_ACTION' took: 90.95 ms