Debug-Logging with conditional compile and config options

M

Marcel Müller

I have a multi-threaded application with a lot of debug logging. The
logging expressions call functions with [Conditional("DEBUG")], so
release builds are free of the overhead.

Now I need to enable/disable different kinds of log events in the
app.config. Of course, this only applies to the debug builds.

But the question is: how to check the conditions?

If I check this in the logging function, the function arguments are
already evaluated. Evaluating the function arguments is often more
expensive than the logging itself. So I need to check the condition
before the function call.

OK, so i need to write
if (Logger.DebugEnabled) Logger.Log(...);

But what happens in a release build where Logger.Log does not exist
because of the Conditional("DEBUG")? Is the condition still evaluated?


Marcel
 
M

Marcel Müller

On 27.10.2011 16:23, Peter Duniho wrote:
[...]
Honestly, the whole question smacks of premature optimization to me.

Yes, you are right.
Logging involves i/o, which is painfully slow compared to practically
anything else a CPU might do. So it's hard to see how it could actually
be the case that "evaluating the function arguments" could be "more
expensive than the logging itself". It'd have to be some pretty
expensive evaluating going on.

The I/O is write back cached by the OS. This is not that critical as
long as it is not too much.

But some of the log entries calculate some complex aggregate information
over a deep data structure and pass the result as string to the logger.
This cases can really slow down some tasks by a factor 3.
I'm also suspicious of the concern that logging methods impose
significant enough overhead that [Conditional("DEBUG")] might provide a
useful performance improvement.

The main improvement results from not evaluating the function arguments.
The condition check will probably not involve any noticeable overhead.

Personally, my general preference is to just use .NET's built-in "trace"
mechanism. It's not the simplest API, but it comes with app.config
support and is efficient enough that it's used in all sorts of places in
the .NET framework itself.

Unfortunately we have our own logging API in our company. This API has
some features needed here. The most important are that several
application instances can safely share the same log file and that the
API is implemented in several different platforms. So I have not the
option to use another tracing tool.
If using my own logging framework, I would
not worry about overhead until I had some specific performance
measurements that I could compare with some specific performance goals
that showed clearly the logging was producing a significant slowdown,

If I put comments in front of a dozen logging calls inside the
applications data cache then some UI actions are about 30-50% faster.
This is significant if the one that does the testing over and over waits
for 20 seconds instead of doing his work.
and even then I would focus only on the specific performance issues found.

I focus on the different cache hit events for now. But I do not want to
remove the logging completely, because it already has been very helpful
in several cases.

As an example, I did run across a significant performance problem in a
logging system last year. But in that case, the problem was that the
system included caller information as part of the logged output, which
required a stack trace. The logging system was generating the stack
trace whether or not the specific level of logging was enabled.

Currently we have no stack trace information unless we log an exception.
In the latter case the stack trace has been examined anyway, isn't it?

Anyway, all that said: I would guess that the JIT compiler will be smart
enough to remove logical test (e.g. "if" statements) if those test
branch around blocks of code that are empty, if it can. Note that if the
logical test involves calling a method that is not a simple property
getter, the compiler may not be able to remove the call, because it has
no way to know that the method call does not involve an important
side-effect.

Currently I tested something like
/// <summary>Enable Debug-Logging</summary>
#if DEBUG
private static readonly bool EnableLog =
Logger.GetLoggingFlag("MyClass");
#else
private const bool EnableLog = false;
#endif
and
if (EnableLog) Logger.DebugEvent(...);

The performance is fine, but I get dozens of warnings about unreachable
code in release build - although DebugEvent has a ConditionalAttribute.
This is a bit annoying.

If the test simply compares a field against some constant (and this may
include a simple property that does the comparison, since those may be
inlined and the JIT optimizer might do the branch removal after the
inlining has been performed), then it's possible the IT compiler can
remove the entire thing.

How can the JIT know that a field does not chance?


Marcel
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Top