Saturday, April 12, 2014

Coldfusion: Easy Timers for your objects

I've been really getting into logging lately.  A good friend of mine, through repeated "Gibbsing", wore me down on it, and I really do like using it.  (We'll talk about unit testing another time.)  It really helps to leave debugging statements in your code, re-enable debugging for that class later and get an insight into what was going on when you haven't looked at the code for a year.

I'm also a big user of Coldbox.  Therefore it is only logical that I also use Logbox, which is heavily modeled on Log4J.  Now, my solution here is really for classes and components (*.cfc files), not so much for *.cfm files.  Though you could easily put this into an application function or anywhere you want that's easy to access.  Would not take much tweaking at all.  In my case, I'm using this in my Service Layer, where 99% of my objects all inherit from a Base.cfc class.  Here are the functions I added to the Base.cfc component.  (I've stripped off some of the hints for clarity here in the post..)

Sorry for the small font, the layout here isn't very conducive.  Just copy to your favorite editor (Sublime?) to view in a larger font.

Coldfusion Code:

<!--- --------------------------------------------------------------------- --->
<!--- Add to your init() or preconstructor:  --->
<!--- --------------------------------------------------------------------- --->
<!--- <cfset variables.stTimers = {} /> --->
<!--- <cfset variables.nTimerTimeoutMS = 600000 > --->
<!--- --------------------------------------------------------------------- --->
<cffunction name="startTimer" access="private" returntype="string" output="false">
<!--- For Railo only, in CF use createUUID --->
<cfset var sHandle = createUniqueID() />

<cfset purgeTimers() />
<cfset variables.stTimers[sHandle] = getTickCount() />
<cfreturn sHandle />
</cffunction>

<!--- --------------------------------------------------------------------- --->
<cffunction name="endTimer" access="private" returntype="numeric" output="false">
<cfargument name="handle" type="string" required="true" />

<cfset local.nTimeInMS = -1 />
<cfif structKeyExists(variables.stTimers, arguments.handle)>
<cfset local.nTimeInMS = getTickCount() - variables.stTimers[arguments.handle] />
<cfset structDelete(variables.stTimers, arguments.handle) />
</cfif>

<cfreturn local.nTimeInMS />
</cffunction>

<!--- --------------------------------------------------------------------- --->
<cffunction name="purgeTimers" access="private" returntype="void" output="false">
<cfloop collection="#variables.stTimers#" index="local.sPurgeHandle">
<cfif getTickCount() - variables.stTimers[local.sPurgeHandle] GT variables.nTimerTimeoutMS>
<cfset structDelete(variables.stTimers, local.sPurgeHandle) />
</cfif>
</cfloop>
</cffunction>

Usage within inherited objects, in this case in conjunction with Logbox debug logging:

<cffunction name="myFuncNeedingTiming">
<!--- 'log' is in my component's 'variables' scope --->
<!--- *Always* wrap debugging code with log.canDebug() --->
<cfif log.canDebug()>
<cfset local.sTimerHandle = startTimer() />
</cfif>

<cfset someOperationThatWillTakeSomeTime() />
<cfset anotherOperationThatWillTakeSomeTime() />

<cfif log.canDebug()>
<!--- Sending the handle back, will kill the timer and return the milliseconds --->
<cfset log.debug('myFuncNeedingTimer complete in #endTimer(local.sTimerHandle)# ms') />
</cfif>
</cffunction>


Fairly easy to implement, should be mighty fast.  In the case of a transient bean inheriting from your Base class, you could modify to add another variables (or override in your BaseBean/BaseEntity class) for whether purging should be performed or not.  (Or create an override function that does nothing.)

Seemed like an idea worth sharing!

- Will Belden
April 12, 2014


3 comments:

Will Belden said...

Oh, yes, before someone beats me to it. This code would be MUCH cleaner in . I still prefer tag-based coding for most things. So that's what I did it in. Sorta looks old-school, I guess, when you see it in a blog post! - WB

Will Belden said...

...in *cfscript*. Yay, Blogger for protecting me from myself.

Brad Wood said...

Nice post. You should do one showing how to implement simple timers via AOP. A basic 'around' advice could be bound to your methods with zero boilerplate in the actual components.