Using the cftrace tag to trace execution

The cftrace tag displays and logs debugging data about the state of your application at the time the cftace tag executes. You use it to provide "snapshots" of specific information as your application runs.

About the cftrace tag

The cftrace tag provides the following information:

A severity identifier specified by the cftrace tag type attribute
A timestamp indicating when the cftrace tag executed
The time elapsed between the start of processing the request and when the current cftrace tag executes.
The time between any previous cftrace tag in the request and the current one. If this is the first cftrace tag processed for the request, the output indicates "1st trace". ColdFusion does not display this information in inline trace output, only the log and in the standard debugging output.
The name of the page that called the cftrace tag
The line on the page where the cftrace call is located
A trace category specified by the category attribute
A message specified by the text attribute
The name and value, at the time the cftrace call executes, of a single variable specified by the var attribute

A typical cftrace tag might look like the following:

<cftrace category="UDF End" inline = "True" var = "MyStatus" 
text = "GetRecords UDF call has completed">

You can display the cftrace tag output in either or both of the following ways:

As a section in the debugging output To display the trace information in the debugging output, in the Administrator, select Tracing Information on the Debugging Settings page.
In-line in your application page When you specify the inline attribute in a cftrace tag, ColdFusion displays the trace output on the page at the cftrace tag location. (An inline cftrace tag does not display any output if it is inside a cfsilent tag block.)

The cftrace tag executes only if you select Enable Debugging on the ColdFusion Administrator Debugging Settings page. To display the trace results in the debugging output, you must also specify Tracing Information on the Debugging Settings page; otherwise, the trace information is logged and inline traces are displayed, but no trace information appears in the debugging output.

Note: When you use in-line trace tags, ColdFusion sends the page to the browser after all page processing is completed, but before it displays the debugging output from the debug template. As a result, if an error occurs after a trace tag but before the end of the page, ColdFusion might not display the trace for that tag.

An in-line trace messages look like the following:

An in-line trace message

The following table lists the displayed information:

Entry

Meaning

Trace type (severity) specified in the cftrace call; in this case, Information.

[CFTRACE 13:21:11.011]

Time when the cftrace tag executed.

[501 ms]

Time taken for processing the current request to the point of the cftrace tag.

[C:\CusionMX\wwwroot\MYStuff\ NeoDocs\tractest.cfm]

Path in the web server of the page that contains the cftrace tag.

@ line:14

The line number of the cftrace tag.

[UDF End]

Value of the cftrace tag category attribute.

GetRecords UDF call has completed

The cftrace tag text attribute with any variables replaced with their values.

MyStatus Success

Name and value of the variable specified by the cftrace tag var attribute.

Entry	Meaning
	Trace type (severity) specified in the `cftrace` call; in this case, Information.
[CFTRACE 13:21:11.011]	Time when the `cftrace` tag executed.
[501 ms]	Time taken for processing the current request to the point of the `cftrace` tag.
[C:\CusionMX\wwwroot\MYStuff\ NeoDocs\tractest.cfm]	Path in the web server of the page that contains the `cftrace` tag.
@ line:14	The line number of the `cftrace` tag.
[UDF End]	Value of the `cftrace` tag `category` attribute.
GetRecords UDF call has completed	The `cftrace` tag `text` attribute with any variables replaced with their values.
MyStatus Success	Name and value of the variable specified by the `cftrace` tag `var` attribute.

ColdFusion logs all cftrace output to the file logs\cftrace.log in your ColdFusion installation directory.

A log file entry looks like the following:

"Information","web-29","04/01/02","13:21:11","MyApp","[501 ms (1st trace)] [C:\CFusionMX\wwwroot\MYStuff\NeoDocs\tractest.cfm @ line: 14] - [UDF End] [MyStatus = Success] GetRecords UDF call has completed "

This entry is in standard ColdFusion log format, with comma-delimited fields inside double-quote characters. The information displayed in the trace output is in the last, message, field.

The following table lists the contents of the trace message and the log entries. For more information on the log file format, see "Logging errors with the cflog tag," in Chapter 14.

Entry

Meaning

Information

The Severity specified in the cftrace call.

web-29

Server thread that executed the code.

04/01/02

Date the trace was logged.

13:21:11

Time the trace was logged.

MyApp

The application name, as specified in a cfapplication tag.

501 ms (1st trace)]

The time ColdFusion took to process the current request up to the cftrace tag, This is the first cftrace tag processed in this request. If there had been a previous cftrace tag, the parentheses would contain the number of milliseconds between when the previous cftrace tag ran and when this tag ran.

[C:\CFusionMX\wwwroot\MYStuff\NeoDocs\tractest.cfm @ line: 14]

Path of the page on which the trace tag is located and the line number of the cftrace tag on the page.

[UDF End]

Value of the cftrace tag category attribute.

[MyStatus = Success]

Name and value of the variable specified by the cftrace tag var attribute. If the variable is a complex data type, such as an array or structure, the log contains the variable value and the number of entries at the top level of the variable, such as the number of top-level structure keys.

GetRecords UDF call has completed

The cftrace tag text attribute with any variables replaced with their values.

Entry	Meaning
Information	The Severity specified in the `cftrace` call.
web-29	Server thread that executed the code.
04/01/02	Date the trace was logged.
13:21:11	Time the trace was logged.
MyApp	The application name, as specified in a `cfapplication` tag.
501 ms (1st trace)]	The time ColdFusion took to process the current request up to the `cftrace` tag, This is the first `cftrace` tag processed in this request. If there had been a previous `cftrace` tag, the parentheses would contain the number of milliseconds between when the previous `cftrace` tag ran and when this tag ran.
[C:\CFusionMX\wwwroot\MYStuff\NeoDocs\tractest.cfm @ line: 14]	Path of the page on which the trace tag is located and the line number of the `cftrace` tag on the page.
[UDF End]	Value of the `cftrace` tag `category` attribute.
[MyStatus = Success]	Name and value of the variable specified by the `cftrace` tag `var` attribute. If the variable is a complex data type, such as an array or structure, the log contains the variable value and the number of entries at the top level of the variable, such as the number of top-level structure keys.
GetRecords UDF call has completed	The `cftrace` tag `text` attribute with any variables replaced with their values.

Using tracing

As its name indicates, the cftrace tag is designed to help you trace the execution of your application. It can help you do any of several things:

You can time the execution of a tag or code section. This capability is particularly useful for tags and operations that can take substantial processing time. Typical candidates include all ColdFusion tags that access external resources, including cfquery, cfldap, cfftp, cffile, and so on. To time execution of any tag or code block, call the cftrace tag before and after the code you want to time.
You can display the values of internal variables, including data structures. For example, you can display the raw results of a database query.
You can display an intermediate value of a variable. For example, you could use this tag to display the contents of a raw string value before you use string functions to select a substring or format it.
You can display and log processing progress. For example, you can put a cftrace call at the head of pages in your application or before critical tags or calls to critical functions. (Doing this could result in massive log files in a complex application, so you should use this technique with care.)
If a page has many nested cfif and cfelseif tags you can put cftrace tags in each conditional block to trace the execution flow. When you do this, you should use the condition variable in the message or var attribute.
If you find that the ColdFusion Server is hanging, and you suspect a particular block of code (or call to a cfx tag, COM object, or other third-party component), you can put a cftrace tag before and after the suspect code, to log entry and exit.

Calling the cftrace tag

The cftrace tag takes the following attributes. All attributes are optional.

Attribute

Purpose

abort

A Boolean value. If you specify True, ColdFusion stops processing the current request immediately after the tag. This attribute is the equivalent of placing a cfabort tag immediately after the cftrace tag. The default is False.If this attribute is True, the output of the cftrace call appears only in the cftrace.log file. The line in the file includes the text "[ABORTED]".

category

A text string specifying a user-defined trace type category. This attribute lets you identify or process multiple trace lines by categories. For example, you could sort entries in a log according to the category.

The category attribute is designed to identify the general purpose of the trace point. For example, you might identify the point where a custom tag returns processing to the calling page with a "Custom Tag End" category. You can also use finer categories; for example, by identifying the specific custom tag name in the category.

You can include simple ColdFusion variables, but not arrays, structures, or objects, in the category text by enclosing the variable name in pound signs (#).

inline

A Boolean value. If you specify True, ColdFusion displays trace output in-line in the page. The default is False.

The inline attribute lets you display the trace results at the place that the cftrace call is processed. This provides a visual cue directly in the ColdFusion page display.

Trace output also appears in a section in the debugging information display.

text

A text message describing this trace point. You can include simple ColdFusion variables, but not arrays, structures, or objects, in the text output by enclosing the variable name in pound signs (#).

type

A ColdFusion logging severity type. The inline trace display and dockable.cfm output format show a symbol for each type. The default debugging output shows the type name, which is also used in the log file. The type name must be one of the following:
Information (default)

Warning

Error

Fatal Information

var

The name of a single variable that you want displayed. This attribute can specify a simple variable, such as a string, or a complex variable, such as a structure name. Do not surround the variable name in pound signs.

Complex variables are displayed in inline output in cfdump format; the debugging display and log file report the number of elements in the complex variable, instead of any values.

You can use this attribute to display an internal variable that the page does not normally show, or an intermediate value of a variable before the page processes it further.

To display a function return value, put the function inside the message. Do not use the function in the var attribute, because the attribute cannot evaluate functions.

Attribute	Purpose
abort	A Boolean value. If you specify True, ColdFusion stops processing the current request immediately after the tag. This attribute is the equivalent of placing a `cfabort` tag immediately after the `cftrace` tag. The default is False.If this attribute is True, the output of the `cftrace` call appears only in the cftrace.log file. The line in the file includes the text "[ABORTED]".
category	A text string specifying a user-defined trace type category. This attribute lets you identify or process multiple trace lines by categories. For example, you could sort entries in a log according to the category. The `category` attribute is designed to identify the general purpose of the trace point. For example, you might identify the point where a custom tag returns processing to the calling page with a "Custom Tag End" category. You can also use finer categories; for example, by identifying the specific custom tag name in the category. You can include simple ColdFusion variables, but not arrays, structures, or objects, in the category text by enclosing the variable name in pound signs (#).
inline	A Boolean value. If you specify True, ColdFusion displays trace output in-line in the page. The default is False. The `inline` attribute lets you display the trace results at the place that the `cftrace` call is processed. This provides a visual cue directly in the ColdFusion page display. Trace output also appears in a section in the debugging information display.
text	A text message describing this trace point. You can include simple ColdFusion variables, but not arrays, structures, or objects, in the text output by enclosing the variable name in pound signs (#).
type	A ColdFusion logging severity type. The inline trace display and dockable.cfm output format show a symbol for each type. The default debugging output shows the type name, which is also used in the log file. The type name must be one of the following: Information (default) Warning Error Fatal Information
var	The name of a single variable that you want displayed. This attribute can specify a simple variable, such as a string, or a complex variable, such as a structure name. Do not surround the variable name in pound signs. Complex variables are displayed in inline output in `cfdump` format; the debugging display and log file report the number of elements in the complex variable, instead of any values. You can use this attribute to display an internal variable that the page does not normally show, or an intermediate value of a variable before the page processes it further. To display a function return value, put the function inside the message. Do not use the function in the `var` attribute, because the attribute cannot evaluate functions.

Note: If you specify inline trace output, and a cftrace tag is inside a cfsilent tag block, ColdFusion does not display the trace information in line, but does include it in the standard debugging display.

The following cftrace tag displays the information shown in the example output and log entry in the "About the cftrace tag" section:

<cftrace abort="False" category="UDF End" inline = "True" text = "GetRecords UDF

  call has completed" var = "MyStatus">

Developing ColdFusion MX Applications with CFML
Debugging and Troubleshooting Applications

Using the cftrace tag to trace execution

About the cftrace tag

Using tracing

Calling the cftrace tag

Comments