The Daily WTF: Curious Perversions in Information Technology

tgape · 2009-10-12 Reply Admin

Curious George:
tgape:
My point is not that profilers won't work, but you need a *good* profiler for this.
What's a good profiler to run with in production?

Just because I said you need it doesn't mean I necessarily know what it is.

But for production use, you need something fast, too, which means it won't be cheap. (RFC 1925.2.7a)

tgape · 2009-10-12 Reply Admin

Bim Job:
Number Two: All the "industry-standard" logging packages I have seen, in whatever language, are barely fit for purpose. I realise that this is a grandiose claim, but I'm standing by it. They all seem to have inherited the same four brain-deal "levels" from NetView, which was yer standard over-engineered HP product. If they involve an RDBMS at any level, then sayonara, buddie.

Unix standard logging uses seven levels. Not a big improvement, but I've seen it replicated more places than I've seen any other type of logging levels. I've even used it myself a few times, when the need for debug logging wasn't much.

The next most common logging I've seen uses a bitstream to determine what is logged and what isn't. Of course, I haven't seen any standard logging package that does this; it's just a design pattern I've seen a lot of places. I use it for most of my own code.

Bim Job:
Number Three, and this is really quite important, they all apply the same deranged paradigm to the task. The code in the OP is a perfect, if extreme, example. Entry and Exit, hah!
Logging is Comments, except as audit trail after the event rather than verbiage before the compiler. Log messages should almost never be associated with the details of language implementation. Log messages should describe the application domain, not the programming domain.

For all log levels higher than debug, I agree. For debug, most should probably be in the programming domain - however, probably farther down the bitstream than most people need to go. (For example, one program I wrote uses bits 0, 1, 2, and 3 for debugging in the application domain. 4, 5, 6, 7, 8, 9, and 10 debugged various programming domain features. 11 and 12 reported hardware/OS details.)

That having been said, enter/exit debugging should only be used on complex functions. One to three line routines should probably only have an enter debug line, if they need even that much. (Exception: if the routine consists of a single if statement with no else clause, it may make sense to add another debug line - but I'd generally do it by adding an else clause and debug the 'and nothing happened' part, rather than an exit line.)

I'd comply with a group coding standard if one instructed otherwise, because I know the cost of an if not taken is very low. However, I would at least let it be known that I felt it was overkill for such simple functions.

tgape · 2009-10-12 Reply Admin

nwbrown:
I guess I do now know why ATMs can run very slow, but not for the reason you think. If your code is so complex that adding entry and exit logs add 5 minutes to the running time, I don't think the problem is in your logging requirements...

It doesn't necessarily take complexity. Say they use an OOP style. Say they follow the 'abstract everything' anti-pattern. Say their library vendors have done the same. Repeat a few times. Now, imagine that many of these 'vendors' are actually different in-house groups which have the same programming requirement.

Oh, and I forgot to mention, they're all OOP purists, so there's no direct use of any member variables outside of getters and setters, and every unit of work which is conceivable to reuse elsewhere is a separate method, even if it's not actually used. (That is, most methods end up being about 5-8 lines, including the logging lines, return statement, and so forth.)

And finally, remember: he didn't say that the logging added 5 minutes, but that the total time was 5 minutes. While they should be the same thing, within a margin of error, they may not be - I've seen some ATMs which took close to a minute to dispense cash. (Of course, for all I know, they were logging every function, method, and subroutine entry and exit too.)

2009-10-12 Reply Admin

ounos:
Brompot:
grzlbrmft:
[...] Conclusion: minor WTF, if at all.
It's the disk I/O of all this logging that hits you, not the processing. At some point writing out of logging will start to clog up your I/O channels an hence puts every method invocation in an I/O wait.
Please explain how logging initiates disk inputs.

Well, of course it must initiate input: how else would it be known if the log file is to be created or appended to?

takatori · 2009-10-13 Reply Admin

Ditto here, have seen this live.

RogerInHawaii · 2009-10-13 Reply Admin

Anonymous:
Mothinator:
You don't "architect" something, you "design" it.
Try telling that to an architect.

Isn't an architect someone who "designs" architecture? He doesn't "architect" architecture. Right?

OK, OK, the dictionary does indeed include architect as a verb, but it sure sounds weird to me.

2009-10-13 Reply Admin

WTF?

duh... here i am trying to read a funny WTF article and some loser lowers the tone with his boring dribble.

yawn.

teh jav · 2009-10-13 Reply Admin

So the real WTFs :- Walter used DEBUG when he should have used FINEST. Walter rolled his own rather than just let AOP handle it.

teh jav · 2009-10-13 Reply Admin

Col Obvious:
Explain? What do you think is the purpose of 'Debug' level logging?

DEBUG - Debugging stuff. Values, the process (not the method) in question. Stuff that would be meaningful for the support team.

FINE - Stuff that is rarely useful for the support team but the developer may need every now and again.

FINEST - Worthless shit the developer /thinks/ he needs when he is completely confused as to what the hell is going on. Turned off 99.999% of the time. Only enabled when the unit tests work gosh darn it. What the hell is going on!?

2009-10-13 Reply Admin

TRWTF is that the setter doesn't log the parameter.

pjt33 · 2009-10-13 Reply Admin

Bim Job:
pjt33:
AIUI the Java JIT does a lot more than the .NET one. I'm pretty sure it isn't put off by try blocks.
Now you're making me mad. FWIW, the JVM and the CLI and, for all I know, the goddamn CIA are way too high level for this stuff. Bottom line. Logging is for when things go wrong. Figure out what you would like to be told when things go wrong. It's not a language issue, it's an application issue. Log things at the simplest, lowest, possible level.

Two things. Firstly, that was an off-topic comment responding to another off-topic comment. I've no idea how you're interpreting it, but you clearly think it had something to do with logging. It didn't.

Secondly, if the JVM is too high level then you must mean that logging should be at the processor level. That's certainly the lowest level, but I think it's so fine-grained as to be completely useless.

tgape:
Oh, and I forgot to mention, they're all OOP purists, so there's no direct use of any member variables outside of getters and setters

That's not OOP purism: it's completely misunderstanding encapsulation. But that's a completely separate rant.

2009-10-13 Reply Admin

Martin:
Sam:
if (logger.isDebugEnabled()) {
  logger.log(Level.DEBUG, "getNamePattern() - start {0}", reallyComplexMethod());
}
That pattern avoids the call to reallyComplexMethod() if you don't need it. I've seen a coworker use this kind of pattern in non-generated code. It's obnoxious to read and debug.
Yes. Replace reallyComplexMethod() with doVeryImportantBusinessLogicStuff() and have fun "debugging" the application: "but it works on my dev machine..." and "with debug logging it works"

That depends, I would say :-) Wouldn't be doVeryImportantBusinessLogicStaff() then a side-effect I rely on when doing logging just for informational purposes? Not that this could never happen, as we all know ;-P

2009-10-13 Reply Admin

Jay:
A Nonny Mouse:
Anonymous:
Mothinator:
You don't "architect" something, you "design" it.
Try telling that to an architect.
or whoever wrote the dictionary

Don't you mean, "whoever AUTHORED the dictionary"?

Surely "dictionaried the verb 'architect'"

2009-10-13 Reply Admin

Ruth:
Oh help.
This is the application I'm working on right now.

looks suspiciously around at team members

You mispelled "Kill me." ;-)

amischiefr · 2009-10-13 Reply Admin

Kermos:
SpasticWeasel:
That has got to be generated code. Nobody would be consistent enough to do something that stupid to every method.

Actually, sadly enough, there are people who are consistent enough to do something that stupid every method. I've seen that, and worse, with my own eyes.

I met a guy who at the top of every method had:

if(this == null) logger.error("Null reference");

powerlord · 2009-10-13 Reply Admin

I'm working on a project right now that has this pattern everywhere in its data access objects, and I am not allowed to remove it.

Fortunately, I was at least allowed to update it, so inconsequential things are logged at log4j info level, and moving the errors that actually mean something to the warn, error, and fatal levels.

Oh, and log4j is set to only log error and fatal level errors.

2009-10-13 Reply Admin

Carl:
Jay:
Logging every time we get a database connection from the pool or return it to the pool: Major useless. If we discover that there's a problem with pool management, it will be time to put something like this in. Otherwise, this adds tons of junk to the log files.
$ grep -v
Gosh, don't you kids know anything?

Yes, yes, if there's ONE pointless message repeated endlessly in the log files, you could grep -v it out. But what happens when there are dozens? I suppose I could write a script to grep -v out all the junk. But then, our log files role over every day at 4:00 am, and they are still hundreds of MB long. Just opening a log file in vi takes forever.

2009-10-13 Reply Admin

Sylver:
Instant classic!

Clbuttic!

2009-10-13 Reply Admin

tgape:
Bim Job:
Number Two: All the "industry-standard" logging packages I have seen, in whatever language, are barely fit for purpose. I realise that this is a grandiose claim, but I'm standing by it. They all seem to have inherited the same four brain-deal "levels" from NetView, which was yer standard over-engineered HP product. If they involve an RDBMS at any level, then sayonara, buddie.

Unix standard logging uses seven levels. Not a big improvement, but I've seen it replicated more places than I've seen any other type of logging levels. I've even used it myself a few times, when the need for debug logging wasn't much.

The next most common logging I've seen uses a bitstream to determine what is logged and what isn't. Of course, I haven't seen any standard logging package that does this; it's just a design pattern I've seen a lot of places. I use it for most of my own code.

I think we're pretty much on agreement on this. (I use a bitmask rather than a bitstream for the purpose, but the implementation is largely irrelevant.) My point, if indeed I had one, and I think I did, was that "I haven't seen any standard logging package that does this." Four levels or seven levels makes no difference to me. Quick pop quiz: what's the difference between "critical," "severe," "major," "minor," and "important?"

From the point of view of the application domain, I'd like to see "related to the comms stack," "parse error," and "DB error." Or suchlike. Easy to do if 0x00000001, 0x00000002 and 0x00000004 are used as "levels." Bonus! You can OR them together! (As you know.) You can also write a trivial filter to collect the results.

As far as I can see, there's no reason to treat the "debug" level differently. (I'd like to associate this with your comment lower down, but I'm running out of patience with the site parentheses.)

tgape:
Bim Job:
Number Three, and this is really quite important, they all apply the same deranged paradigm to the task. The code in the OP is a perfect, if extreme, example. Entry and Exit, hah!
Logging is Comments, except as audit trail after the event rather than verbiage before the compiler. Log messages should almost never be associated with the details of language implementation. Log messages should describe the application domain, not the programming domain.

For all log levels higher than debug, I agree. For debug, most should probably be in the programming domain - however, probably farther down the bitstream than most people need to go. (For example, one program I wrote uses bits 0, 1, 2, and 3 for debugging in the application domain. 4, 5, 6, 7, 8, 9, and 10 debugged various programming domain features. 11 and 12 reported hardware/OS details.)

That having been said, enter/exit debugging should only be used on complex functions. One to three line routines should probably only have an enter debug line, if they need even that much. (Exception: if the routine consists of a single if statement with no else clause, it may make sense to add another debug line - but I'd generally do it by adding an else clause and debug the 'and nothing happened' part, rather than an exit line.)

I'd comply with a group coding standard if one instructed otherwise, because I know the cost of an if not taken is very low. However, I would at least let it be known that I felt it was overkill for such simple functions.

Which is where we disagree, I guess. Entry/Exit logging should never be used. It's irrelevant to the problem/application domain, and a fuckton of low signal/noise output for the programming domain. As far as I'm concerned, it's cargo-cult logging ... I've seen it a thousand times, and I've never seen it work once.

Like the Robert Frost allusion with "the if not taken..."

Apologies to pjt33, btw. I committed the cardinal sin of engaging fingers before brain. My (very) bad.

Mind you, it's not like any of us disagree in any fundamental way. A sensible approach to logging is far more important than the average PHB (or, these days, Junior Designer) will ever comprehend.

Perhaps there is a best-selling book in this.

2009-10-13 Reply Admin

It's the disk I/O of all this logging that hits you, not the processing. At some point writing out of logging will start to clog up your I/O channels an hence puts every method invocation in an I/O wait.

I see so many slow Java apps because of silly things like this - Use SAN, log to a separate filesystem, there is a world of difference between a development Windows system with a "C:" drive and a UNIX system with SAN, active/active multipathing, and all sorts of features that simply do not seem to ever get mentioned to Java developers. These devs then see nothing wrong with logging to the same place as the data, or similar evils.

I still doubt that a 40% speedup was achieved just by removing the logging as mentioned, though - there must be more to the story than what we have been told.

2009-10-14 Reply Admin

Bim Job:
dkAllen:
The OP (IIRC) did not indicate the type of application, i.e., if it was a long-running process, or a short transactional thing. The last two decades have muddied the distinction.
Muddying, not. Standard Java Transactions, unless otherwise notified. I'm unaware of any "long-running process" that has ever been described in terms of transactions.
Please don't log to the database.

Please don't log to the database.

Blah, blah. I read dkAllen's part twice (the second time after your post), and I still fail to see where he suggested logging into the database. Or, to put it in a way more appropriate to you:

Learn to read.

pjt33 · 2009-10-14 Reply Admin

Bim Job:
Apologies to pjt33, btw. I committed the cardinal sin of engaging fingers before brain. My (very) bad.

Apology accepted.

Mind you, it's not like any of us disagree in any fundamental way. A sensible approach to logging is far more important than the average PHB (or, these days, Junior Designer) will ever comprehend.

I think there are at least two camps on what is a sensible approach to logging. At a conceptual level I do the same as you: log the events with one level for network comms, another for local file access, another for exceptions in the business logic, ... But clearly there are some people here claiming to log entry/exit at FINEST and to consider that a good idea.

2009-10-14 Reply Admin

Jay:
Just opening a log file in vi takes forever.

Ok you are obviously trolling, but a fomer coworker of mine really read all log files with vi.

I told him repeatedly how stupid that is (especially on production systems), but he never get out of that habit.

The fact that he left the team largely improved the code quality of our project.

2009-10-14 Reply Admin

OK, I'll: what's so brain-dead about severity levels? And why are the standard logging packages so dumb?

You have logs for at least three different purposes:

For debug purposes during development, especially in distributed systems where single-stepping through an IDE isn't even possible. Level=DEBUG. The more, the better, generally - the getters and setter logging here would be noisy, but a good logging package should allow you to filter those out.
For fault isolation purposes during operations. Usually, we'd be interested in ERRORS (fatal and nonfatal) and WARNINGS, enabling INFO or DEBUG as needed to drill down with repeatable faults.
For audit purposes. I wouldn't put that in an operations log; rather, I'd set up two log destinations, with business domain events going both to the operations log as INFO, and to the audit log (which by God had better be treated as sensitive information and regularly backed up).

You seem to focus on the audit purposes. Well and good, but 'logging' serves multiple concerns. Otherwise, we seem to be in agreement. And Amen! to your concluding remark -- I'll help hold them down, and possibly set the knobbly things on fire once inserted.

To conclude: the WTF is leaving DEBUG turned on in production, across an entire application, without the excuse of ongoing fault isolation. Not exactly a world-class WTF, that; I've helped track down much worse config problems caused by development and test configurations infecting production environments. Logging getters and setters is at worst a mild annoyance, especially if decent log filtering is supported.

2009-10-14 Reply Admin

Bim Job:
eViLegion:
Bim Job:
If even one person takes away the lesson from today that "logging is evil," I will hunt them down and insert knobbly things in each and every orifice.

But it is. Didn't you see that 40% performance hit? =P
I'm thinking Jerusalem artichokes, for starters. Possibly braised pig knuckles for the, ahem, entree. For dessert, may I recommend Pineapple Flambe on a stick?

Don't worry, all the entries and exits will be carefully logged.

Clogged, even.

2009-10-14 Reply Admin

A Nonny Mouse:
Anonymous:
Mothinator:
You don't "architect" something, you "design" it.
Try telling that to an architect.
or whoever wrote the dictionary

When it was dictionaristed, they must have consulted an architect.

2009-10-14 Reply Admin

Jay:
A Nonny Mouse:
Anonymous:
Mothinator:
You don't "architect" something, you "design" it.
Try telling that to an architect.
or whoever wrote the dictionary
Don't you mean, "whoever AUTHORED the dictionary"?

That's kind of true. Anyway, a word becomes a word when enough people have used it, and it then enters the dictionaries.

2009-10-14 Reply Admin

Sam:
For folks not familiar with Java logging, like the developer, an interesting feature of logger.debug() is that the implementation first checks to see if isDebugEnabled() returns true. The explicit check for logger.isDebugEnabled() should only be used when you are doing something like:
if (logger.isDebugEnabled()) {
  logger.log(Level.DEBUG, "getNamePattern() - start {0}", reallyComplexMethod());
}
That pattern avoids the call to reallyComplexMethod() if you don't need it. I've seen a coworker use this kind of pattern in non-generated code. It's obnoxious to read and debug.

Yeah, we do that at my current job. It's more often:

if (logger.isDebugEnabled()) {
  logger.log(Level.DEBUG, "complexDataModelObject: ", complexDataModelObject);
}

2009-10-14 Reply Admin

AnyNamous:
Sam:
For folks not familiar with Java logging, like the developer, an interesting feature of logger.debug() is that the implementation first checks to see if isDebugEnabled() returns true. The explicit check for logger.isDebugEnabled() should only be used when you are doing something like:
if (logger.isDebugEnabled()) {
  logger.log(Level.DEBUG, "getNamePattern() - start {0}", reallyComplexMethod());
}
That pattern avoids the call to reallyComplexMethod() if you don't need it. I've seen a coworker use this kind of pattern in non-generated code. It's obnoxious to read and debug.
Yeah, we do that at my current job. It's more often:
if (logger.isDebugEnabled()) {
  logger.log(Level.DEBUG, "complexDataModelObject: ", complexDataModelObject);
}

lol that is obviously a bit daft, but the common pattern

if (logger.isDebugEnabled()) {
  logger.log(Level.DEBUG, "complexDataModelObject: " + complexDataModelObject);
}

avoids the call to complexDataModel.toString() and the subsequent string concatenation, the pattern itself is not a WTF.

2009-10-15 Reply Admin

The real WTF is that, if he really did want that sort of logging, why he didn't just roll a bit of AOP code to do it

2009-10-19 Reply Admin

Foo:

cough #ifdef DEBUG ... #else ... #endif

Yep, you are right..

Also, in C/C++ you probably need the macro to get the FUNCTION and LINE thingy from the preprocessor.

My daily WTF is something like dudes saying. "I am a programmer. I can only program in java" .. hahahah

2009-10-20 Reply Admin

AOP, anyone?

2009-10-23 Reply Admin

@Sam

If your log message is of the form:

logger.debug("[method] X: " + x + ", Y: " + y");

then you wrap it in

if (logger.isDebugEnabled()) { logger.debug("[method] X: " + x + ", Y: " + y"); }

to avoid the StringBuffer/StringBuilder creation for the arguments, because Java doesn't do lazy evaluation, although this is a great example of where it would be useful.

Only if you have something like:

logger.debug("[foo} I am at HERE!!!");

should you not wrap with the check, even though the method itself includes the check.

2009-12-21 Reply Admin

If you're writing Java code there really is no reason why there should be much (if any) actual logging code directly visible in your source code. The easiest way to do this is to use Aspect Oriented Programming, like AspectJ for instance, which can "leave" the logging code where you need it as defined by the join points. The entire "method start, method end" type of logging could handled by a simple pointcut like: execution(* ()), which matches every return type or every class of every method with any parameters (that's what those asterisks mean).

Anyway, just read the article on http://en.wikipedia.org/wiki/Aspect-oriented_programming to get an idea of what this means.

Walter Logged

Leave a comment on “Walter Logged”