HST Page Diagnostics / Reporting

HST has built-in (extensible) support for page diagnostics / reporting. The default out of the box diagnostics prints how long in milliseconds different parts of the HST request cycle took to execute. It can be switched on and off in development, test, acceptance or production environment, and also can be configured to only be invoked for requests from specific client IP addresses in order to avoid too much logging in a production environment when diagnostics are switched on. The diagnostics in HST during a request are held by Task objects, where a Task is a composite structure that can have child Tasks and a parent Task. The child tasks (subtasks) of a task are logged hierarchically indented below the parent task, by default. Thus for example, you will see output like this:

- Foo (50ms): {extra info about task 'Foo'}
    |-subtask Bar (5ms) :  {extra info about task 'Bar'}
    `-subtask Lux (42ms) :   {extra info about task 'Lux'}
            |- subsubtask subLux1 (30ms) :  {extra info about task 'subLux1'}
            ` subsubtask subLux2  (10ms) :  {extra info about task 'subLux2'}

Note that all the times accumulated of direct child tasks of a Task cannot exceed the time spent on the Task. Thus above, the sum of time spent in both subtask Bar and subtask Lux cannot exceed the time spent in the parent task, Foo.

Out of the box, the HST supports diagnostics for the following tasks.

• HstFilter : Normally the same as the total time spend for an HST request
• Host and Mount Matching : Time taken for matching the correct mount
• Sitemap Matching : Time taken for sitemap item matching
• Pipeline processing : Total processing time of all valves
• HstComponentInvokerProfiler : Time taken for a single doBeforeRender/ doAction/ doBeforeServeResource
• HstQuery : Time taken for a query
• Dispatcher : Time taken for rendering a jsp or freemarker template

The default available DiagnosticReportingValve logs its reporting info to the normal hippo-site.log file. An example of the Gogreen homepage diagnostics is added at the end of this page. In there, you can see the hierarchical output of how long different parts of the request took. For the HstQuery task also the query that was executed is logged.

Switching on/off Diagnostics

By default, page diagnostics in the HST is switched off. Switching it on is as simple as adding the property (or setting) hst:diagnosticsenabled = true at /hst:hst/hst:hosts :

+ hst:hst
    + hst:hosts
        - hst:diagnosticsenabled = true

When the property is not present, diagnostics are turned off. Once switched on, the last valve in the HST clean up valve, the DiagnosticReportingValve, will start logging page diagnostics at INFO level. To see the logs, you need to set the log level of org.hippoecm.hst.core.container. DiagnosticReportingValve to INFO or lower. By default, the 7.8 archetype however will already have log4j configured with:

<!-- DiagnosticReportingValve only logs when diagnostics enabled in hst:hosts
     config in repo hence can be here on level 'info' -->
<logger additivity="false"
        name="org.hippoecm.hst.core.container.DiagnosticReportingValve">
    <level value="info"/>
    <appender-ref ref="site"/>
    <appender-ref ref="console"/>
</logger>

For projects created with older archetypes, adding the above <logger> to the log4j configuration is enough.

Diagnostics for certain client IP address(es) only

If you want to diagnose certain pages in a production environment, sometimes it might be undesirable to have diagnostic logging enabled for every visitor. In that case, you can also give a multi-valued property, hst:diagnosticsforips, that contains client IP address(es) for which diagnostics should be logged.

+ hst:hst
    + hst:hosts
        -hst:diagnosticsenabled = true
        -hst:diagnosticsforips = {10.10.100.139, 10.10.100.140}

Only log diagnostics if some threshold is exceeded

If you only want to log those request that take more than, say, 1 second the process, you can configure a threshold in milliseconds for this. If you set

+ hst:hst
    + hst:hosts
        -hst:diagnosticsenabled = true
        -hst:diagnosticsthresholdmillisec = 1000

then only when the request took more than 1 second, it will be logged.

Only log the Tasks until some depth

To avoid diagnostics logs to grow too fast, you can configure to only log the task hierarchy until some depth. If you have not configured a depth, the entire Task hiearchy will be logged. If you configure depth = 0, only the root task is logged, depth = 1 logs the root task and its direct children, etc.  Logging the root task + direct children would for example be achieved as follows:

+ hst:hst
    + hst:hosts
        -hst:diagnosticsenabled = true
        -hst:diagnosticsdepth = 1

Only log the Tasks which exceed some threshold

If you only want to log those tasks which take at least a certain amount of time (to avoid many 0 ms tasks to be logged), you can configure hst:diagnosticsunitthresholdmillisec . If configured and bigger than 0, only tasks that take longer than diagnosticsunitthresholdmillisec will be present in the outputted log. For example

+ hst:hst
    + hst:hosts
        -hst:diagnosticsenabled = true
        -hst:diagnosticsunitthresholdmillisec = 1

Customizing Diagnostics

Adding own Tasks

You can add your own diagnostics tasks very easily. They will be automatically hierarchically nested below the current active Task. Adding a Task is very simple and can best be shown in code as follows:

Assume you have the following code in your HstComponent of which you expect that it can be expensive:

@Override
public void doBeforeRender(HstRequest request, HstResponse response)
                                           throws HstComponentException {
    HippoBean rootBean = getSiteContentBaseBean(request);
    traverseAllBeans(rootBean);
}

traverseAllBeans sounds expensive Changing the above to include a page diagnostics Task only takes:

@Override
public void doBeforeRender(HstRequest request, HstResponse response)
                                          throws HstComponentException {
    Task queryTask = null;
    try {
        if (HDC.isStarted()) {
            queryTask =
               HDC.getCurrentTask().startSubtask("Traverse All Beans");
        }
        HippoBean rootBean = getSiteContentBaseBean(request);
        traverseAllBeans(rootBean);
    } finally {
        if (queryTask != null) {
            queryTask.stop();
        }
    }
}

Now, assume that for every iteration in the recursive traverseAllBeans method you'd also like to update some extra information (see gogreen example below the HippoBeanIterationCount) in the "Traverse All Beans" task, you can to traverseAllBeans method add something like:

private void traverseAllBeans(HippoBean bean) {
    // some code etc etc
    if (HDC.isStarted()) {
        AtomicInteger iterCount = (AtomicInteger) HDC.getCurrentTask()
                                  .getAttribute("HippoBeanIterationCount");
        if (iterCount == null) {
            HDC.getCurrentTask().setAttribute("HippoBeanIterationCount",
                                               new AtomicInteger(1));
        } else {
             iterCount.incrementAndGet();
        }
    }
    for (.....) {
        traverseAllBeans(childBean);
    }
}

You can also add your own Task via AOP based Spring configuration. For this, see a good example at https://code.onehippo.org/cms-community/hippo-site-toolkit/blob/hst-4.2.6/components/core/src/main/resources/org/hippoecm/hst/site/container/SpringComponentManager-trace.xml

Custom diagnostics valve

By default, the HST ships with a DiagnosticReportingValve that prints the diagnostics to hippo-site.log in the format as shown at the end of this page. If you want a different logging style, expose it as JMX beans, write it to a database or whatever, you can hook in your own diagnostics reporting valve. You can do this by overriding the diagnosticReportingValve as show below in your hst-assembly.overrides.

<bean id="diagnosticReportingValve" parent="abstractValve"
      class="org.hippoecm.hst.core.container.DiagnosticReportingValve">
</bean>

Example output

03.12.2012 14:40:46 INFO  [org.hippoecm.hst.core.container.DiagnosticReportingValve.logDiagnosticSummary():52] Diagnostic Summary:
- HstFilter (124ms): {hostName=www.demo.test.onehippo.com, uri=/site/, query=null}
  |- Host and Mount Matching (0ms): {}
  |- Sitemap Matching (0ms): {}
  `- Pipeline processing (124ms): {pipeline=null}
     |- Targeting update valve (4ms): {}
     |- HstComponentInvokerProfiler (4ms): {method=doBeforeRender, window=homepage, component=com.onehippo.gogreen.components.DefaultPageComponent, ref=r46}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=main, component=com.onehippo.gogreen.components.BaseComponent, ref=r46_r1}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=home-boxes-left, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r1}
     |- HstComponentInvokerProfiler (4ms): {method=doBeforeRender, window=latestjobs, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r1_r1, HippoBeanIterationCount=1}
     |  `- HstQuery (4ms): {query=//*[(@hippo:paths='a5a24dd3-04a0-4ed1-a59a-ffc960ae69f2') and (@hippo:availability='live') and not(@jcr:primaryType='nt:frozenNode') and ((@jcr:primaryType='hippogogreen:job'))] order by @hippogogreen:closingdate descending}
     |- HstComponentInvokerProfiler (8ms): {method=doBeforeRender, window=latestcomments, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r1_r2, HippoBeanIterationCount=1}
     |  `- HstQuery (8ms): {query=//*[(@hippo:paths='a9868436-8f6a-4da0-9b67-7eb6e013c885') and (@hippo:availability='live') and not(@jcr:primaryType='nt:frozenNode') and ((@jcr:primaryType='hippogogreen:comment'))] order by @hippostdpubwf:lastModificationDate descending}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=home-boxes-right, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r2}
     |- HstComponentInvokerProfiler (4ms): {method=doBeforeRender, window=latestevents, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r2_r2, HippoBeanIterationCount=1}
     |  `- HstQuery (4ms): {query=//*[(@hippo:paths='392850eb-ba46-472f-a1d5-e69aeccfb65d') and (@hippo:availability='live') and not(@jcr:primaryType='nt:frozenNode') and (@hippogogreen:date >= xs:dateTime('2012-12-03T14:40:46.638+01:00')) and ((@jcr:primaryType='hippogogreen:event'))] order by @hippogogreen:closingdate ascending}
     |- HstComponentInvokerProfiler (8ms): {method=doBeforeRender, window=latestreviews, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r2_r3, HippoBeanIterationCount=1}
     |  `- HstQuery (8ms): {query=//*[(@hippo:paths='6896b028-bfaf-48fd-bd35-6fe38cea758b') and (@hippo:availability='live') and not(@jcr:primaryType='nt:frozenNode') and ((@jcr:primaryType='hippogogreen:review'))] order by @hippogogreen:closingdate descending}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=home-boxes-promo, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r3}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=banner, component=com.onehippo.gogreen.components.common.Banner, ref=r46_r1_r3_r1}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=home-banner, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r4}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=bannercarousel, component=com.onehippo.gogreen.components.common.BannerCarousel, ref=r46_r1_r4_r1}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=home-boxes-intro, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r5}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=banner, component=com.onehippo.gogreen.components.common.Banner, ref=r46_r1_r5_r1}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=featuredproducts, component=com.onehippo.gogreen.components.products.FeaturedProducts, ref=r46_r1_r5_r2}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=body, component=org.hippoecm.hst.core.component.GenericHstComponent, ref=r46_r2}
     |- HstComponentInvokerProfiler (4ms): {method=doBeforeRender, window=header, component=com.onehippo.gogreen.components.common.WebsiteLogo, ref=r46_r3}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=topnav, component=org.hippoecm.hst.core.component.GenericHstComponent, ref=r46_r3_r1}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=search, component=org.hippoecm.hst.core.component.GenericHstComponent, ref=r46_r3_r2}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=mainnavigation, component=com.onehippo.gogreen.components.common.SiteMenu, ref=r46_r3_r3}
     |- HstComponentInvokerProfiler (4ms): {method=doBeforeRender, window=langnavigation, component=com.onehippo.gogreen.components.common.LanguageComponent, ref=r46_r3_r4}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=login, component=com.onehippo.gogreen.components.common.Login, ref=r46_r3_r5}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=footer, component=com.onehippo.gogreen.components.FooterComponent, ref=r46_r4}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=service, component=com.onehippo.gogreen.components.common.SiteMenu, ref=r46_r4_r1}
     |- HstComponentInvokerProfiler (0ms): {method=doBeforeRender, window=sections, component=com.onehippo.gogreen.components.common.SiteMenu, ref=r46_r4_r2}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=sections, component=com.onehippo.gogreen.components.common.SiteMenu, ref=r46_r4_r2}
     |  `- Dispatcher (4ms): {dispatch=/WEB-INF/jsp/standard/footer/menu.jsp}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=service, component=com.onehippo.gogreen.components.common.SiteMenu, ref=r46_r4_r1}
     |  `- Dispatcher (4ms): {dispatch=/WEB-INF/jsp/standard/footer/menu.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=footer, component=com.onehippo.gogreen.components.FooterComponent, ref=r46_r4}
     |  `- Dispatcher (0ms): {dispatch=/WEB-INF/jsp/standard/footer/footer.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=login, component=com.onehippo.gogreen.components.common.Login, ref=r46_r3_r5}
     |  `- Dispatcher (0ms): {dispatch=/WEB-INF/jsp/standard/header/login.jsp}
     |- HstComponentInvokerProfiler (8ms): {method=doRender, window=langnavigation, component=com.onehippo.gogreen.components.common.LanguageComponent, ref=r46_r3_r4}
     |  `- Dispatcher (8ms): {dispatch=/WEB-INF/jsp/standard/header/langnavigation.jsp}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=mainnavigation, component=com.onehippo.gogreen.components.common.SiteMenu, ref=r46_r3_r3}
     |  `- Dispatcher (4ms): {dispatch=/WEB-INF/jsp/standard/header/mainnavigation.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=search, component=org.hippoecm.hst.core.component.GenericHstComponent, ref=r46_r3_r2}
     |  `- Dispatcher (0ms): {dispatch=/WEB-INF/jsp/standard/header/search.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=topnav, component=org.hippoecm.hst.core.component.GenericHstComponent, ref=r46_r3_r1}
     |  `- Dispatcher (0ms): {dispatch=/WEB-INF/jsp/standard/header/topnav.jsp}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=header, component=com.onehippo.gogreen.components.common.WebsiteLogo, ref=r46_r3}
     |  `- Dispatcher (4ms): {dispatch=/hst:hst/hst:configurations/common/hst:templates/standard.header.ftl}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=body, component=org.hippoecm.hst.core.component.GenericHstComponent, ref=r46_r2}
     |- HstComponentInvokerProfiler (8ms): {method=doRender, window=featuredproducts, component=com.onehippo.gogreen.components.products.FeaturedProducts, ref=r46_r1_r5_r2}
     |  `- Dispatcher (8ms): {dispatch=/WEB-INF/jsp/products/featured.jsp}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=banner, component=com.onehippo.gogreen.components.common.Banner, ref=r46_r1_r5_r1}
     |  `- Dispatcher (4ms): {dispatch=/WEB-INF/jsp/common/banner.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=home-boxes-intro, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r5}
     |  `- Dispatcher (0ms): {dispatch=/org/hippoecm/hst/pagecomposer/builtin/components/vbox.ftl}
     |- HstComponentInvokerProfiler (8ms): {method=doRender, window=bannercarousel, component=com.onehippo.gogreen.components.common.BannerCarousel, ref=r46_r1_r4_r1}
     |  `- Dispatcher (8ms): {dispatch=/WEB-INF/jsp/common/bannercarousel.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=home-banner, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r4}
     |  `- Dispatcher (0ms): {dispatch=/org/hippoecm/hst/pagecomposer/builtin/components/vbox.ftl}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=banner, component=com.onehippo.gogreen.components.common.Banner, ref=r46_r1_r3_r1}
     |  `- Dispatcher (4ms): {dispatch=/WEB-INF/jsp/common/banner.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=home-boxes-promo, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r3}
     |  `- Dispatcher (0ms): {dispatch=/org/hippoecm/hst/pagecomposer/builtin/components/vbox.ftl}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=latestreviews, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r2_r3}
     |  `- Dispatcher (4ms): {dispatch=/WEB-INF/jsp/reviews/latest.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=latestevents, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r2_r2}
     |  `- Dispatcher (0ms): {dispatch=/WEB-INF/jsp/events/latest.jsp}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=home-boxes-right, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r2}
     |  `- Dispatcher (4ms): {dispatch=/org/hippoecm/hst/pagecomposer/builtin/components/vbox.ftl}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=latestcomments, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r1_r2}
     |  `- Dispatcher (0ms): {dispatch=/WEB-INF/jsp/comments/latest.jsp}
     |- HstComponentInvokerProfiler (4ms): {method=doRender, window=latestjobs, component=com.onehippo.gogreen.components.common.LatestItems, ref=r46_r1_r1_r1}
     |  `- Dispatcher (4ms): {dispatch=/WEB-INF/jsp/jobs/latest.jsp}
     |- HstComponentInvokerProfiler (0ms): {method=doRender, window=home-boxes-left, component=org.hippoecm.hst.pagecomposer.builtin.components.StandardContainerComponent, ref=r46_r1_r1}
     |  `- Dispatcher (0ms): {dispatch=/org/hippoecm/hst/pagecomposer/builtin/components/vbox.ftl}
     |- HstComponentInvokerProfiler (12ms): {method=doRender, window=main, component=com.onehippo.gogreen.components.BaseComponent, ref=r46_r1}
     |  `- Dispatcher (12ms): {dispatch=/WEB-INF/jsp/home/main.jsp}
     `- HstComponentInvokerProfiler (4ms): {method=doRender, window=homepage, component=com.onehippo.gogreen.components.DefaultPageComponent, ref=r46}
        `- Dispatcher (4ms): {dispatch=/hst:hst/hst:configurations/common/hst:templates/layout.webpage.ftl}