CFDJ Feature Story - Debugging ColdFusion MX7

Debugging. That necessary evil that none of us dare turn on in our production environments unless it is absolutely necessary. We all wonder what all that stuff does don't we? Well, let's investigate what some of it does, and what it means.

I have read through numerous scenarios, mechanisms, and tools to help in debugging my CF applications. What I have found is that a combination of some default debugging information, as well as some custom code, is generally the most appropriate solution. I certainly found the short section about the Administrator API on page 38 of the "Configuring and Administering ColdFusion MX" manual a very welcome read (yes, some people actually do read the manuals, it's sad really).

Several years ago Macromedia had an excellent class for "Performance Analysis and Tuning." If you are lucky, you can still find the course materials floating around the Net. I haven't seen it offered as a class in the past few years but I do know that they still provide it as a professional services engagement. If you are interested, I recommend calling MM and asking customer services about it. I am also under the impression that AboutWeb and UniversalMind both have a good foundation in "Performance Analysis and Tuning" engagements and teach some of the fundamentals.

Now, before we get started talking about debugging performance, let's discuss what the default settings can provide you.

Here are a few caveats about utilizing the default debugging information:

1.  To utilize CF's default debugging information it must be enabled in the administrator by selecting the "Enable Debugging" checkbox.

2.  When this setting is left unchecked, it will override the settings listed under the "Custom Debugging Output" heading.

• Note: By enabling debugging, your server will incur a certain amount of performance degradation. In previous versions, this could be significant. However, in the latest version it seems to be nominal.

3.  Sites utilizing CSS positioning, in general, will find that the debugging content often gets hidden behind the content, forcing the developer to comb through the source.

• This can be resolved in your own custom debugging by utilizing JavaScript to find the bottom of your <div>s, then adjusting the div containing your debug information below that.

4.  CFCs, data from Web services, complex objects, or structures are not, appropriately, represented in the default debugging settings.

5.  Multiple instancing of your environment will certainly cause issues with your default debugging settings.

• It is recommended that you supplement your default debugging with your own brand of custom debugging and error handling.

It should be noted that debugging and error handling are not exactly the same thing. However, they do generally run hand in hand. You'll likely use a number debugging techniques in your error handling. Our discussion today will focus on debugging and, more specifically, the tools used for performance debugging but not really error handling.

The type of information that a developer can get out of the default setting is certainly useful and significant. We can get our hands on the standard application, CGI, client, cookie, form, request, server, session, and URL structures as well as database activity. This is what most developers think of when referring to CF Debugging information. There are a few new features like <CFTRACE> and <CFTIMER> that have been added to the arsenal for performance debugging. In addition, we can also find settings for Flash Form errors as well as my personal favorite, CFSTAT.

Debugging data, if enabled, will default to the localhost or 127.0.0.1. To see your debug information, your IP address must be listed within the Debugging IP Addresses section of the CF Administrator. Have you ever asked your systems administrator to add your IP address to the CF Administrator? You need to be able to see what variables the users are setting during their use of your application, right? Maybe get the timing of those long running queries? That button for "Add Current" IP can be a dangerous thing. I've seen many sites where some administrator or developer has simply clicked that button not realizing that they just added the proxy servers IP and are now broadcasting debugging information at the bottom of every page. Although, when you have debugging turned on for your application server, you should also be aware that whether you see the output or not you will incur the added performance hit. This may not affect your environment by adding 100 or so milliseconds per request, but in the grand scheme of things every little bit can count.

One of the most critical pieces that slow your applications is database connectivity and access. As a result, I think we should really start there with our discussion of specific features. Database Activity, once you have enabled this feature, will allow CF to output every query it performs, from the beginning of the request till the end of the request. It will also provide the data source it was performed against, the number of records it returned, the SQL statement, the template it was run in, the time it was run, and the time it took to process the request.

When I say CF will output every query it performs, I mean that in a literal sense. If you're the kind of developer who prefers to manipulate your code at a finer grain, to create your queries utilizing "QueryNew()" and its corresponding functions, you won't find those in the default debug information. You will, however, find that they will show up in CFSTAT, but we'll cover that later. This is one area where you will need to utilize <CFQUERY> to perform a query of queries to get your manually generated query into the debug output. It should be of additional note that the use of this technique is not really to get the timing of your manually generated query. It's really more for the benefit of having the query list so that you can remember to compensate for the timing in your design.

Here's an example:

<cfset qryFoo = QueryNew("col1,col2")>
<cfset tmp = QueryAddRow(qryFoo)>
<cfset tmp = QuerySetCell(qryFoo, "col1", "abc")>
<cfset tmp = QuerySetCell(qryFoo, "col2", "def")>

<cfdump label="qryFoo" var="#qryFoo#"><br />

<cfquery name="qryFoo2" dbtype="query">
    Select * from qryFoo
</cfquery>

<cfdump label="qryFoo2" var="#qryFoo2#">

So the actual output would look something like:

SQL Queries

qryFoo2 (Datasource=, Time=0ms, Records=1) in C:\Inetpub\
wwwroot\foo.cfm @ 23:23:30.030
Select * from qryFoo

Scope Variables

CGI Variables:
AUTH_PASSWORD=
AUTH_TYPE=
AUTH_USER=
CERT_COOKIE=
CERT_FLAGS=
CERT_ISSUER=
CERT_KEYSIZE=

Cookie Variables
CFADMIN_LASTPAGE=/CFIDE/administrator/debugging/index.cfm
JSESSIONID=8430c64ef280$C7$06$E
Debug Rendering Time: 78 ms

Note the "Debug Rendering Time" listed above. "Debug Rendering Time" is in addition to the processing time required to deliver the rest of the page.

Some of the new features like <CFTRACE> will help you track program flow and efficiency. Adding a Trace will look something like:

<cftrace abort="no" inline="yes" type="warning" var="FooTrace" text="This is a trace">

And will output something like :

We can use <CFTRACE> in our code to get an idea of how our application is performing as we are utilizing it. Utilizing this method should step up your performance investigation and just like the use of getTickCount() should be removed from your final release. A partner to <CFTRACE>, and speaking of getTickCount(), is a new mechanism that performs the same functions that we used to use "getTickCount()" functions for, <CFTIMER>. It's a bit leaner than the use of getTickCount() and can be rendered in debug, outline, inline, and comment form. Here is an example of its use:

<cftimer Label="timerFoo" type="DEBUG">
   <cfquery name="qryFoo2" dbtype="query">
    Select * from qryFoo
   </cfquery>
</cftimer>

Here's an example of its output:

CFTimer Times

[31ms] timerFoo

My favorite, for performance debugging though, is a little used command-line tool called CFSTAT. It wasn't really advertised as part of the application server but has been shipped with it since at least version 4. It can be found in the \bin directory of your CFMX root. Its utilization is simple: CFSTAT <space> interval (in seconds).

CFSTAT 2 … the 2 referring to a 2 second interval

CFSTAT will deliver:

1.  Pages per second - now and high

• This is how many requests came in during the last interval.

2.  Database requests per second - now and high

• This will show how many query requests were performed by CF including any query manipulation you do on your own.
• Note that this name is misleading and in reality reflects all query requests, locally built and externally requested.

3.  Cache Pops per second - now and high

• "Cache Pops" refers to pulling data from cache.
• i.e., a <CFQUERY> that may be utilizing the "cachedwithin" attribute.

4.  Requests queued

• The number of requests still waiting to be processed.

5.  Running requests

• The number of requests that are currently being processed.

6.  Requests timed out

• The number of requests that exceeded your administrator time out settings.

7.  Average queue time

• The average amount of time a request was in the queue waiting to be processed (in milliseconds).

8.  Average request time

• The average amount of time it is currently taking to process requests ( in milliseconds).

9.  Average DB time

• The average time required to process your query requests.
• Note that this name is misleading and in reality reflects all query requests, local built, and externally requested.

10.  Bytes in per second

• The amount of data received by the CF Server (in bytes).

11.  Bytes out per second

• The amount of data transmitted back to the requesting browser (including whitespace) (also in bytes).

Just like any tool, the results need to be interpreted. There are numerous ways to read CFSTAT and my best recommendation would be to turn it on and watch it for a while. As you watch it, you'll start to see the patterns and can then investigate them. As you watch your output, you might start to notice something like DB/sec reaching a maximum number. That maximum number happens to coincide with the maximum number of simultaneous threads you have set in the CF Administrator. You might also find that the average DB time is higher than you expected and seems to grow with the Bytes Out/sec, indicating that your bandwidth is being affected by your output and is also possibly affecting access to your database. These are only examples of what you could find, not necessarily what you will find.

In this article I directed my focus on the performance aspects of the CFMX debugging features more so than the generic ones. However, if you have any questions about how to go about writing some custom debugging features of your own, or would like to share some of your how-tos, please feel free to e-mail me at Jason@Heaslet.net