Simple Template Profiling

Author: feddersen
Publication Date: 9/2/2010 8:05

During your development phase, the generation time of a project usually doesn't play a big role. The project contains just a few hundred pages, maybe even less. Most template developers use a partial generation/deployment to test their changes, which completes within a few seconds.

The generation time gets more important once the launch date is approaching. More and more content is added to the project, more pages are added and the overall generation time increases. That's when the project manager comes along and assigns an "optimization task" to someone.

Lucky you! Let's gather some information about the project's generation time first:

Examine the generation log

1. Download a generation log from the server (server monitoring -> Logfiles according to deployment -> choose your project and download the log for a full generation
2. Examine the last lines of the log, they should like this:

INFO  23.08.2010 12:52:27.866 {seID=82228} (de.espirit.firstspirit.server.scheduler.GenerateTaskExecutor): finished generation of project 'Your Project Name - Your Project Description' (id=82126) - 0 fatal error(s), 0 error(s), 0 warning(s), duration 0:16:14.303
INFO  23.08.2010 12:52:27.866 {seID=82228} (de.espirit.firstspirit.server.scheduler.GenerateTaskExecutor): 12508 pages produced, ~77 ms per page
INFO  23.08.2010 12:52:27.867 {seID=82228} (de.espirit.firstspirit.server.scheduler.ScheduleManagerImpl): finished task 'generate' - schedule entry 'generate full' (id=82228)

So 12508 pages have been generated in 16 minutes and 14 seconds, averaging to a generation time of 77milliseconds per page. Not too bad, but the average generation time doesn't help us very much. There might be pages that generate within 10ms, other may take more than a second.

Insert profiling code

We're most interested in pages with a large generation time, but how to identify them? The easiest and fastest way is to insert some profiling code right into your templates. The obvious place would be your page templates, but you can use the same mechanism to profile smaller blocks of code (section templates, loops, scripts etc.).

Here's the code:

$-- insert at the very beginning of your page template, stores NOW into a variable --$
$CMS_SET(set_pt_startTime,#global.now.milliseconds)$
$--
all of your normal template code
--$
$-- enable profiling if we're in debug mode, enable debug mode with $CMS_SET(#global.debugMode, true)$ --$
$CMS_IF(#global.debugMode)$
    $CMS_SET(set_pt_bodyGenerationTime,#global.now.milliseconds - set_pt_startTime)$
    $-- log a warning if generation time is above 100ms --$
    $CMS_IF(set_pt_bodyGenerationTime > 100)$
        $CMS_VALUE(#global.logWarning("Slow generation page detected. Body of " + #global.node.getUid() + " generated in " + set_pt_bodyGenerationTime + " ms"))$
    $CMS_END_IF$
$CMS_END_IF$

A couple of notes:

• You can adjust the log level if you don't want to log a warning (list of available log methods) or extend the if statement to log warnings for very slow pages only
• It's a good idea to put the profiling snippets into format templates, so that you can reuse them in multiple templates.
• You might want to use a variable instead of a hardcoded treshold.

Re-examine the generation log

Start a complete generation and download the generation log once it's done. Scan the files for entries similar to:

WARN  24.08.2010 11:03:47.211 {seID=82232} (de.espirit.firstspirit.generate.SiteProduction): Slow generation page detected. Body of index_1 generated in 31837 ms

Since we logged the reference name (uid), you can easily jump to the page by using the "search for reference name" dialog. From there, you can use the shortcuts to jump to the page and template.

As mentioned earlier, it might be a good idea to insert additional measurements to identify the slow code block. Most of the time it's pretty obvious, but you can apply the same principle to measure the generation time for a section template or  a script.

Once you've identified the slow code, rewrite it and start all over. Saving a few milliseconds on every page can have a big impact on the overall generation time, especially in large projects.

Tags: fs4.2, generation, hint, profiling, template