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 byTask objects, where aTask is a composite structure that can have childTasks and a parentTask. 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 aTask cannot exceed the time spent on theTask. Thus above, the sum of time spent in bothsubtask Bar andsubtask 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 andMount 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 singledoBeforeRender/doAction/doBeforeServeResource
• HstQuery : Time taken for a query
• Dispatcher : Time taken for rendering a jsp or freemarker template

The default availableDiagnosticReportingValve logs its reporting info to the normalsite.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 theHstQuery 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, theDiagnosticReportingValve, will start logging page diagnostics atINFO level. To see the logs, set the log level oforg.hippoecm.hst.core.container.DiagnosticReportingValve toINFO or lower. By default, projects created using the Hippo Maven archetype will already havelog4j configured with:

<!-- DiagnosticReportingValve only logs when diagnostics enabled in hst:hosts config in repo hence     can be here on level 'info' --><Logger name="org.hippoecm.hst.core.container.DiagnosticReportingValve" level="info"/>

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 configuredepth = 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 activeTask. Adding aTask is very simple and can best be shown in code as follows:

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

@Overridepublic 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:

@Overridepublic void doBeforeRender(HstRequest request, HstResponse response)                                          throws HstComponentException {    try (Task queryTask = HDC.getCurrentTask().startSubtask("Traverse All Beans")) {        HippoBean rootBean = getSiteContentBaseBean(request);        traverseAllBeans(rootBean);    }}

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

private void traverseAllBeans(HippoBean bean) {    // ...    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 viaAOP based Spring configuration. For this, see a good example athttps://github.com/bloomreach/brxm/blob/brxm-14.7.3/site-toolkit/components/core/src/main/resources/org/hippoecm/hst/site/container/SpringComponentManager-trace.xml.

Custom diagnostics valve

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

<bean parent="abstractValve"     ></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}