Printf Debugging Revisited

gsasha writes "After long nights spent in debugging, w e have developed a C++ logging facility geared for debugging - and an article that describes our debugging methodology. The article consists of two parts: the first one describes the basics of the method, and the second one presents advanced techniques (to be completed if there is enough reader interest).
Happy debugging!"

Comments

Looks primitive.

[Anonymous Coward]

First look at the code... looks rather primitive[0]. Guess I have to read the paper to figure out what's new here?

Don't think I will.

[0] Which isn't necessarily a bad thing, but you'd wonder why it's here to begin with.

Re:Looks primitive.

[Viking Coder]

Look, friend - first you're responding to an Anonymous Coward. Expecting an AC to RTFA is wishful thinking.

Second, he's right - your code is rather primitive, as you admit. Why not start with a much more advanced logging utility, and then speak about using the logging consistently?

Third, if your whole point was about a methodology, then talk about the methodology. Reading your article, it doesn't read like that - it reads much more like a User's Manual for how to use your code.

Fourth, what makes you think that using loggers consistently is the answer? In fact, I can't see how to turn off your code (make it compile down to nothing, not merely something small) in release mode. You're essentially asking people to always use logging, for the sake of sometimes doing debugging.

Fifth, have you actually researched how people will use your utility, or are you just making a blanket assertion that "it'll be easy to debug" if you merely follow some trick? Gotcha on this one - you're essentially pitching the idea of a silver bullet, while stating that "there is no silver bullet in sight." Well, which is it?

Look, you might have some good ideas - but when pitching a methodology, speak about it in terms of a methodology, and don't lecture down to some random Anonymous Coward on Slashdot. That's like Bill Gates stopping in the supermarket to argue with some woman about whether "Start | Shutdown" makes any sense.

Re:Looks primitive.

[gsasha]

Ok then.

First: my fault ;)

Second: because you don't need a much more advanced logging facility for the intended use.

Fourth: Whoa! That's easy: #define LOG(x) if (false) os. But actually, yes, I do ask people to not throw logging out once it's there. The reason it's not expensive when not used is that the branches in the "if(is_active())" do not change throughout the program, and thus are predicted very well and cost very little. I actually did measurements about the overhead of the mechanism and found it to be very small.

Fifth: We have used this methodology in several very complex projects, and with very good results. You are free to use other debugging methods if you wish.

And anyway, an article such as this is a fine way to research on how will people use my utility :)

Some comments

[Cthefuture]

I didn't read the paper, but I looked at the code (for me this is usually more telling).

The first thing that jumps out at me is the coding style. Very junior programmer-ish. College student maybe? The style has that "everything crammed together" very diffcult to read feel. When I dug deeper I found the system to be over-designed and not well implemented.

Nice try though, get some experience then try again.

I've found that a simple C based logging facility is much more versatile. It can be used from C or C++ plus most programming languages and applications support calling external C libraries also.

Re:Some comments

[Brandybuck]

Actually my experience is that you can tell how junior a programmer is by their style. While their styles will vary greatly, old timers will almost uniformly prefer an easy-for-others-to-read style. There are of course exceptions. Some junior programmers have been exposed to professors/managers/reviewers who won't accept unreadable code, and some senior programmers got tagged as "heroes" and have never had to maintain someone elses code.

Re:Some comments

[Soul-Burn666]

If you look at the links, you can see they are both PhD students in the Technion institute of technology.
It's actually pretty strange the coding style is like this, specifically the hard coded functions like get_enabled1 or set_red instead of variables and constants like get_enabled(unsigned num) and set_color(Logger::color col).
I'm particularly surprised because I study in the same institute and faculty as they do and the programming courses we have are pretty demanding and specifically point to code reusability instead of code copying.

Re:Some comments

[SamBeckett]

Can you please point me to a good C+ compiler... gcc keeps complaining about my .cp files.

Re:Some comments

[jeif1k]

While their styles will vary greatly, old timers will almost uniformly prefer an easy-for-others-to-read style.

Easy-to-read for whom? Easy to read for an absolute beginner? Easy to read for an expert programmer?

There is no style that works for every reader--a style that makes code easy to read for beginners can obscure patterns and shorthands that make code easy to read for expert programmers.

Re:Some comments

[gsasha]

Well, if you didn't RTFA, then you missed the point. The article is not about "oh, we wrote this wonderful logging mechanism". It's about the *methodology* of debugging almost exclusively by logging (as opposed to *sometimes* doing postmortem analysis by looking at the logs).
It's about leaving the logging code inside and improving it, rather than throwing it out shortly after it's used.

log4c++

[Hard_Code]

Hasn't this wheel already been invented many many times?

How about Log4C++, a port of the canonical Log4J logging package for Java.

Re:log4c++

[Mysteray]

we have developed a C++ logging facility geared for debugging

My first reaction to this was, who hasn't?

I agree with some of the other posters that their code has some, well, "interesting" features. I have to say it never would have occurred to me to use strcmp on a compile-time constant in a member initialization.

That they use, but don't derive from, std::ostream for this is another example. It's not exactly trivial to do so, but it's also hard to argue against not doing it for something like this without good reason. But since there's not a single comment in the source files except some revision control macros we're just left to wonder.

C++ makes it hard

[YGingras]

It's hard to do a good printing debugger in C++. The lack of introspection throws most of the work in the hands of the pre-processor/developper.

When I learned Common Lisp, the first macro I did was for printing debugging. It reads the expresions it is debugging, prints it (and shortens it with "..." if needed), evaluates it, prints the results and returns the results.

What a monster you might say. Lets fist see an example of it's use:

CL-USER> (+ 16 34 (- 6 7 8) (/ (* 3 (expt 4 1/2)) 2 3))
42.0
CL-USER> (dbg (+ 16 34 (dbg (- 6 7 8)) (dbg (/ (* 3 (dbg (expt 4 (/ 1 2)))) 2 3))))
(- 6 7 8): -9
(EXPT 4 (/ 1 2)): 2.0
(/ (* 3 (DBG (EXPT 4 (/ 1 2)))) 2 3): 1.0
(+ 16 34 (DBG (- 6 7 [...] 4 (/ 1 2)))) 2 3))): 42.0
42.0

It's done like that (and it's actually readable when indented properly):

(defmacro dbg (expr)
`(let ((val ,expr)
(repr (format nil "~A" ',expr)))
(if (> (length repr) 50)
(format t "~A [...] ~A: ~A~%"
(subseq repr 0 20)
(subseq repr (- (length repr) 20))
val)
(format t "~A: ~A~%" repr val))
val))

Most of the hard work is taken away by the ability of the program to read itself, by dynamic typing and by the notion that there are no statements, only expressions. That being said, I don't claim that you should never use C++, just that it lacks introspection and that it makes printing debuging a lot harder.

Instead of adverts for 2nd-year student projects

[devphil]

why not a link to a more professional and better-designed debugging library instead? The author has made insane efforts to handle all kinds of error conditions which it looks like these kids haven't even thought of.

Don't reinvent the wheel

[pyrrhonist]

Don't reinvent the wheel. These facilities already handle logging better:

• Log4cxx
• Log4cplus

Don't take the criticism too hard guys...

[museumpeace]

Virtually every project of 10 or more engineers that I have been on in my 30 years of software dev has cooked up its own logging facility. You are on the back of a very crowded bus here. Depending on whether memory, disk i/o resources or realtime and multithread requirements reign in your application, rather different logging approaches are applicable. Being able to dump the Nth occurance is a nice feature but so many more are needed. THE BIGGEST DIFFERENCE I SEE between your logger kit and some I have used/written is that you published the code. A partial feature checklist I would be looking for:

• []has both compile time and run time mechanism to set severity thresholds.
• [] idenifies the process/thread from which the logging call is issued
• [] can generate some kind of event ID so context can be deduced even when the same message occurs many times.
• []timestamping: this can give you a poor man's perfmon with added programability.
• [] supports detection of recursion by indenting printouts that are called as you go deeper on the stack
• [] NOMENCLATURE REGULARITY: a syntax for timestamps, severity, function name from which print is called, etc so that you can automate [eg with AWK etc ] the sorting and dredging for clues in a long output run.
• []when not in use, can be "turned off" with no compile or run time overhead but still present as comments.

...there are more, believe me.

Why is this on Slashdot at all?

[Anonymous Coward]

As many have said, this has been done before. One of their main macros isn't even correct. Ie.,

#define LOG(logger) if ((logger).is_active()) (logger).os()

This will break if one writes:

if (value == 0)
LOG(xxx) "hello" endl;
else ...

The "else" gets interpreted as being attached to the "if" inside the LOG macro when it shouldn't.

It should be written as:

#define LOG(logger) if (!(logger).is_active()) ; else (logger).os()

For a much more expansive trace/log system see OSE at:

http://ose.sourceforge.net

and specifically

http://ose.sourceforge.net/browse.php?group=librar y-manual&entry=logger.htm

and

http://ose.sourceforge.net/browse.php?group=librar y-manual&entry=tracer.htm

The OSE library has had this stuff for over ten years now.

Re:aah, academic stuff

[gsasha]

Actually, it's not academic stuff and never meant to be. It's a simple article describing a nice methodology... and actually, it's not that much about the logger implementation (it isn't at all), but about how using debugging by logging consistently is a powerful technique.

PURE EVIL

[Viking Coder]

// Constructor:
Logger(const Logger& enable2 = *(Logger*)0);

(Trimmed to trick the lameness filter.)

Pure. Evil.

And don't go telling me "that's perfectly valid," cause you know what? I don't care if the C++ compiler accepts it, and I don't care if you do it in your code. That is just pure evil.