Making it easier to debug and test your templates

Sometimes there can be nothing more frustrating than trying to troubleshoot publishing performance. Often users must resort to the brute force method of debugging, such as:

• embedding print STDERR statements in Movable Type's source code - but how many people know how to do that?

• blocking out huge swaths of code using the <mt:ignore> tag to hone in on the root cause - a cumbersome and time consuming process.

• turning on performance logging - a feature whose output was intended for machines and as a result is sometimes too verbose or difficult to read by mere mortals.

To help our users find a more elegant and efficient way to debug their templates and optimize their system, we have developed a simple tool that can more quickly and effectively help users hone in on those aspects of their templates that are the bottlenecks in their publishing system. The tool is a simple command line tool that outputs four very useful things:

1. the output from the template itself - very the accuracy of the template's output yourself.

2. a table of all the template tags invoked by the template - this table not only shows the template tag name, but also the average time it took to process each one.

3. total build time and total number of queries executed - when trying to find the template at the root of your performance problem, this will help you to quickly identify the outlier.

4. a table of all the SQL statements made during the publishing process - an effective way to find the actual query that is problematic.

Check out this sample output:

<template output omitted>
Template Tag Utilization:
.----------+----------------------+--------+---------+--------+--------+-------.
| Time     | Tag                  | Calls  | Avg     | SQL    | Hits   | Miss  |
+----------+----------------------+--------+---------+--------+--------+-------+
| 0.083    | entryassets          | 20     | 0.004   | 40     | 20     | 20    |
| 0.040    | entries              | 8      | 0.005   | 12     | 16     | 4     |
| 0.027    | assetproperty        | 16     | 0.002   | 16     | 0      | 0     |
| 0.020    | include              | 6      | 0.003   | 7      | 3      | 3     |
| 0.019    | categories           | 4      | 0.005   | 5      | 20     | 5     |
| 0.014    | assetthumbnaillink   | 4      | 0.003   | 4      | 4      | 0     |
| 0.010    | keyvalues            | 4      | 0.002   | 0      | 0      | 0     |
| 0.006    | collatesetfield      | 32     | 0.000   | 0      | 0      | 0     |
| 0.004    | setvarblock          | 28     | 0.000   | 0      | 0      | 0     |
| 0.004    | gridcell             | 8      | 0.000   | 0      | 0      | 0     |
                                   -- snip--
'----------+----------------------+--------+---------+--------+--------+-------'
  Total Queries: 86
  Total Build Time: 0.261901
.------------------------------------------------------------------+-----------.
| Query                                                            | Number    |
+------------------------------------------------------------------+-----------+
| RAMCACHE_GET ?                                                   | 63        |
| RAMCACHE_ADD ?                                                   | 32        |
| SELECT asset_id FROM mt_asset, mt_objectasset WHERE (objectasse- | 20        |
| t_object_ds = ?) AND (objectasset_asset_id = asset_id) AND (obj- |           |
| ectasset_object_id = ?)                                          |           |
| SELECT asset_id, asset_blog_id, asset_class, asset_created_by, - | 20        |
| asset_created_on, asset_description, asset_file_ext, asset_file- |           |
| _name, asset_file_path, asset_label, asset_mime_type, asset_mod- |           |
| ified_by, asset_modified_on, asset_parent, asset_url FROM mt_as- |           |
| set WHERE (asset_id IN (?))                                      |           |
| SELECT asset_meta_asset_id, asset_meta_type, asset_meta_vchar, - | 20        |
| asset_meta_vchar_idx, asset_meta_vdatetime, asset_meta_vdatetim- |           |
| e_idx, asset_meta_vinteger, asset_meta_vinteger_idx, asset_meta- |           |
| _vfloat, asset_meta_vfloat_idx, asset_meta_vblob, asset_meta_vc- |           |
| lob FROM mt_asset_meta WHERE (asset_meta_asset_id = ?)           |           |
                                   -- snip--
'------------------------------------------------------------------+-----------'

Using the tool is relatively straight forward: all you need to do is give the tool the ID of the template you want to debug, in addition to any other contextual information that template might need, e.g. a category ID if you are publishing a category archive. Running the tool with the conventional --help flag will tell you all of the possible options.

• Download mt-tmpl-test now

Keep reading behind the cut to learn more specifically how to use this tool.

Example Usage

First, installation:

prompt> cp mt-tmpl-test /path/to/mt/tools

Now, how to get help:

prompt> cd /path/to/mt
prompt> perl ./tools/mt-tmpl-test --help
usage:  ./tools/mt-tmpl-test [template name]

    --blog <name>      Specify a blog context by blog ID or name.
    --template <name>  Specify a template to process by template ID or name.
    --category <label> Specify a category to process by category ID or label.
    --entry <title>    Specify an entry to process by entry ID or title.
    --author <name>    Specify an author to process by ID or username.
    --archive <type>   Specify a archive type.
    --profile          Enables SQL and template tag profiling.
    --debug <mode>     Sets MT's DebugMode.

And finally, how to actually use the tool:

prompt> perl ./tools/mt-tmpl-test --template=123 --profile
* output to appear here *