• Madball (unregistered)

    if (logger.isFristEnabled()) { logger.debug("setSetFristPattern(String)-start"); logger.debug("Frist!"); logger.debug("setSetFristPattern(String)-end"); }

  • Anon (unregistered)

    function writeString (string) { logString(string); return string; }

    function logString(string) { log = log + writeString(string); }

  • Mike (unregistered) in reply to Anon
    Anon:
    function writeString (string) { logString(string); return string; }

    function logString(string) { log = log + writeString(string); }

    Infinite-loop warning! Performance may be affected.

  • (cs)

    The really sad thing is that all of that logging was even more useless than it already appears. Throw an exception and you bypass the exit messages, meaning that you have an utter nightmare trying to match exit messages with entry messages.

  • SpasticWeasel (unregistered)

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

  • Sylver (unregistered)

    Instant classic!

  • (cs) in reply to SpasticWeasel
    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.

  • Sam (unregistered)

    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.
  • Julian Calaby (unregistered)

    Hahaha.

    No.

    I have hacked on some code that had a several thousand line class that not only contained it's own database abstraction layer and logging functionality, but had "entry" messages for every single method.

    And I know for a fact that it wasn't generated code. The person who wrote it wasn't that smart.

    Hacking it to use the system logging class, cleaning up the duplicated methods, cutting all the unnecessary messages (like "****** markTrustTransactionPaid() ---- ENTRY ****") and generally spring cleaning the class cut a couple of thousand lines out of it, but it's still more than 2000 lines of code.

    And it still makes me shudder.

  • leppie (unregistered)

    His name is not Walter, it is XXXXX and it works with me!

  • Anon-y-mouse (unregistered)

    I've done work for "a large financial transaction company" who insisted on a very similar logging style in their systems.

    Every single public method of every class had "Assembly.Class.Method() Entry" and "Exit" logged, along with parameters and return values - in production code.

    We tried to protest. We tried to educate. But they were very insistent.

    So next time it takes 5 minutes for the ATM to give you cash, you'll know why!

  • (cs)

    I have, in fact, been forced to write code similar to this. It was one of the coding standards requirements for this project I once worked on.

    I was able to successfully argue that while it sometimes made sense to log entry and exit from functions, it did not make sense to do so on every function, getters and setters included. Once the standards people understood that this wasn't C code, and thus not every function had such a useful purpose, they relented.

  • RBoy (unregistered)

    Would this be considered a speed up log?

  • grzlbrmft (unregistered)

    Alright, for those accessor methods this is a bit of overkill. On the other hand the way it is implemented here should really not make a noticable performance difference.

    What really can cause trouble is when those parameters are not simple Strings but complex objects with complex toString() methods and when the methods are called really often. (like TreeCellRenderer#getTreeCellRendererComponent)

    Conclusion: minor WTF, if at all.

  • Anon (unregistered)

    Seems like a fine pattern to follow. Maybe a bit of overkill. Maybe not, depending on requirements. I would turn off debug log messages for production.

  • Joshua (unregistered) in reply to SpasticWeasel

    You haven't met many Java developers...

  • Anonymous (unregistered) in reply to grzlbrmft
    grzlbrmft:
    Alright, for those accessor methods this is a bit of overkill. On the other hand the way it is implemented here should really not make a noticable performance difference.
    It clearly said in the article that disabling debug reaped a 40% performance improvement. Are you calling Alex a liar?
  • Brompot (unregistered)

    This guy built his own profiler. Without all the advantages of an actual profiler, like being able to turn it off.

  • Brompot (unregistered) in reply to grzlbrmft
    grzlbrmft:
    Alright, for those accessor methods this is a bit of overkill. On the other hand the way it is implemented here should really not make a noticable performance difference.

    What really can cause trouble is when those parameters are not simple Strings but complex objects with complex toString() methods and when the methods are called really often. (like TreeCellRenderer#getTreeCellRendererComponent)

    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.

  • ned (unregistered)

    I've got to say this is far better than what the company I currently work for has for logging - which is absolutely none at all (including error logging).

  • grzlbrmft (unregistered) in reply to Anonymous
    Anonymous:
    grzlbrmft:
    Alright, for those accessor methods this is a bit of overkill. On the other hand the way it is implemented here should really not make a noticable performance difference.
    It clearly said in the article that disabling debug reaped a 40% performance improvement. Are you calling Alex a liar?

    Definitly not. Of course when debugging is on there must be a performance decrease.

    I should have made clear that there should not be a significant performance difference between a method following this pattern and a method not following this pattern. Got it now?

  • Optimus Dime (unregistered) in reply to Anon-y-mouse

    Logging get/set functions is a bit extreme, but this pattern is hardly a TDWTF. I've personally done this to help solve problems with multi-server IVR software that would allow, for example, conference calling. The 'errors' that would occur wouldn't be simple exceptions, they would be 'people showing up in the wrong conference', so extensive logging of what is going on was about the only way to solve the problem.

    Further, if your error is going to cause multiple people to be affected, (or in the case of Anon-y-mouse, multiple people to lose lots of money), it strikes me as a bit irresposible to avoid logging as extensively as possible.

    Finally, historical tracability can, at times, require this kind of logging. In production code. No matter how much this might slow down your clever algorhithm.

    captcha: minim
    The amount you seem to care about solving obscure bugs.

  • NightKhaos (unregistered) in reply to grzlbrmft

    And yet when logging was turned off they noted a 40% performance increase?

  • Herman (unregistered)

    Why didn't he log halfway?

    It's like asking my how far I'm on my way to my parents house and I'm only able to say I've started or ended my journey.

    There should be a loop in there in a seperate thread keeping track of the progress of the returned string bit for bit.

    ABIGO - When you try to say amigo with a cold.

  • Murf (unregistered) in reply to Anonymous
    Anonymous:
    It clearly said in the article that disabling debug reaped a 40% performance improvement. Are you calling Alex a liar?

    This really isn't that bad - it's not the isDebugEnabled() check that'd kill the performance, it's the IO bottleneck in writing all that rubbish to disk, and debug should be off in production anyway.

    Really, I'd rather someone over-log, which I rarely see, than under-log, which I see everyday.

  • virgil (unregistered)

    Right, so he overdid it a little? This is the big WTF? A bigger WTF is to have production systems with very little or no logging. You can easily disable logging in production. The WTF is maybe the fact that he didn't have "severity levels" in logging... but again, it's far from being a "classic wtf" as some suggested.

    And about the other user comment, that it doesn't help in case of exception.... well, in fact, it does; an exception is not something that typically goes unnoticed in a log. And when you match the "entry" with "exit", you also have a clear picture of how many levels up the exception traveled.

  • grzlbrmft (unregistered) in reply to NightKhaos
    NightKhaos:
    And yet when logging was turned off they noted a 40% performance increase?

    My bad - communication failure. See here

    WTF:

  • Bim Job (unregistered) in reply to ned
    ned:
    I've got to say this is far better than what the company I currently work for has for logging - which is absolutely none at all (including error logging).
    Logging is one of the most misunderstood areas of programming. Trivial, but misunderstood.

    Number One: despite what the OP implies, this has nothing whatever to do with "architecture." The guy hasn't even built his own logging infrastructure, for chrissake. (And I'm not saying he should...) I normally get hives when I hear the words "Java" and "architecture," but not in this case.

    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.

    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.

    Sorry for the huge amounts of emphasis, but this stuff is beginning to bug me. I've cowritten a 4000 TPS system, and it was chock full of logging. In useful places. And, filtered for "debug," left fully functional in production.

    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.

  • Ruth (unregistered)

    Oh help.

    This is the application I'm working on right now.

    looks suspiciously around at team members

  • eViLegion (unregistered) in reply to Bim Job
    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

  • Steve Burnap (unregistered)

    Honestly, it could be worse. Two decades ago, I had a very similar task in C code that was traced to the following macros:

    #define BEGIN(FUNC) \
{ PUSH_NAME(FUNC); LOG("Entering %s\n",FUNC);

#define END(FUNC) \
{ POP_NAME(); LOG("Leaving %s\n",FUNC);

    Yes, every function did look like this:

    int myfunc()
BEGIN(myfync)
    /* Code */
END(myfunc)

    It was written by a contractor.

    Though actually I shouldn't say "could be worse" because it was this and crap like it that let me look like the hero by speeding up the app by a couple orders of magnitiude

  • Mothinator (unregistered)

    You don't "architect" something, you "design" it.

    And, yes, I know I'm a grammar nazi.

  • Bim Job (unregistered) in reply to eViLegion
    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.

  • Martin (unregistered) in reply to Sam
    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"

  • CW (unregistered) in reply to SpasticWeasel

    This is generated by a logging plugin for Eclipse called Log4E. A great plugin with many handy features; of which, can toggle the placement of such "automatic log statements" and can apply them on a project/package level... as well as remove them. A simple two clicker

  • Anonymous (unregistered) in reply to Mothinator
    Mothinator:
    You don't "architect" something, you "design" it.
    Try telling that to an architect.
  • Dark Sun (unregistered) in reply to Bim Job

    I personally prefer overly verbose logging over speechless systems that don't give you any clue when somethings goes wrong, where it goes wrong.

    The only WTF I can see is that verbose logging seems always to be enabled. Log levels are one method for filtering too many log messages (if the compiler was smart, it inlined the log calls anyway), the other method is to use C style #defines/maybe also Java consts to tell the compiler not to include these log messages at all.

    I find the 40% increase performance increase hard to believe, because log messages are usually bufferd (not flushed) before they are written to disk in one chunk. Hence the performance toll is not so big or the application was not as slow as the article suggests.

  • Anonymous (unregistered) in reply to grzlbrmft
    grzlbrmft:
    Anonymous:
    grzlbrmft:
    Alright, for those accessor methods this is a bit of overkill. On the other hand the way it is implemented here should really not make a noticable performance difference.
    It clearly said in the article that disabling debug reaped a 40% performance improvement. Are you calling Alex a liar?

    Definitly not. Of course when debugging is on there must be a performance decrease.

    I should have made clear that there should not be a significant performance difference between a method following this pattern and a method not following this pattern. Got it now?

    Not really. Could you try it again, this time with a little more feeling.
  • Average Luser (unregistered) in reply to Mike
    Mike:
    Anon:
    function writeString (string) { logString(string); return string; }

    function logString(string) { log = log + writeString(string); }

    Infinite-loop warning! Performance may be affected.

    What, with all that progress and advances in computers, you're telling me they can't log a string to a file?

    Captcha: damnum

  • (cs)

    There's not really that much wrong with the logging. Heck, I even wrote a little library that does the entry and exit logging for certain operations (not methods, that's not really that useful) automatically, storing it in a collection from java.util.concurrent and using the thread ID as the key.

    Not because I thought it was such a jolly idea, but because the support people very specifically asked for it. They wanted this amount of logging.

    Then, when I delivered it, they thought there was perhaps a little too much logging going on, but hey, that's what they asked for.

  • Anonymous Coward (unregistered) in reply to Steve Burnap
    Steve Burnap:
    #define BEGIN(FUNC) \
{ PUSH_NAME(FUNC); LOG("Entering %s\n",FUNC);
#define END(FUNC) \
{ POP_NAME(); LOG("Leaving %s\n",FUNC);
    That is why they invented #ifdef and friends. You can compile it out: 
    #ifdef DEBUG
#define XXX YYY
#else
#define XXX
#endif
  • bsiegel (unregistered) in reply to pjt33
    pjt33:
    The really sad thing is that all of that logging was even more useless than it already appears. Throw an exception and you bypass the exit messages, meaning that you have an utter nightmare trying to match exit messages with entry messages.

    Ah, you're right, this is much better:

        public void setNamePattern(String namePattern) {
        if (logger.isDebugEnabled()) {
            logger.debug("setNamePattern(String) - start");
        }
        try {
            this.namePattern = namePattern;
        } finally {
            if (logger.isDebugEnabled()) {
                logger.debug("setNamePattern(String) - end");
            }
        }
    }

    And as a bonus, if the Java compiler is anything like the .NET compiler with which I have some familiarity, this will prevent the compiler from performing any optimizations within the try block (which in this instance would be the entire contents of every method).

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

    Just allow me to pat my Erlang trace primitives and smile smugly at the Java dweebs, OK?

  • Anon (unregistered) in reply to CW
    CW:
    This is generated by a logging plugin for Eclipse called Log4E. A great plugin with many handy features; of which, can toggle the placement of such "automatic log statements" and can apply them on a project/package level... as well as remove them. A simple two clicker

    That would be good had our equivalent of Walter used it. It wasn't quite as bad as having these on every accessor, but they were on 90% of the methods. Sometimes, the problems with exceptions as was indicated by ptj33 was solved by needless try/finally blocks. Oh and you should have heard the howling when I and the other sane developers began to remove them.

  • (cs) in reply to virgil
    virgil:
    And about the other user comment, that it doesn't help in case of exception.... well, in fact, it does; an exception is not something that typically goes unnoticed in a log. And when you match the "entry" with "exit", you also have a clear picture of how many levels up the exception traveled.
    That's back to front. If you have a clear picture of how many levels up the exception travelled then you can match the "entry" with the "exit". Otherwise recursion (or methods with the same names, or calls to super.thisMethod in overriding methods, given the implementation in the article) means that your logic to match entry to exit quickly requires complex heuristics.

    To keep the matching simple either the code which logs catching the exception has to say how many levels were skipped (doable, but there's no evidence that it was done here), or you need a complex try-catch-finally setup (more complex than bsiegel's, although that's on the right lines: you really want to know whether you exited normally or abnormally).

    Besides all that, if you really insist on logging entry and exit to every method in Java then the sensible thing to do is to learn enough Aspect-J to do it all in an aspect without cluttering your main code and creating maintenance consistency nightmares.

    bsiegel:
    And as a bonus, if the Java compiler is anything like the .NET compiler with which I have some familiarity, this will prevent the compiler from performing any optimizations within the try block (which in this instance would be the entire contents of every method).
    AIUI the Java JIT does a lot more than the .NET one. I'm pretty sure it isn't put off by try blocks.

    PS In constructing and submitted this post I was sent twice to the error page, which mentions that "Not sure what it was, but it was logged." Maybe part of the reason this site is slow to load is that the server's disk is fragmented by 5TB of error logging.

  • Martijn Lievaart (unregistered) in reply to Dark Sun
    Dark Sun:
    I find the 40% increase performance increase hard to believe, because log messages are usually bufferd (not flushed) before they are written to disk in one chunk. Hence the performance toll is not so big or the application was not as slow as the article suggests.

    You never tried this, did you? If the logging is not buffered (or flushed at every record) you have a application that is standing still, not just 40% slowdown.

    I would go further, the fact that it slowed the application ONLY 40% shows the application did other I/O intensive work, otherwise it would have been much worse.

    Which does not mean logging is bad, just that you should be aware of the performance hit copious logging can bring about. M4

  • Bim Job (unregistered) in reply to A Nonny Mouse
    A Nonny Mouse:
    Anonymous:
    Mothinator:
    You don't "architect" something, you "design" it.
    Try telling that to an architect.
    or whoever wrote the dictionary
    There's a good reason not to "dictionary" something, and it's the same reason. (Please don't make me think about "Johnsoning.")

    To be fair, I suppose that "to dictionary" would be a special case. At least, with "to architect," you can be pretty sure that the presumed architect in question has signed off on the plans (never mind all the other things that architects might or might not do ... let's not lose a truly useful verb-o-noun purely on the basis of oversimplification).

    I propose that "to dictionary" is far more appropriate when referring to

     - 3 architected results
Dictionary (etc etc etc)
dic⋅tion⋅ar⋅y  [dik-shuh-ner-ee]  Show IPA
–noun
    

      

    1. one huge mutha of a book.  All the words fit to speak, and then some!
–verb (used with object)
      2. 

    2. to make a pointless reference to one of several random URLs on the Web purporting to be long-standing authorities on the subject of etymology.
(See also: being a ninny.)
    Bottom line: verbs can traditionally be turned in to nouns with very little loss of information -- in fact, this is precisely the purpose of a gerundive.

    To turn a noun in to a verb, however, is almost certain to lose information. What, precisely, did Le Corbusier "architect"? And how?

    I'm also fascinated by Akimsa's concept of "spam." I wonder whether the word "spam" will get through? Apparently, the First Amendment ain't doing too well in the brave new world of the Internet...

  • Anonymous Coward (unregistered)

    The basic idea makes sense, and depending on how you configured the logging, this style could have had no I/O bottleneck at all; you can send it to an in-memory buffer and then flush hundreds of events at a time to syslog, and have that deal with it.

    The real WTF is that Log4E was set up to generate logging on getter / setters, and the system was configured with the logging level turned up to DEBUG in production.

  • PJ Volk (unregistered)

    Maybe auto tunnels need to make sure that every person that enters, leaves. Logging is good, logging is bad, yadda yadda. Excessive logging tells me that the code is not trusted. The people that do this will go on chapter and verse on how great their language of choice is.

Leave a comment on “Walter Logged”

Log In or post as a guest

Replying to comment #:

Log Out

« Return to Article