No, that's not the point, and yes, trace logging IS bad

| 8 Comments
Sahil Malik doesn't agree with Jeremy Miller's description of excessive tracing being a code smell. He suggests a 'neat' way to get around the problem but, IMHO, he's completely missing the point, and I've said as much before. Oh, and I agree with Rockford, the 'neat' way stinks ;)

Firstly, Sahil seems to have misunderstood the smell. It's not seeing the output (which is what his 'neat' trick avoids) it's having the log statements in the code in the first place.

As Jeremy points out; "Those trace statements are in there because the code is prone to breaking and hard to understand".

It seems that Sahil is well on the way to building a complex tracing system, hmm, didn't I say that's always what people in love with tracing tend to do in these situations? It wont work, you're solving the wrong problem and building complexity for the sake of it! Stop it! ;)

Jeremy nails most of the reasons that excessive logging is a bad smell but there's one other potential issue. The Heisenberg uncertainty principle; the act of logging can change the way the program works. This is especially true in multi-threaded programs where writing to a log often causes a synchronisation point between threads which often changes how the threads in the system are sheduled (threads writing to a shared log may block on locking devices designed to protect the log). This can often mean that adding, or turning on, logging to show up a threading problem can cause the problem to go away (or arrive!).

I'd say that there are NO valid situations where trace logging should be left in production code. There are much better ways to achieve the same ends. Please note my distinction between trace logging and application logs...

Oh, and the 'neat' trick is awful. In fact I'm quite amazed that the .Net designers managed to come up with a conditional compilation trick that's even worse than a C/C++ preprocessor #define macro.

8 Comments

You are usually sensible, Len. But this time you are rambling ;-)


>As Jeremy points out; "Those trace statements are in there because the
>code is prone to breaking and hard to understand".

Most code is hard to understand, and tracing gives you an effective way to
know what is going on inside a program. What is your alternative?
mindlessly pressing f11/f10 in the debugger a thousand times?


>Jeremy nails most of the reasons that excessive logging is a bad smell

Well, doing anything "excessively" is bad. There is little information
in that sentence.

>The Heisenberg uncertainty principle; the act of logging can change the
>way the program works.

Again. what is the alternative? Stepping through threads in debugger?
The impact of tracing is miniscule compared to that.

> This is especially true in multi-threaded programs where writing to a log
>often causes a synchronisation point between threads which often changes
>how the threads in the system are sheduled (threads writing to a shared
>log may block on locking devices designed to protect the log).

Use a better trace system!

http://www.cuj.com/documents/s=8014/cuj0204leman/

>Oh, and the 'neat' trick is awful.

The trick makes it possible to get the situation you want where there is no
tracing in a release build.

--
Vagn "trace-lover" Johansen

VJ,

Thanks for the comment, don't worry, I like people disagreeing with me, it's usually when I learn new things or find out that I'm wrong!

I realise that my stance of 'no debug tracing in production code' is controversial and I expect that the real solution is possible somewhere nearer the middle, but...

One of the alternatives is to unit test the code so that you don't need to be able to run the whole application with tracing turned on to be able to see what's happening. I know it's not always possible but in systems where tracing is prevalent tracing is often seen as the ONLY way.

Another alternative is to look at the code and reason about what it does (wacky idea, I know). If it's complicated to work out what will happen then adding trace lines so that you can watch what it in operation does nothing to help the underlying problem; the code is hard to understand. I personally don't subscribe to the idea that all code is hard to understand; mostly, it seems, it's only the bad code ;)

Anyway, since you're in there making changes why not refactor the code a little to make it easier to understand? I'm not suggesting that you go into a huge system and start making random changes, but a huge system full of tracing doesn't become huge and unmanageable over night. It grows. If you avoid relying on tracing from the start and only use it for exceptional situations or remove it when it has served its purpose then your code stays cleaner and easier to understand.

So, sure, put some tracing in to understand some interaction, then, if you can, get that code into some form of test, then, perhaps, refactor it a bit so it's not so complex and then remove the tracing. I view tracing as scaffolding, it's not something that you leave around once the real work is done.

As for the multi-threaded problem, thanks for the link, it looks interesting. Again testing helps here; though I agree that it's harder. I've nothing against using debug traces to help you locate a problem but if you can then reproduce that problem in a test you can remove the tracing.

The 'neat' trick: I'm not a great fan of massive differences between debug and release builds. :) After all the flak that the C/C++ preprocessor gets and all the hype about how .Net is so much better I would have thought that something a little less 'hacky' could have been achieved. I'd personally prefer it to be obvious at the call site that the code is conditional; make the ugliness of the concept visible and people are less prone to abuse it. Something like:

Conditional("Debug", trace("Goes away if Debug not defined"));

makes it clear to all concerned that the code is conditional. You can see that it is, at the call site. The 'neat trick' means that you have to actually go and look at every method to know for sure if it's included ... (I suppose syntax highlighting could be used to achieve the same ends though...)

I tried to post a reply, but all I got was this:

Comment Submission Error
Your comment submission failed for the following reasons:

Your comment could not be submitted due to questionable content

Please correct the error in the form below, then press Post to post your comment.

Sorry about that, over zealous comment spam blacklist... It was blocking absolut (the vodka ;) )... I've removed it, try again?

'no debug tracing in production code'?! Are you changing your mind? I
thought you were against all tracing.

I could not agree more about the unit test. I wish it was possible for
me to use them more often. Sometimes I combine them with tracing, so
that if a unit test fails I enable tracing for just this test case and
look at the trace output. Of course, the ideal is that the failure
information from the unit test framework makes it possible to deduce
what the problem is. The lack of thinking can happen both when
mindlessly adding one more trace message or one more breakpoint.

The system I am currently working is 15 years of patchwork. Refactoring
is not really an option. And to make matters worse there is almost no
trace messages! I can understand that debuggers could seem wonderful
when you first hear about them. But when you are trying to debug a
problem involving multiple processes on multiple machines, then the idea
of controlling 4 (or more) debugger sessions of multi-threaded programs
begins to look like juggling. OK, that was my worst case scenario.

So, I have absolutely no plans to "avoid relying on tracing". But
hopefully relying more on unit testing. Also I think it is very
important to leave the trace messages in the code. If one developer
thought it was an important message, there is good chance it will be
useful for the next programmer working on the code.

Regarding the visibility of the 'neat trick': In C/C++ uppercase
identifiers are typically used to alert the (code) reader of a special
case (e.g. #define TRACE(..) ...). Well, those who forget history ...


--
Vagn Johansen

No, I'm not changing my mind. By no debug tracing I mean no function calls left in the code (even if they're conditionally compiled out). So whilst I agree that debug traces can be useful in problem diagnosis I feel that they should be put in to find the problem and then removed once the problem is fixed.

I feel your pain re the 15 year old app and multiple debug sessions and, perhaps, for your situation debug traces are the best option at the moment. I was called in by a client to look at a similar system. It had 3 or 4 different styles of debug traces and the logs were "impressive" but utterly useless to both the developers and the support staff who were expected to use the logs to diagnose system errors. We ripped the lot out and put in some appropriately placed calls to log transaction problems to the windows event log and the support staff was much happier.

I'm not convinced about leaving the messages in, sorry. Perhaps if your 15 year old app had used trace messages from early on you'd agree with me ;) I find that the messages that you find useful today are rarely useful the next time; if they are then perhaps you didn't do enough last time ;) Or, more likely, you're working on a bigger problem which spans releases. But personally I'd prefer to see the traces removed before you consider the work complete; though by all means check the 'finished' work into source control with the trace messages in and then check it out and remove them before checking in for the release...

Like all things in this business there is no black or white and, obviously, if trace messages are helping you to move forward then that's good, but I'd still prefer to avoid using that particular crutch unless you really have to...

I have to say I disagree with you on this one, Len. I think the important thing to remember here is that tracing has its greatest value not when code is development but in the field where you might not have any other source of information. Customers won't let you step through the code in a debugger, if that's even technically feasible for the kind of code involved. They won't let you put debug versions of libraries on their systems. There are often both confidentiality and logistical obstacles to collecting crash dumps. Therefore, trace logs are most useful precisely where you would preclude them - in production code that ships to customers. They might be the only thing you have.

You might call this application logging rather than tracing, but I think you're making the wrong distinction. The kind of trace facility you leave active in production has to be more detailed than mere once-per-request logging. It's OK if older stuff falls out of the trace, but not if the trace is too sparse for the time period it covers, and it has to perform well so as to be minimally invasive. Fixed-size circular buffers with accurate timestamps and dynamically changeable levels (including an "always log this" level) are the order of the day. Information density is key, so you do have to fight an ongoing battle against the inclusion of trace items that aren't actually all that useful, but that's life in a modern development/support milieu. It's still a very different kettle of fish than the ad hoc text logging that developers might add for their own benefit.

If I hadn't made sure such facilities had existed in products that I've helped to ship, customers would still be experiencing crashes and possibly even data corruption because of bugs that left absolutely no other clues for developers. To say that such a feature should be left out of production code is to say that developers' convenience trumps the interests of customers.

Platypus,

If the support of an application can benefit from some form of tracing then that tracing should be designed as part of the application. I've no problem with providing support engineers with the tools that they need to do their job but the logs that are actually useful to these guys are rarely the same logs that are put in by most developers. So, I think we agree, ad hoc developer debug tracing is different and that's what I object to; especially as it often precludes the inclusion of proper support tracing...

Leave a comment

About this Entry

What's wrong with my CSS? was the previous entry in this blog.

Disappointing .Net Sockets article in MSDN Magazine this month is the next entry in this blog.

I usually write about C++ development on Windows platforms, but I often ramble on about other less technical stuff...

Find recent content on the main index or look in the archives to find all content.

I have other blogs...

Subscribe to feed The Server Framework - high performance server development
Subscribe to feed Lock Explorer - deadlock detection and multi-threaded performance tools
Subscribe to feed l'Hexapod - embedded electronics and robotics
Subscribe to feed MegèveSki - skiing