Custom Logging Template for SQL queries and Stored Procedures

We'll combine the last two blog posts, Where Does CF Debug Information Come from Mommy? Or How to use the ColdFusion Service Factory and ColdFusion Custom Debugging Template. The task is to create a template to log any database activity, specifically looking for consistently long running queries and to make a baseline for our code optimization.

Let's take a look at the data we are gathering. I created this table to keep data which I thought would be pertinent.

Hey this image will be loaded soon!

Here's a key explaining the basics on this table:
ATTUID = individual user id
RequestID = Individual ID per request (more below)
Body = the actual query
Line = line number of query or stored procedure
Name = assigned name of query or stored procedure
CFScript = not what you think, this is the script name calling the query or stored procedure
CFTimeStamp = ColdFusion's time stamp
SQLTimeStamp = MS SQL's time stamp
Type = query or stored procedure

Now the code...
First we'll utilize the ColdFusion Service Factory:

view plain print about
1<!--- initialize the CF Server's Service Factory --->
2<cfset factory = createObject("java","coldfusion.server.ServiceFactory") />
3<!--- get all the debugging data --->
4<cfset queries = factory.getDebuggingService().getDebugger().getData() />
We create the logging service by calling Illudium PU-36 generated beans and DAO (Data Access Objects). Basically these are the getters and setters.
view plain print about
1<!--- Set up Logging Service - call it once and reuse it --->
2<cfset CFLog = createObject("component","optimization.cfc.Optimization_Code_Log").init() />
3<cfset CFLogger = createObject("component","optimization.cfc.Optimization_Code_LogDAO").init(application.sqlSource) />

Add this in to help keep individual page requests identified together.

view plain print about
1<!--- Unique ID per request --->
2<!--- keep all requests per page call together --->
3<cfset RequestID = Val(Replace(Rand(),"0.","")) />
A little detail about this... I desired a random number be generated but wanted it to be a whole number. The Rand() function creates a decimal. I am treating the Rand() produced number as string, removing the preceding "0.", and converting to a number with the Val() function. The number length varied, so multiplication would not be work.

To get the data we want we are going to query the debugging data, "queries" called above, as shown below:

view plain print about
1<cfquery dbType="query" name="cfdebug_queries" debug="false">
2    SELECT *, (endTime - startTime) AS executionTime
3    FROM queries
4    WHERE type = 'SqlQuery'
5</cfquery>

Two things of note. One is the calculation of Execution Time, really what we are after, and the type = 'SqlQuery'. For Stored Procedures, we replace this with "StoredProcedure".

view plain print about
1<cfquery dbType="query" name="cfdebug_storedproc" debug="false">
2    SELECT *, (endTime - startTime) AS executionTime
3    FROM queries
4    WHERE type = 'StoredProcedure'
5</cfquery>

Loop the query containing all the debug data for queries run on your template, then set the data in the bean using the Illudium PU-36 setters, e.g. CFLog.setBlahBlah(variablescope.blahblah). Once they are all set, then we save using the generated DAO.

view plain print about
1<cfloop query="cfdebug_queries">
2
3    <cfset CFLog.setATTUID(client.ATTUID) />
4    <cfset CFLog.setRequestID(RequestID) />
5    <cfset CFLog.setBody(cfdebug_queries.Body) />
6    <cfset CFLog.setDatasource(cfdebug_queries.Datasource) />
7    <cfset CFLog.setIPAddress(CGI.REMOTE_ADDR) />
8    <cfset CFLog.setEndTime(cfdebug_queries.EndTime) />
9    <cfset CFLog.setExecutionTime(cfdebug_queries.ExecutionTime) />
10    <cfset CFLog.setLine(cfdebug_queries.Line) />
11    <cfset CFLog.setName(cfdebug_queries.Name) />
12    <cfset CFLog.setCFRowCount(cfdebug_queries.RowCount) />
13    <cfset CFLog.setStartTime(cfdebug_queries.StartTime) />
14    <cfset CFLog.setCFScript(CGI.SCRIPT_NAME) />
15    <cfset CFLog.setURLString(CGI.QUERY_STRING) />
16    <cfset CFLog.setTemplate(cfdebug_queries.Template) />
17    <cfset CFLog.setCFTimeStamp(cfdebug_queries.TimeStamp) />
18    <cfset CFLog.setSQLTimeStamp(Now()) />
19    <cfset CFLog.setType(cfdebug_queries.Type) />
20
21    <cfset CFLogger.save(CFLog) />
22</cfloop>

You can see that we are gathering more information than what was provided from the service factory, for example, the client user id, and several CGI variables.

We do the same thing for the Stored Procedures, except for one small but important change. Note also that I do not have to create another set of bean and DAO objects, I just reuse the existing ones, CFLog and CFLogger.

view plain print about
1<cfloop query="cfdebug_storedproc">
2
3    <cfset CFLog.setATTUID(client.ATTUID) />
4    <cfset CFLog.setRequestID(RequestID) />
5    <cfset CFLog.setBody(cfdebug_storedproc.Body) />
6    <cfset CFLog.setDatasource(cfdebug_storedproc.Datasource) />
7    <cfset CFLog.setIPAddress(CGI.REMOTE_ADDR) />
8    <cfset CFLog.setEndTime(cfdebug_storedproc.EndTime) />
9    <cfset CFLog.setExecutionTime(cfdebug_storedproc.ExecutionTime) />
10    <cfset CFLog.setLine(cfdebug_storedproc.Line) />
11    <cfset CFLog.setName(cfdebug_storedproc.result[cfdebug_storedproc.currentRow][1].name) />
12    <cfset CFLog.setCFRowCount(cfdebug_storedproc.RowCount) />
13    <cfset CFLog.setStartTime(cfdebug_storedproc.StartTime) />
14    <cfset CFLog.setCFScript(CGI.SCRIPT_NAME) />
15    <cfset CFLog.setURLString(CGI.QUERY_STRING) />
16    <cfset CFLog.setTemplate(cfdebug_storedproc.Template) />
17    <cfset CFLog.setCFTimeStamp(cfdebug_storedproc.TimeStamp) />
18    <cfset CFLog.setSQLTimeStamp(Now()) />
19    <cfset CFLog.setType(cfdebug_storedproc.Type) />
20
21    <cfset CFLogger.save(CFLog) />
22</cfloop>

That change is for Name. Inexplicably, in successive Stored Procedure calls in my template, the query output name remained the same for the following Stored Procs, ignoring the actual name. I had to dig down into the result column output to get the correct name for the Stored Procedure called.

view plain print about
1<cfset CFLog.setName(cfdebug_storedproc.result[cfdebug_storedproc.currentRow][1].name) />

If you pull a <cfdump> on the query output, you'll readily see from where this came, and possibly the situation in to which I ran.

Here is the entire chunk of code for my logging template. I'll not provide the Illudium PU-36 generated bean and DAO unless there are some requests. It's easy enough to generate your own.

view plain print about
1<!--- Get the Debugger Service --->
2<cfset factory = createObject("java","coldfusion.server.ServiceFactory") />
3<cfset queries = factory.getDebuggingService().getDebugger().getData() />
4
5<!--- Set up Logging Service - call it once and reuse it --->
6<cfset CFLog = createObject("component","optimization.cfc.Optimization_Code_Log").init() />
7<cfset CFLogger = createObject("component","optimization.cfc.Optimization_Code_LogDAO").init(application.sqlSource) />
8
9<!--- Unique ID per request --->
10<cfset RequestID = Val(Replace(Rand(),"0.","")) />
11
12<!--- EVENT: SQL Queries --->
13<cftry>
14    <cfquery dbType="query" name="cfdebug_queries" debug="false">
15        SELECT *, (endTime - startTime) AS executionTime
16        FROM queries
17        WHERE type = 'SqlQuery'
18    </cfquery>
19    <cfscript>
20        if( cfdebug_queries.recordCount eq 1 and not len(trim(cfdebug_queries.executionTime)) )
21        {
22            querySetCell(cfdebug_queries, "executionTime", "0", 1);
23        }
24    
</cfscript>
25    <cfcatch type="Any">
26        <cfscript>
27            cfdebug_queries = queryNew('ATTRIBUTES, BODY, CACHEDQUERY, CATEGORY, DATASOURCE, ENDTIME, EXECUTIONTIME, LINE, MESSAGE, NAME, PARENT, PRIORITY, RESULT, ROWCOUNT, STACKTRACE, STARTTIME, TEMPLATE, TIMESTAMP, TYPE, URL, et');
28        
</cfscript>
29    </cfcatch>
30</cftry>
31
32<!--- EVENT: Stored Procedures --->
33<cftry>
34    <cfquery dbType="query" name="cfdebug_storedproc" debug="false">
35        SELECT *, (endTime - startTime) AS executionTime
36        FROM queries
37        WHERE type = 'StoredProcedure'
38    </cfquery>
39    <cfscript>
40        if( cfdebug_storedproc.recordCount eq 1 and not len(trim(cfdebug_storedproc.executionTime)) )
41        {
42            querySetCell(cfdebug_storedproc, "executionTime", "0", 1);
43        }
44    
</cfscript>
45    <cfcatch type="Any">
46        <cfscript>
47            cfdebug_storedproc = queryNew('ATTRIBUTES, BODY, CACHEDQUERY, CATEGORY, DATASOURCE, ENDTIME, EXECUTIONTIME, LINE, MESSAGE, NAME, PARENT, PRIORITY, RESULT, ROWCOUNT, STACKTRACE, STARTTIME, TEMPLATE, TIMESTAMP, TYPE, URL');
48        
</cfscript>
49    </cfcatch>
50</cftry>
51
52<!--- SQL Queries Logging --->
53<cftry>
54    <cfloop query="cfdebug_queries">
55
56        <cfset CFLog.setATTUID(client.ATTUID) />
57        <cfset CFLog.setRequestID(RequestID) />
58        <cfset CFLog.setBody(cfdebug_queries.Body) />
59        <cfset CFLog.setDatasource(cfdebug_queries.Datasource) />
60        <cfset CFLog.setIPAddress(CGI.REMOTE_ADDR) />
61        <cfset CFLog.setEndTime(cfdebug_queries.EndTime) />
62        <cfset CFLog.setExecutionTime(cfdebug_queries.ExecutionTime) />
63        <cfset CFLog.setLine(cfdebug_queries.Line) />
64        <cfset CFLog.setName(cfdebug_queries.Name) />
65        <cfset CFLog.setCFRowCount(cfdebug_queries.RowCount) />
66        <cfset CFLog.setStartTime(cfdebug_queries.StartTime) />
67        <cfset CFLog.setCFScript(CGI.SCRIPT_NAME) />
68        <cfset CFLog.setURLString(CGI.QUERY_STRING) />
69        <cfset CFLog.setTemplate(cfdebug_queries.Template) />
70        <cfset CFLog.setCFTimeStamp(cfdebug_queries.TimeStamp) />
71        <cfset CFLog.setSQLTimeStamp(Now()) />
72        <cfset CFLog.setType(cfdebug_queries.Type) />
73
74        <cfset CFLogger.save(CFLog) />
75    </cfloop>
76    <cfcatch type="Any">
77        <!--- Error reporting query event --->
78    </cfcatch>
79</cftry>
80
81<!--- Stored Procedures Logging --->
82<cftry>
83    <cfloop query="cfdebug_storedproc">
84
85        <cfset CFLog.setATTUID(client.ATTUID) />
86        <cfset CFLog.setRequestID(RequestID) />
87        <cfset CFLog.setBody(cfdebug_storedproc.Body) />
88        <cfset CFLog.setDatasource(cfdebug_storedproc.Datasource) />
89        <cfset CFLog.setIPAddress(CGI.REMOTE_ADDR) />
90        <cfset CFLog.setEndTime(cfdebug_storedproc.EndTime) />
91        <cfset CFLog.setExecutionTime(cfdebug_storedproc.ExecutionTime) />
92        <cfset CFLog.setLine(cfdebug_storedproc.Line) />
93        <cfset CFLog.setName(cfdebug_storedproc.result[cfdebug_storedproc.currentRow][1].name) />
94        <cfset CFLog.setCFRowCount(cfdebug_storedproc.RowCount) />
95        <cfset CFLog.setStartTime(cfdebug_storedproc.StartTime) />
96        <cfset CFLog.setCFScript(CGI.SCRIPT_NAME) />
97        <cfset CFLog.setURLString(CGI.QUERY_STRING) />
98        <cfset CFLog.setTemplate(cfdebug_storedproc.Template) />
99        <cfset CFLog.setCFTimeStamp(cfdebug_storedproc.TimeStamp) />
100        <cfset CFLog.setSQLTimeStamp(Now()) />
101        <cfset CFLog.setType(cfdebug_storedproc.Type) />
102
103        <cfset CFLogger.save(CFLog) />
104    </cfloop>
105    <cfcatch type="Any">
106        <!--- Error reporting query event --->
107    </cfcatch>
108</cftry>

DAO missing WHERE clause

Illudium PU-36 Code Generator - generated code based on database tables.

DAO has a blank WHERE statement or clause.

This is due to not having a primary key in the table. Once the primary key is set in the table, regenerate your DAO with the Illudium PU-36 Code Generator.

Debugging Illudium PU-36 Hints

Remove the <cftry> and <cfcatch> in the generated DAO and use <cfdump abort=true> statements. This will help publish the errors in assisting to debug.

In the generated bean CFC, the primary key or ID is identified as a string:

view plain print about
1<cfcomponent displayname="MyBean" output="false">
2<cfproperty name="id" type="string" default="" />
This created some issues for me, conflicting with the database which had the ID as an INTEGER. I just changed it to represent as numeric.
view plain print about
1<cfproperty name="id" type="numeric" default=0 />

Also, in the bean's init function,

view plain print about
1<cffunction name="init" access="public" returntype="MyBean" output="false">
change the ID argument from string:
view plain print about
1<cfargument name="id" type="string" required="false" default="" />
to numeric:
view plain print about
1<cfargument name="id" type="numeric" required="false" default=0 />

BlogCFC was created by Raymond Camden. This blog is running version 5.9.7. Contact Blog Owner