ColdFusion Debugging and Profiling

While I'm thinking about CFUnited I just wanted to point out a few not so well known features in CF.

To be fair, this is inspired by Charlie Aerharts presentation about their new profiler tools. Seeing the crowd's reaction I realized that many people must not know that most of what they showed is already in ColdFusion (as of CF6).

  • 1) Dumping the complete struct in debug output
  • What you may not realize that you can modify the default debug output yourself, and add dump tag output. This output is a just a simple .cfm page located in the "/WEB-INF/debug/" folder.

    You can create your own file, or edit the classic.cfm. For instance if you wanted to have a cfdump view of your application scope you can just replace lines 677 with <cfdump var='#application#'>

  • 2) logging all errors to a file
  • This one has a few options. The first, if you're using CF7, you can use the new Application.cfm onError() method. With this you can just use cffile to write the error object to a log file.

    The second option, which is doable in CF6+, is to edit the default error template. Just like the ColdFusion debug output the ColdFusion error templates are also .cfm pages. These are located in the "/web-inf/exception" folder. You can modify these to do what ever you need to with the error messages; send them in an email, write the error to a log file, just change the error formatting so it matches the rest of your site when an error happens.

  • 3) Profiler
  • Since CF6 ColdFusion has shipped with two views for your debug output "summary" and "tree".

    "Summary" is the default and what you've seen in ColdFusion since the early days of CF (not sure which version it first appeared in, 2 or 3). It provides a listing of all the templates, CFC's and custom tags called with a total execution time for each template.

    What you may not of realized is that there is also the "Tree" view, this view provides your with a detailed profiler type of view for the page. It creates a tree of the templates used to create the page. Showing you each individual template, custom tag, cfc execution (with cfc arguments) and the execution path that was taken to get to that page, just like a profiler does. (And you didn't need to buy JProbe. ;)

    This "Tree" view allows you figure out exactly which template is slow. For instance perhaps you loop over a custom tag 3 times, with this view you could see that the 3rd time the execution time triples. This would tell you that their must be something different with the arguments of the 3rd request, something that causes your code to take a different slower path.

    Note: Like a profiler, not like the "Summary" view, the tree view also displays the template execution time of the .cfm and all of it's children, instead of just the time spend on each template. This allows you to follow the slow running branches easier. If you need to know the just the individual template execution time it a simple matter of adding up the 1st level children and subtracting that from the total for the template.

Granted we do have some area of improvement, for instance we don't drill down to the individual tag counts for each .cfm. If you have any debugging idea for future versions of CF, please send them my way. What we can improve? What we can add? Etc... Perhaps the first thing to do is make the tree view the default for CF :)

Comments
David L's Gravatar How about a session or 2 in next year's CFUNITED about all those features / possibilities? <br/>
# Posted By David L | 7/7/05 1:13 PM
Doug Hughes's Gravatar How about the standard debuging features like stop points, variable watching, etc?&nbsp; I know this used to be in CF5, though I never used it then (d'oh!).&nbsp; <br/>
<br/>
I honestly think the debugging in Eclipse for Java is terrific.&nbsp; Something akin to that would be great.<br/>
<br/>
Doug<br/>
# Posted By Doug Hughes | 7/7/05 2:23 PM
Paul Kenney's Gravatar After talking to you about the profiling and the &quot;tree&quot; output, I tried it out. One thing I noticed was that it only showed me the top-most pages. If I wanted to see all of the CFCs that were called in the depths of my code I could not. The only way they showed up was in the &quot;summary&quot; output. Does that sound familiar?&nbsp; If so, is it supposed to be that shallow in detail or might it be a problem with something else. Basically, this is a machii app, so there is a single include file, then a bunch of cfcs.<br/>
# Posted By Paul Kenney | 7/7/05 3:38 PM
Brandon Harper's Gravatar Just a couple of initial ideas that I had of off the top of my head for discussion:<br/>
<ul>
<li>Grouping the execution time of related functions and tags to give a high level view of what type of operations in a particular request is taking the longest, as well as provide a percentage break down for them.&nbsp; For example, grouping queries in a group, XML related functions in a group, struct related functions in a group, etc.&nbsp; This also gives&nbsp; things when people are complaining about X being slow...&nbsp; &quot;look, the queries are taking 80% of the time on this page.. it's not ColdFusion that is slow&quot;<br/>
</li>
<li>Some sort of supported/documented debugging API might be useful.. ie OnRequestEnd, you could grab the debugging params which were most important to you via the debugging API and save them to a log to review after load testing an application, etc&nbsp; This would also be helpful to debug event gateways with I would think if you could easily output the debug output of reach request to a file.</li>
</ul>
# Posted By Brandon Harper | 7/7/05 3:43 PM
Brandon Harper's Gravatar FWIW, I also had the same above observation as Paul, but thought perhaps I was just missing something?<br/>
# Posted By Brandon Harper | 7/7/05 3:54 PM
ike's Gravatar small typo -- &quot;Application.cfm onError() method&quot; ought to be Application.cfc. I know you know this Mike,&nbsp;just thought I'd mention it for the benefit of the casual observer. :)
# Posted By ike | 7/7/05 3:57 PM
Mike Nimer's Gravatar <p>These are great enhament ideas. Keep them coming. </p>
<p>--nimer</p>
# Posted By Mike Nimer | 7/8/05 12:28 PM
Mike Nimer's Gravatar <p>Paul and Brandon,</p>
<p>can either of you, or better both of you, send me some kind of test case that I can run. I haven't heard anything about this tree not showing all of the CFC's that were called. </p>
<p>thanks</p>
# Posted By Mike Nimer | 7/8/05 12:31 PM
Paul Kenney's Gravatar I can try to come up with one. Not exactly sure how, but we'll see.<br/>
# Posted By Paul Kenney | 7/8/05 3:10 PM
Brandon Harper's Gravatar One other enhancement to the debugger or maybe a different debugger display type-- it would be nice to be able to follow the lifecycle of a request.. ie from top to bottom, it lists what methods were called with what arguments, etc... you could then click on the particular method/action which would then give you a detailed run down of what tags were used in that method, and how long each one of them took (including percentage of the total time it took)?&nbsp; <br/>
<br/>
I often find myself breaking down things percentage-wise post load testing to present to stakeholders if something is running too slow and I can't find a way to make it perform better.&nbsp;&nbsp; Something to the effect of telling them we should think about pulling X piece of functionality out because it eats-up 15% of the processing time but isn't that useful to the end-user, or that it will add X percent more time to something if we have to do it multiple times, etc.<br/>
<br/>
Actually after re-reading Paul's comment and what you wrote about the debugger (I'm sometimes guilty of skimming stuff too quickly while at work), it looks like it's behaving as advertised, so I'm not actually having that problem.<br/>
# Posted By Brandon Harper | 7/8/05 3:52 PM
Johnny's Gravatar <p>I was surprised to see people gasped at Charlie Aerheart's presentation and applaused when he said he will make it available as a commerical product.&nbsp; My first thought was that they are going to sell something that is already available in CFMX for years now,&nbsp;&nbsp;well, with a little enhancement.&nbsp; My second thought was there are so many beginners in our community who did not have a chance to explore the Admin area well.&nbsp; My third thought was that there are so many useful hidden features in CFMX.&nbsp; Macromedia should market these features more often.</p>
# Posted By Johnny | 7/8/05 5:32 PM
Nathanael Waite's Gravatar <p>I would agree with Johnny's Post about so&nbsp;many features of CFMX not documented that many of us just pass them by. </p>
<p>I have often found that Allaire/Macromedia has often left out some of the coolest features that are available&nbsp; out of thier documentation.</p>
<p>&nbsp;</p>
# Posted By Nathanael Waite | 7/8/05 9:53 PM
Raymond Camden's Gravatar Mike, I'm doing some work now on a custom debug template and I've noticed two things.<br/>
<br/>
First - the debug templates make use of the ServiceFactory. That is supposed to be a no-no. Are you recommending us to use that anyway? (As far as I know, there is no other choice.)<br/>
<br/>
Secondly - there are, as far as I know, no docs on the 'mega-query' returned and used by the debugger. I'd love to see a doc explaining each of the columns. As it stands, I'm slowly writing my own doc as I try to grok classic.cfm.<br/>
# Posted By Raymond Camden | 7/11/05 10:02 AM
Johnny's Gravatar Why is it a no-no to use the ServiceFactory?
# Posted By Johnny | 7/11/05 1:03 PM
Brian Kotek's Gravatar I have the same issue where the tree is only showing me the top-most level of templates/cfcs that were called during the request. I'll see if I can trim it down to simple test case but obviously this is happening to multiple people.<br/>
# Posted By Brian Kotek | 7/11/05 1:41 PM
Raymond Camden's Gravatar The servicefactory is intended for MACR's use only. Yes, people &quot;in the wild&quot; use it, but MACR doesn't support it, and future updates/patches/etc may break your code. In general - I wouldn't use it for a client's code. <br/>
# Posted By Raymond Camden | 7/11/05 2:04 PM
Mike Nimer's Gravatar <p>Ray,<br/>
For now the only way is with the service factory. I need to fix that ;)</p>
<p>You can get it through the adminapi, getDebugRecordSet(), but the method is locked down and requires authentication, which it shouldn't.</p>
<p>One thing you may not know, you can use the addDebugEvent() method of the adminapi to add your own custom rows of debug data, while you are running your pages. These will then be available in the debug recordset in your debug template. I used this, ok the service factory,&nbsp;&nbsp;in the cf_timer tag (before it was a real cftag) in CF6. </p>
<p>&nbsp;</p>
# Posted By Mike Nimer | 7/11/05 8:07 PM
Mike Nimer's Gravatar <p>Believe it or not we document everything we can. The problem is that there are 1600+ pages to find where it is documented.&nbsp; </p>
<p>Any ideas on how to point this stuff out better? For now I'll just keep blogging what I can.</p>
# Posted By Mike Nimer | 7/11/05 8:10 PM
Matthew Newby's Gravatar <p>I'd created some mods to the classic debugging template in CFMX 6.1, and am now working to get them integrated into the CFMX 7 template.&nbsp; Y'all changed a few things from one rev to the other, so I gotta redo my changes!&nbsp; In our case, we're running TONS of queries, some of 'em with TONS of arguments, and that's taking up TONS of space at the bottom of the page.&nbsp; Of course, this is useful information when something goes wrong or when you just want to poke around and see things, but in most cases it's extraneous.&nbsp; So, I wrapped each section with a DIV or named ID, wrote a show/hide javascript and set it up so the heading has a show/hide link that causes the block to appear when clicked.&nbsp; Our default is to start off with all the debugging info hidden except the overall show/hide, which effectively keeps the debugging info from cluttering up our pages, yet still available on every page load.</p>
<p>&nbsp;</p>
<p>Does anyone have any custom revisions to the debugging template they'd like to share?&nbsp; I'm very interested in seeing what others are doing with the debugging.</p>
# Posted By Matthew Newby | 7/29/05 2:39 PM
Duckling's Gravatar Do you know what the name of that debugging product was? I'm looking for a good one and so far I'm going to go with FusionReactor (fusion-reactor.com) because they are offering a free version. The only other one I found was called seefusion, but I didn't like it as much.
# Posted By Duckling | 12/2/05 4:35 AM
Mike Nimer's Gravatar No you can't do that. You can override HTML tags and create a server-side version of the tag (see the CFIMPORT docs). However, with the CF tags those you can not change.

at the most you could wrap them in your own CF_TAGS, and then you can output what you want around them.
---nimer
# Posted By Mike Nimer | 9/12/06 8:26 AM
Charlie Arehart's Gravatar I realize that this is *way* past when this was posted, but I'd like to point out in my defense (or rather, New Atlanta's) that what they showed was a statement-level profiler. That's very different than the 3 things Mike names above. I'm surprised that no one who was at that presentation ever pointed that out here. Still, as I'm sure some will want to point out, New Atlanta never did release that profiler. It's a shame, because people were indeed impressed and intrigued. And the only reason it didn't get out was that it needed some polishing and that just kept falling down the priority list. I've since left the company (in April 06), but I'm not aware of any plans by them to resurrect/release it. Perhaps we'll see more in Scorpio. :-)
# Posted By Charlie Arehart | 3/1/07 2:14 PM