I needed something to measure performance of sections of code, possibly sections spanning multilpe templates. I needed it to report in a helpful way. So I knocked together Daves Tick Counting Machine (tm).
It enables you to drop 2 lines of code in with existing code to start performance measuring (first line=start, 2nd lin=stop, like a stopwatch).
It gives you a nice sequential, nested output at the end. And it lets you display the results either on screen, to a log file, or both.
Here's the code: -
In application.cfm: -
<cfset request.tcm=createObject("component","DavesTickCountingMachine").init(enabled=true,outputToScreen=true,outputToLog=false)>
To start/stop monitoring: -
<cfset request.tcm.toggleCounter("Counter Name")>
To view output: -
<cfoutput>#request.tcm.report()#</cfoutput>
DavesTickCountingMachine.cfc: -
<Cfcomponent name="davesTickCountingMachine" hint="Provides a method of recording performance data">
<cffunction name="init" hint="creates the tick counting machine">
<cfargument name="enabled" default="true" type="boolean" hint="Turns the TCM on (true) and off (false)">
<cfargument name="outputToScreen" default="true" type="boolean" hint="Turns the TCM screen output on (true) and off (false)">
<cfargument name="outputToLog" default="false" type="boolean" hint="Turns the TCM csv file output on (true) and off (false). File is saved in root of calling file.">
<cfset this.enabled=arguments.enabled>
<cfset this.outputToScreen=arguments.outputToScreen>
<cfset this.outputToLog=arguments.outputToLog>
<!---holds performance data--->
<cfset this.TCM=structNew()>
<cfset this.seq=0>
<Cfreturn this>
</cffunction>
<cffunction name="toggleCounter" hint="Start or Stop timing an item">
<Cfargument name="counterName" hint="The unique identifier for the section of code being analysed">
<cfset var whatTimeIsIt=getTickCount()>
<cfif this.enabled eq "true">
<cfset request.seq=this.seq+1><!--- increment seq no--->
<Cfif not structKeyExists(this.TCM,arguments.counterName)>
<!--- if the counter doesn't exist, create a new struct--->
<cfset this.TCM[arguments.counterName]=structnew()>
<cfset this.TCM[arguments.counterName].start=whatTimeIsIt>
<cfset this.TCM[arguments.counterName].seq=this.seq>
<cfset this.TCM[arguments.counterName].name=arguments.counterName>
<cfset this.TCM[arguments.counterName].stop=0>
<Cfelseif this.TCM[arguments.counterName].stop eq 0>
<!--- it's an existing counter, so this must be the end time--->
<cfset this.TCM[arguments.counterName].stop=whatTimeIsIt>
</Cfif>
<Cfelse>
<!--- it's turned off. return fast--->
<Cfreturn "">
</cfif>
</cffunction>
<cffunction name="report" hint="Returns the analysis report" output="true">
<cfif this.enabled eq "true">
<style>
.tcm{
background:##eeeeee;
padding:5px;
margin:5px;
background-repeat:no-repeat;
border:1px solid navy;
}
</style>
<!--- calculate total times --->
<Cfloop collection="#this.tcm#" item="fn">
<Cfif structKeyExists(this.tcm[fn],"start") and structKeyExists(this.tcm[fn],"start")>
<cfset this.tcm[fn].time=this.tcm[fn].stop-this.tcm[fn].start>
<Cfelse>
<cfset this.tcm[fn].err=true>
</Cfif>
</Cfloop>
<cfset tickData=arrayNew(1)>
<Cfloop collection="#this.tcm#" item="fn">
<!--- build an array so we can sort the data --->
<cfset log="">
<cfset log=structNew()>
<cfset log.fn=fn>
<cfset log.seq=this.tcm[fn].seq>
<cfset log.time=this.tcm[fn].start>
<cfset log.action="start">
<cfset arrayAppend(tickData,log)>
<cfset log="">
<cfset log=structNew()>
<cfset log.fn=fn>
<cfset log.seq=this.tcm[fn].seq>
<cfset log.time=this.tcm[fn].stop>
<cfset log.action="stop">
<cfset arrayAppend(tickData,log)>
</Cfloop>
<cfset MovedSomething=1>
<!--- now sort the data so it can be represented in the order it actually happened--->
<Cfloop condition="MovedSomething eq 1">
<cfset MovedSomething=0>
<Cfloop from=2 to="#arraylen(tickData)#" index="i">
<cfset leftItem=tickData[i-1]>
<cfset rightItem=tickData[i]>
<cfif leftItem.time gt rightItem.time>
<!--- if first item started after 2nd, then swap --->
<cfset arraySwap(tickData,i-1,i)>
<cfset movedSomething=1>
<Cfelseif leftItem.time eq rightItem.time>
<!--- They started at same time. --->
<cfif leftItem.action eq rightItem.action>
<!--- they are both the same action --->
<Cfif leftItem.action eq "stop">
<!--- they are both EOF --->
<Cfif leftItem.seq lt rightItem.seq>
<!--- assume that the item that started first, stopped last - i.e. nested --->
<cfset arraySwap(tickData,i-1,i)>
<cfset movedSomething=1>
</Cfif>
<Cfelse>
<!--- they are both SOF --->
<Cfif leftItem.seq gt rightItem.seq>
<!--- move to start seq order--->
<cfset arraySwap(tickData,i-1,i)>
<cfset movedSomething=1>
</Cfif>
</Cfif>
<Cfelseif leftItem.seq gt rightItem.seq>
<cfset arraySwap(tickData,i-1,i)>
<cfset movedSomething=1>
</cfif>
</cfif>
</Cfloop>
</Cfloop>
<!--- display it. nest child processes --->
<cfif this.outputToScreen eq "true">
<div class="tcm" >
<div style="background:navy;color:white;padding:5px;">Dave's TickCounting Machine (tm)</div>
<div style="float:left;">
<Cfif arrayLen(tickData) neq 0>
<cfset base=tickData[1].time-1>
<cfset depth=0>
<TABLE>
<Cfloop from=1 to="#arrayLen(tickData)#" index="i">
<Cfif tickData[i].action eq "start"><cfset depth=depth+1></Cfif>
<tr>
<td>#repeatString(" ",depth)##tickData[i].fn#</td>
<td>(#tickData[i].action#)</td>
<td align=right>#tickData[i].time-base#ms</td>
</tr>
<Cfif tickData[i].action eq "stop"><cfset depth=depth-1></Cfif>
</Cfloop>
</TABLE>
<Cfelse>
No data was recorded for this request
</Cfif>
</div>
<div style="float:left;padding-left:20px">
<strong>How's It Work?</strong>
<br><br>
Simple.
<br><br>1. Drop a ##request.tcm.toggleCounter("ID String")## at the point you want to start timing.
<br>2. Drop a ##request.tcm.toggleCounter("ID String")## at the point you want to end timing.
<br>3. Relax - Dave's TickCounting Machine (tm) does the rest...
<br><br>
</div>
<br style="clear:both">
</div>
</cfif>
<cfif this.outputToLog eq "true">
<div class="tcm" >
<div style="background:navy;color:white;padding:5px;">Dave's TickCounting Machine (tm)</div>
<cfset date=dateformat(now(),"dd-mmm-yyyy")>
<cfset time=timeformat(now(),"HH:MM:SS")>
<cfset path_trans=cgi.path_translated>
<cfset url_path=url.path>
<Cfif arrayLen(tickData) neq 0>
<Cfloop from=1 to="#arrayLen(tickData)#" index="i">
<Cfif tickData[i].action eq "start"><cfset depth=depth+1></Cfif>
<cfset logrow="">
<cfset logRow=listAppend(logRow,date)>
<cfset logRow=listAppend(logRow,time)>
<cfset logRow=listAppend(logRow,depth)>
<cfset logRow=listAppend(logRow,path_trans)>
<cfset logRow=listAppend(logRow,url_path)>
<cfset logRow=listAppend(logRow,tickData[i].fn)>
<cfset logRow=listAppend(logRow,tickData[i].action)>
<cfset logRow=listAppend(logRow,tickData[i].time-base)>
<Cffile action="append" file="#expandpath("tcm.log.csv")#" output="#logRow#" addnewline="true" mode="775">
<Cfif tickData[i].action eq "stop"><cfset depth=depth-1></Cfif>
</Cfloop>
TCM Data logged to: <a target="_new" href="tcm.log.csv">#expandpath("tcm.log.csv")#</a>
<Cfelse>
No data was recorded for this request
</Cfif>
</div>
</cfif>
</cfif>
</cffunction>
<cffunction name="deleteLog" hint="Deletes the log file">
<Cffile action="delete" file="#expandpath("tcm.log.csv")#">
</cffunction>
</Cfcomponent>
