== Visualizing dynamic program flow 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 /dwiki/TemplatesUsed]] 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_ ../programming/WhyPrintBasedDebugging]]; 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 ../web/RobotsTxtSurprise]] in specific): # dwiki.tmpl: ## html/dtd ## struct/head.tmpl: *$var* *$var* ### html/css: *$var* ### syndication/discovery.tmpl: atom::autodisc (1.3 msec for struct/head.tmpl) ## struct/header.tmpl: ### struct/breadcrumbs: breadcrumbs ### struct/loginstate.tmpl: *$var* ## dwiki/overrides.tmpl: ### Overrides/blog/all.tmpl: #### dwiki/standard.tmpl: ##### views/normal-file.tmpl: ###### wikiauth.tmpl: wikitext[4.1ms] ####### 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) #### Overrides/blog/sidebar.tmpl: ##### 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) ## struct/datecrumbs.tmpl: blog::datecrumbs blog::prevnext[18ms] (18 msec) ## struct/bottom.tmpl: ### bits/pagetools.tmpl: pagetools[1.6ms] (1.7 msec) ### hist/locker.tmpl: hist::lockedby ~~Empty~~ ### struct/searchbox.tmpl: search::enter ### struct/loginbox.tmpl: auth::loginbox ### syndication/feeds.tmpl: atom::feeds[1ms] (1.1 msec) ### bits/lastmod.tmpl: lastmodified ### site-sig.tmpl (5.2 msec for struct/bottom.tmpl) (45 msec for dwiki.tmpl) (Reading [[this dwiki/TemplateSyntax]] and [[this dwiki/ProcessingModel]] will be helpful.) The rough format is 'N.