Someone I know has been talking to me recently about bravely becoming the first outside user of DWiki. As part of this, I realized he might like to have practical documentation about how DWiki templates get used in practice for things like producing this blog. Which made me realize that I'd forgotten how the template flow goes.

I could have re-read the templates and traced the execution path, but then I had a bright idea: why not make the program do this for me? So I instrument template processing to dump all the templates used, properly nested to show the expansion structure.

Once I had this visualization, more questions started popping out: what work was being done by each template? How long was it taking? Augmenting the tracing to add them wasn't too hard, and somewhat to my surprised it started bringing out useful information; the performance information has been particularly useful. It's evidently one thing to profile an application, but another thing to see where in the flow of execution the time is going (instead of in the code).

Visualizing program flow this way is sort of a variant of debugging via print; instead of trying to figure out how the program got somewhere, you're interested in seeing where it went in general.

To illustrate what I'm talking about, here's an example. This is the flow of templates for the web page for a single blog entry (this one in specific):

1. dwiki.tmpl:
   1. html/dtd
   2. struct/head.tmpl: $var $var
      1. html/css: $var
      2. syndication/discovery.tmpl: atom::autodisc
      (1.3 msec for struct/head.tmpl)
   3. struct/header.tmpl:
      1. struct/breadcrumbs: breadcrumbs
      2. struct/loginstate.tmpl: $var
   4. dwiki/overrides.tmpl:
      1. Overrides/blog/all.tmpl:
         1. dwiki/standard.tmpl:
            1. views/normal-file.tmpl:
               1. wikiauth.tmpl: wikitext[4.1ms]
                  1. comment/tools.tmpl: comment::countlink Empty
                  (5.2 msec for wikiauth.tmpl)
               (5.5 msec for views/normal-file.tmpl)
            (6 msec for dwiki/standard.tmpl)
         2. Overrides/blog/sidebar.tmpl:
            1. struct/readme-dir.tmpl: inject::upreadme[9.4ms] (9.5 msec)
            search::enter (10 msec)
         (17 msec for Overrides/blog/all.tmpl)
      (18 msec for dwiki/overrides.tmpl)
   5. struct/datecrumbs.tmpl: blog::datecrumbs blog::prevnext[18ms] (18 msec)
   6. struct/bottom.tmpl:
      1. bits/pagetools.tmpl: pagetools[1.6ms] (1.7 msec)
      2. hist/locker.tmpl: hist::lockedby Empty
      3. struct/searchbox.tmpl: search::enter
      4. struct/loginbox.tmpl: auth::loginbox
      5. syndication/feeds.tmpl: atom::feeds[1ms] (1.1 msec)
      6. bits/lastmod.tmpl: lastmodified
      7. site-sig.tmpl
      (5.2 msec for struct/bottom.tmpl)
   (45 msec for dwiki.tmpl)

(Reading this and this will be helpful.)

The rough format is 'N. <template file>: <renderer> ...', interspersed with sub-templates; $var marks variable expansion, and Empty means the template ended up generating nothing (often because it wasn't applicable to the page). Times are omitted if they're less than a millisecond.

At 25 templates and 45 milliseconds, this is a fairly typical DWiki page. The sidebar means that WanderingThoughts has a more complex template cascade than ordinary pages, but frankly I like small modular templates. (A lot of them are only a line or two long.)

(And yes, I know that there are a number of inefficient bits in here. Figuring out how to speed DWiki up is on the to-do list, although I had not realized quite how time consuming the blog::prevnext renderer was before now.)