Trace running with debug turned off

[Raymond Camden]

Twice now in a CF9/ORM/MG3 application I've noticed something odd.
I'll get a timeout error and the tag involved will be cfdump,
specifically:

EventContext.cfc:

<cffunction name="addTraceStatement" access="public" returnType="Void"
output="false" hint="I add a message to the trace log.">
<cfargument name="type" type="string" />
<cfargument name="message" type="any" />
<cfargument name="tag" type="string" default="" />
<cfargument name="traceType" type="string" default="OK" />

<cfset arguments.time = getTickCount() />

<cfif not isSimpleValue(arguments.message)>
<cfsavecontent variable="arguments.message"><cfdump
var="#arguments.message#" /></cfsavecontent>
</cfif>

<cfset variables._logWriter.write(this, arguments) />
</cffunction>

If I comment out the CFIF and let the error 'go through', it seems
simple enough. In my case it has been a simple matter of setting an
integer based column to a string. I don't know why the server would
time out just dumping it, but it does. After a few reloads the server
will crash.

But anyway - my real question is - should addTraceStatement be running
when debugging is turned off? I added a cflog and see that it seems to
run quite often. Even if it runs quickly, that cfdump is a bit of a
waste if it doesn't actually end up getting used anywhere.


--
===========================================================================
Raymond Camden, ColdFusion Jedi Master

Email : r...@camdenfamily.com
Blog : www.coldfusionjedi.com
AOL IM : cfjedimaster

Keep up to date with the community: http://www.coldfusionbloggers.org

[Chris Blackwell]

<cfdump> can be a real hog, so i think if we can avoid running it we should.  How about adding a check for the debug status at the top of addTraceStement() ?

<cfif getModelGlue().getConfigSetting('debug') IS NOT true>

<cfreturn />

</cfif>

something like that should work, although checking my config now, with the debug property set to "false" in coldspring.xml, modelglue is reporting a value of "none" for the debug config setting... whats up with that?

chris

2009/11/30 Raymond Camden <rca...@gmail.com>

--
Model-Glue Sites:
Home Page: http://www.model-glue.com
Documentation: http://docs.model-glue.com
Bug Tracker: http://bugs.model-glue.com
Blog: http://www.model-glue.com/blog

You received this message because you are subscribed to the Google
Groups "model-glue" group.
To post to this group, send email to model...@googlegroups.com
To unsubscribe from this group, send email to
model-glue+...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/model-glue?hl=en

[Ezra Parker]

Behind the scenes, a config value of "true" is converted to "verbose",
and "false" to "none". The debug setting actually supports three
states: "verbose", "trace" and "none" -- although it appears that
support for the "trace" level was never completed (see lines 13-14 of
gesture/eventrequest/log/LogRenderer.cfc).

FWIW, the conditional statement that is currently used to render to
the debugging in ModelGlue.cfm is:

<cfif mg.configuration.debug neq "false" and mg.configuration.debug neq "none">

(Although I'm not really sure why the "false" case is present...)

I'm inclined to agree that it would probably be a good idea to return
out of addTraceStatement() if debugging is disabled -- can anyone
think of a reason not to do this?

--
Ezra Parker

[Dennis Clark]

The addTraceSatement method only calls cfdump when the message is a complex value, and the only place I know where that is done is at line 167 of http://svn.model-glue.com/trunk/ModelGlue/gesture/eventrequest/EventContext.cfc:

<!--- Trace the exception.  Maybe people will like this ;) --->

<cfset addTraceStatement("Exception", cfcatch) />

I think I can speak for most of us when I respond to the above comment with NO WE DO NOT!!!!

I propose that the abovementioned code be removed from the framework to eliminate the unnecessary issues it causes during exception processing. I do not find such a trace helpful even in debug mode. If someone really needs to log the entire cfcatch structure (which tends to be quite huge) they should do it from a controller in the exception event.

Cheers,

Dennis

[Chris Blackwell]

slightly OT... is it really the job of addTraceStatement to <cfdump> complex values?  isn't that the job of the renderer?  

There was talk of being able to override the default logRenderer in future, in which case it would make sense for complex objects to be placed into the log as-is so that any custom renderer can access them and do whatever it needs with them.  For example your custom renderer might be tailing them to a log file, in which case you definitely don't want cfdump's output in there.

chris

2009/11/30 Ezra Parker <ez...@cfgrok.com>

[Dan Wilson]

Chris, you bring up some good points.

The logging needs to be revisited anyways as I think we do need to fully implement the moderate setting of 'trace'. The verbose setting can often drown out useful info.

Can you guys please give the logging functionality a think and see if you can come up with any other useful ideas? I'd probably try to jump on this Wednesday and make headway.


DW

“Come to the edge, he said. They said: We are afraid. Come to the edge, he said. They came. He pushed them and they flew.”

Guillaume Apollinaire quotes

[Dennis Clark]

I like your idea of moving the cfdump to the renderer. At the very least it means that the burden of processing complex trace data is delayed until rendering time, allowing more important processing to occur first.

Dennis

[Dennis Clark]

I'll also +1 the idea of having addTraceStatement() do nothing if debugging is off. I'm certain that for the default logWriter implementation there is absolutely no point in writing log entries when debugging is off, because that log writer only stores log data for the renderer, and as Ezra pointed out the renderer is not even invoked when debugging is off. We ought to set the expectation now for alternate logWriter implementations that they will never be invoked if debugging is off.

As for making better use of the different debug modes for filtering, I think it'd be better for those modes to be used for early filtering (during event.addTraceStatement() or logWriter.write())  rather than late filtering (during logRenderer.renderLog()).

Dennis

[Chuck Savage]

I know this thread is kind of old, but ran across it when it was
mentioned in a new thread. Basically following Chris' suggestion
above, I got about a 50% improvement, but having it call
getConfigSetting('debug') on every addTraceStatement() is rather slow.

So I added a <cfset variables._debuggingEnabled = false> to the
component definition, and these statements to the Init() just before
the addTraceStatement() at the end of the function,

<cfif arguments.modelglue.getConfigSetting('debug') NEQ "none">
<cfset variables._debuggingEnabled = true>
</cfif>

and added this <cfif variables._debuggingEnabled> around the code in
addTraceStatement()

At least a 90% improvement in speed!

[Dennis Clark]

Chuck,

Try using the following code in addTraceStatement:

<cfif variables._modelGlue.configuration.debug EQ "none">

<cfreturn />

</cfif>

Please let us know how the performance of this code compares to the other two approaches.

This method of accessing the framework configuration is not part of the public API, but is used in some internal framework components for performance. It is not intended for use in controllers or any other custom application code.

Cheers,

-- Dennis

[Chuck Savage]

<cfif variables._modelGlue.configuration.debug EQ "none">

<cfreturn />

</cfif>

Please let us know how the performance of this code compares to the other two approaches.

Well, my completely unscientific approach, just involved pasting that code in Dennis ahead of my other code, and then counting in my head as I tried various pages and load times.  Of course pages didn't load in the exact same time each time, but mostly they did.  On average, the above snippet loads maybe a half second slower than just checking an already set true/false value.

As to the default approach, IE no IF statement in the addTraceStatement()...

I wrote the above before testing it, my server speed just increased incredibly and default was faster, so I had to re-run the other tests.  Perhaps caching plays a part in these results, so they may not be the best tests.

The default is normally like a 10 second load, and with either of the if statements, they are 2-5 second loads, though mostly 2-3.  I'll have to try again when my application times out and a new load is required.

Another interesting caveat, is if an array is passed to this, arrays are pass by value, not reference, so a copy of all the objects in the array is done before the array is received.  That would slow things down too, even with a switch to not process the array once received.

--
Chuck Savage
http://SeaRisen.com

[Josen Ruiseco]

unsubscribe

---

From: model...@googlegroups.com [mailto:model...@googlegroups.com] On Behalf Of Chuck Savage
Sent: Wednesday, January 13, 2010 1:12 PM
To: model...@googlegroups.com
Subject: Re: [Model-Glue] Re: Trace running with debug turned off

[Raymond Camden]

So does anyone know if the problems addresses here have been fixed
back in the source?

[Chris Blackwell]

Not in SVN yet, but would be nice if this fix was rolled out asap, even if a complete rework of the logging is on the cards in the long run.

2010/1/14 Raymond Camden <rca...@gmail.com>

[Dan Wilson]

There is a fix/enhancement in SVN right now for this. Here is the way it works:

1. addTraceStatement does nothing to the data it is asked to trace. It merely calls the logWriter.
2. The logWriter is now configurable in ColdSpring and gets the value of debug when the application loads.
3. If debug is set to true, then complex values will be converted to simple values, then logged. If the value was originally a simple value, it is just logged.
4. If debug is set to false, then nothing is convered to simple values nor logged. 

You can now provide your own implementation of the logWriter. All you need to do is create an entry in your ColdSpring.xml with the bean ID of modelGlue.logWriter and make sure to link it to your modelGlue.modelGlueConfiguration bean so it'll know the debug status:

<bean id="modelglue.logWriter" class="ModelGlue.gesture.eventrequest.log.LogWriter">

<constructor-arg name="debugMode"><bean factory-bean="modelglue.modelGlueConfiguration" factory-method="getDebug" /></constructor-arg>

</bean>

Now you can do whatever you want to when logging. Want to surpress all complex value logging? Go for it. Want to log remote requests and nothing else, while in production? You can easily do that.

And of course, you never ever have to touch a core Model Glue file to accomplish this. Don't believe me? Read http://docs.model-glue.com/wiki/FAQs/HowDoICustomizeTheModelGlueFramework

DW

DW