• Bim Job (unregistered) in reply to pjt33
    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. Christ, for the least twenty years I've been carrying around a thousand lines of C code that does this properly. It is not Rocket Science.
    pjt33:
    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.
    You're missing a smiley. I think smileys are due a renaissance.

    Meanwhile, and directed at myself -- Whoosh!!!

    I wonder if there's a smiley for that?

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

    Nah, The OP said that their inhouse guy architected the thing and that he logged a whole lot. Knocking off the debug loggin in production was a good first step, but as the OP said, much work remains.

  • (cs)

    Where walter really got in trouble was when he added logging to the logging methods.

  • Edwin Bolthar (unregistered)

    Ahem... AOP anyone? TRWTF is about the choice of polluting the code with that crap instead of using AOP as it's supposed to be... management requiring a log with every method call (start and end) is insane but not unheard of.

  • Carlos Konstanski (unregistered)

    One word: profiler.

  • Bim Job (unregistered) in reply to PJ Volk
    PJ Volk:
    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.
    It's nothing to do with the language of choice: bad, good, or disastrously inappropriate.

    It's nothing to do with "teh Kodez not B Trust, Respeck!"

    It's to do with cleaning up afterwards. Fact(ish):

    20% of programmer effort is deployed on the original system.

    80% of (maintenance) programmer effort is deployed on correcting Teh Codez. Often, for problems that could not possibly have been detected when implementing the original product.

    This is why, on the happy occasions that I get near the early stages of a product, I fight tooth and nail over logging.

    Do you want to be woken up at two in the morning to solve a problem, only to see a log message that says "This should never happen!" If you're lucky. At least you can troll through the code to find it on line 22,461 in some obscure library you've never seen before.

    It's happened to me. Several times, over five years.

    Get another job, mate. How are you with lipstick? Alternatively, pig farmers are always on the lookout for suitable carcasses.

  • Jay (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

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

  • dkAllen (unregistered)

    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.

    For short transactions (and this is why the old slow obsolete mainframes could still process airline reservations blindingly fast -- much faster than your typical contemporary ajax-enabled ATM application) the amount of processing is ruthlessly kept to a minimum.

    A proper database pends the updates for a very short time, then writes them to the roll-forward log in one short burst. Variations exist, including roll-back vs. roll-forward, but the point is, one transaction should equal one IO. Two, if the base data isn't already in database cache, but often it is. Actual page updates don't go to disk during the transaction, they wait until later.

    Now. Insert logging. Depending upon the file system, you /may/ end up writing the entire log output in one burst, if the entire output will fit in one file system allocation unit. But this is at least two writes as well... metadata, and data. Also consider that you have many of these happening concurrently -- which the database is designed to handle expeditiously, and which the filesystem is designed not to screw up, if at all possible.

    In that environment, I would not be surprised to see a greater than 50% improvement in disabling the logging.

    Captcha: appellatio... For some reason, the name Steve Jobs comes to mind. I have no idea why.

    2nd try.

  • Jay (unregistered)

    I'm working on a system now that does huge amounts of logging. And about 90% of it is useless. Which means that every time you have to track down a problem, you have to hack your way through megabytes worth of useless drivel.

    Logging every query before you execute it: Very useful. It lets us see exactly what the query was that blew up.

    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.

  • Beaker (unregistered) in reply to Sylver
    Sylver:
    Instant clbuttic!

    FTFY

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

    For short transactions (and this is why the old slow obsolete mainframes could still process airline reservations blindingly fast -- much faster than your typical contemporary ajax-enabled ATM application) the amount of processing is ruthlessly kept to a minimum.

    A proper database pends the updates for a very short time, then writes them to the roll-forward log in one short burst. Variations exist, including roll-back vs. roll-forward, but the point is, one transaction should equal one IO. Two, if the base data isn't already in database cache, but often it is. Actual page updates don't go to disk during the transaction, they wait until later.

    Now. Insert logging. Depending upon the file system, you /may/ end up writing the entire log output in one burst, if the entire output will fit in one file system allocation unit. But this is at least two writes as well... metadata, and data. Also consider that you have many of these happening concurrently -- which the database is designed to handle expeditiously, and which the filesystem is designed not to screw up, if at all possible.

    In that environment, I would not be surprised to see a greater than 50% improvement in disabling the logging.

    Captcha: appellatio... For some reason, the name Steve Jobs comes to mind. I have no idea why.

    2nd try.

    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.

    Keeping your hilarious interpretations of a captcha to yourself would be a welcome benefit ... although admittedly not on the lines of unrolling a TPF loop.

    Please don't log to the database.

    I don't know how many times I have to tell you this.

    Please don't log to the database.

    The performance sucks, it isn't what logging is for, and furthermore it is almost impossible to retrieve useful log information from a database.

    Please don't log to the database.

  • NH (unregistered)

    There is a fine balance between too much and too little logging.

    With a sufficient amount of logging you are able to resolve bugs a lot faster but too much is obviously slowing down the system.

    But logging every method entry/exit without regard to call frequency or how critical it is is just stupid.

  • (cs) in reply to Jay
    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"?

    whoever logged the dictionary

  • Henning Makholm (unregistered)

    On the other hand, if your running time is dominated by a pure log term, you know your algorithm will scale well. :-)

  • ya hahahaha (unregistered)

    Umm, was that Log4J code?

  • Franz Kafka (unregistered) in reply to Henning Makholm
    Henning Makholm:
    On the other hand, if your running time is dominated by a pure log term, you know your algorithm will scale well. :-)

    Oh god, I'm in an algorithm analysis class right now!

  • Zork II (unregistered) 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.

    Now what did Einstein (or was is Arthur C Clarke?) say about human stupidity?

    Trust me, there are people who do that...

  • ShakedownSt (unregistered)

    What a Java newbie...

    That should be:

    void meth( String arg ) { logger.entering( this.getClass().getName(), "meth", arg ); // ... logger.exiting( this.getClass().getName(), "meth", arg ); }

  • (cs)

    Oh, I see.....

    public class logger() {
  static boolean isDebugEnabled() {
    boolean result = db.create(Conn).exec("SELECT VALUE FROM TBL_PARAM WHERE NAME='isDebugEnabled'");
    return result;
  }

  static boolean debug(string text) {
    db.create(Conn).exec("INSERT INTO TBL_LOG VALUES('" + text + "')");
  }
}
  • Outtascope (unregistered) in reply to Bim Job
    Bim Job:
    To turn a noun in to a verb...

    Don't you mean "To verb a noun" ?

  • Donny (unregistered) in reply to Madball

    Must... restrain... fist... of... death..

  • (cs) in reply to Outtascope
    Outtascope:
    Bim Job:
    To turn a noun in to a verb...

    Don't you mean "To verb a noun" ?

    FTW !!!

  • Goo (unregistered)

    It could be worse. He could have written a custom logger system that went like this:

    void log(Level logLevel, Object message){ if(isDebugEnabled()) { log(debug, "Attempting to log " + message); } javaLogger.log(logLevel, message); if(isDebugEnabled()) { log(debug, "Finished logging " + message); } }

    I've seen that code get to system testing, and I ended up discovering it when, trying to solve a problem, I set the global log level to debug.

    The poor former trainee still gets crap for this, 10 years later.

  • PJ Volk (unregistered) in reply to Bim Job

    Exactly my point. I conclude from the debug code, that either the developer didn't trust their work, or they never got around to cleaning up from unit testing.

    If you think nothing could be done, you're mistaken. Many things in retrospect ASK for trouble. If you're in maintenance, try playing code pathologist. Why did they do that?

    Logging is good, when it's useful. But giving tickets when someone enters a tunnel, and collecting it when you leave is not particularly useful. You know thoughtful logging when you see it... I hope (hint: 02:05.03.003 - All is well .004 - All is well .005 - This shouldn't happen. There's a difference between info and noise. There's also a difference between real problems (i.e. the problem the program is trying to solve), and artificial problems (the bug that crashes the logging system, which the customer doesn't see, but takes 40% of the system resources... Do you think the System Architect factored that into their system specs? Or are you one of those arrogant idiots that sees the 50% overspec, and thinks it's for them, and not for when they double the users, or the database size?)

    I know, you know everything. You've been in the biz a whopping 5 years. Met a customer once, did you? (Year 23 for me - started in test, developer/PM now)

  • Mike (unregistered) in reply to Mothinator
    Mothinator:
    You don't "architect" something, you "design" it.

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

    Sorry, "architect" is now a verb. This issue is now officially wordsmithed.

    CAPTCHA: minim - truly minimalist?

  • Gumpy Guss (unregistered)

    It's hard to know how much logging you're going to need, so I usually log with a priority level. Things that happen at the lowest levels are logged at priority 0, so you never see those unless you ask for them. With a default clipping level of 2 or 3, a good 90% of the log messages are surpressed, leaving you with a manageable subset of messages.

  • Foo (unregistered) in reply to Steve Burnap
    Steve Burnap:
    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

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

  • Sam (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).

    You only need error logging when you have errors in your program.
    The l33t among us write programs without errors, so writing code to log errors is a waste of everybodies time. It's called robust code.

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

    A) they probably didn't measure, some bright spark just said 'Wow - that must be 40% faster' ("42% of people know all statistics are made up" - Homer J Simpson (roughly) B) 40% of what? C) Other things that I have now forgotted D) Yawn!!!

  • (cs) in reply to Sylver
    Sylver:
    Instant classic!
    Did you mean "Instant clbuttic!"?

    Edit: Beaten to the punch. Darn.

  • (cs)

    I'd like to comment on this WTF. Here is the first sentence of my comment. Yes, logging is good, but I've never found it necessary to log absolutely every method call. I'm done with the first part of my comment so here is my next sentence. You end up with overly verbose logs that just make it difficult to find an issue when someone has a real error. That's all I wanted to say in the second part of my comment and that's it for my comment on this WTF.

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

    Please explain how logging initiates disk inputs.

  • Dopey (unregistered)

    I've seen developers who log in time senitive paths without thhought to the time implications of logging. I work with them today, every day, they are everywhere.

    I've seen developers who wont log in time insensitive, function critial, paths "because it's a performance drain". I work with them today, wvery day, they are everywhere.

    I've seen developers who way lyrical about wrapping time insensitive log.debug in if (log.isDebugEnabled()) and 99% of the time get it right, but 1% of the time mess up the flow control, and in so ding self invalidate. I work with them today, every day, they are everywhere.

    In the end of the day, what most of all I've seeb, is developer output log to discover how the code mught behave. This becomes the product, and the support crew are understandably dum-founded. There is always a background project (support driven), never resourced (not sales driven), to "clean up the logging".

  • spike (unregistered) in reply to bsiegel
    bsiegel:
    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).

    alternatively you could have something like

    public class EntryExitLog
{
EntryExitLog(...) {logger.debug(...)}
~EntryExitLog(...) {...}
}

    then you wouldn't need the try/finally, but you would still see the logs in the face of exceptions

    it seems that this may be a case of applying a coding style designed for one type of coding paradigm to code written under a different paradigm. I used to see a lot of this kind of logging when normal debugging facilities were either unavailable or unusable.

    one advantage i can see is that you have a record of the complete call tree, not just the current stack trace you would get with a debugger.

    one major problem with this kind of logging is that ones logs can get very large, to the point that they may become useless.

  • Mac (unregistered)

    My turn to get on a soapbox....

    There are two types of logging to consider: Error Logging Debug Logging

    Error Logging logs Errors (wow!). This means ONLY error conditions should appear in an error log. If the log is filled with noise from errors that we ignore, it becomes very difficult to find real errors. If we plan to ignore errors in the log (especially long term), then the logging of these errors should be removed (no point noting that something we don't care about just happened).

    Debug logging should have variable level and log information about where in the code we are, how we are going and perhaps what the values of some key variables in that function are (depending on the set level). The twats that suggest "#ifdef DEBUG" should first realise that (in this case) we are talking Java (which I don't think has these compiler directives) and secondly this is the WRONG approach anyway. Why? The biggest use for debug is incident/problem investigation and resolution. This should not be a compiled option (ie there shouldn't be two separate binaries on a system that do roughly the same thing (but different). How do you know if the debug is up to date with the non-debug? Rather, debug should be able to be turned on (eg restart a daemon with a flag indicating debug level or something). In this way, the debug is available to some poor person on support duties, and is definitely the current version. Debug should not be permanently on - aside from implying you don't trust your system (and won't be able to recreate problems) it causes overhead and increases the likelihood of unrelated errors - eg debug log fills disk or exceeds max file size etc).

    The real trick (which is by no means easy, if even possible) is to create debug which doesn't affect the running of the system. Too often, debug mode behaviour is (unintentionally) different from non-debug (especially, it seems, when the problem lies in memory management - although this would not be as much a problem Java).

    Logging for the sake of logging is stupid, and rather than logging "Entered myMethod", etc, why not set a variable to hold the method name at the beginning of the method, and display this at every debug/Error print (this way you can see which method you are in and where you came from without having to scroll back to see). An example of debug logging might be:

    Oct 12 12:13:12 2009: processFile: readFromFile [temp.txt] Oct 12 12:13:12 2009: readFromFile: opening [temp.txt] Oct 12 12:13:12 2009: processFile: read 156752 Bytes Oct 12 12:13:12 2009: callingProcess: read from [temp.txt] buffer begins [It was a cold and fr]

    (this might be excessive and slow, however we would have options to reduce the debug level, and let's not forget that debug is only on in the case that a developer is currently looking into a problem - ie, generally short term).

  • (cs) in reply to Outtascope
    Outtascope:
    Bim Job:
    To turn a noun in to a verb...

    Don't you mean "To verb a noun" ?

    You're both wrong.

    [image]
  • Col Obvious (unregistered)

    Not read all the comments so this has probably been pointed out already, but TRWTF is that debug level logging was turned on in production code.

  • Bim Job (unregistered) in reply to Col Obvious
    Col Obvious:
    Not read all the comments so this has probably been pointed out already, but TRWTF is that debug level logging was turned on in production code.
    It may not help your dismal career prospects, but I'd suggest that you read the comments first.
  • Carl (unregistered) in reply to Jay
    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?
  • (cs) in reply to Bim Job
    Bim Job:
    Do you want to be woken up at two in the morning to solve a problem, only to see a log message that says "This should never happen!" If you're lucky. At least you can troll through the code to find it on line 22,461 in some obscure library you've never seen before.

    The real problem with this sort of logging happens when you grep for 'This should never happen', and you find that it occurs 1,386 times over the 52,964 lines of the file - making it the second most common line in the file (the most common, of course, being a lone closing curly bracket, as the programmer felt that vertical whitespace is for losers.)

    I've not experienced anything quite that bad, mind you - the worst I've personally encountered was a program where that error output could originate from about 200-300 different lines across 20 files.

    On another note: please, never log directly to a database. Please correct any code that logs directly to a database to log to a regular file. (Note: it is acceptable to log to a flat file and a database (for example, something like Splunk); the problem is where one must utilize a database access protocol to get to the logs. An exceptionally gratuitous case of this issue is the error message 'cannot connect to database', which should never be sent directly to the database. I hope the reasons for this are obvious.)

  • Col Obvious (unregistered) in reply to Bim Job

    Explain? What do you think is the purpose of 'Debug' level logging? Ok maybe logging getters and setters is excessive, but i'd rather have plenty of logging information available (for example if you aren't doing the testing and a fault is raised by the testing team), thats better than having no clue as to where the error occured and having to start from scratch with a debugger. With regard to the pattern (checking for level first), that's common if the logging parameter is more expensive than the check, and really should not impact performance. Are you suggesting that debug level logging code should be removed from production code altogether? If your just saying logging getters and setters is overkill then fair enough but I still say the RTWTF is that debug level logging was left on in production code - note he got a 40% increase in performance when it was turned off.

    P.S. my career is doing fine and dandy thank you very much

  • (cs) in reply to Carlos Konstanski
    Carlos Konstanski:
    One word: profiler.

    Most profilers I've encountered do not report problems with code which is spread across every single routine (aka function, subroutine, or method) - they only report how much time is spent within each routine.

    Some of the profilers I've encountered will also only report the processor time spent, not the I/O time; such a profiler could miss this entirely.

    My point is not that profilers won't work, but you need a good profiler for this.

  • Curious George (unregistered) in reply to tgape
    tgape:
    Carlos Konstanski:
    One word: profiler.

    Most profilers I've encountered do not report problems with code which is spread across every single routine (aka function, subroutine, or method) - they only report how much time is spent within each routine.

    Some of the profilers I've encountered will also only report the processor time spent, not the I/O time; such a profiler could miss this entirely.

    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?

  • Buzzard (unregistered) in reply to Martijn Lievaart

    I have seen a system brought to its knee's due to the fact that the idiot who configured log4j did not have circular logging set up. 90% of available disk space was consumed with logs, so the 40% performance degradation mentioned is very believable.

  • Buzzard (unregistered) in reply to Edwin Bolthar

    While I like AOP and lots of examples use logging as a typical scenario, AOP is not without it's disadvantages.

    Introduces extra wrapper classes that have to be generated and compiled on the fly ( aspectJ at least, when u weave your aspect ).

    When developing in eclispe, I find AOP a real drag as it seems to slow things down significantly, while log4J does not.

    Still AOP would have worked here.

    Nice suggestion.

  • Laughing Jack (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.
    I love it when you talk dirty.
  • flob9 (unregistered)

    public static function isDebugEnabled() { // query database for xml file name ... // parse the xml file ... // return debug boolean return bDebug; }

  • OliverWhite (unregistered)

    The real WTF is he wasn't using aspects.

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

    There will be a savings anytime you use that pattern, even if it is just writing a plain string (creating the String object, and either garbage collecting it or storing it in the string pool). I just did a quick test using a logger that does nothing more than log a string literal appended with an integer and the version that had the guard outside of the log block was consistently well over 10 times faster (though that's a small fraction of the savings you get compared when logging is actually enabled and it has to actually write those messages). Now normally its not going to be worth the effort to do this (in my test, even logging a million times the unguarded version took less than half a second), unless you happen to have a macro of some sort in your IDE to do this. Which in this case if they have this many logging statements, they probably did.

    Oh, and when in a method that gets called often, reallyComplexMethod doesn't have to be that complex to make a noticeable difference. A very common log message would be something like logger.log(Level.FINE, "received object "+myObject). That could have a significant performance hit if the implicit myObject.toString() is slow.

  • (cs) in reply to Anon-y-mouse
    Anon-y-mouse:
    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!

    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...

Leave a comment on “Walter Logged”

Log In or post as a guest

Replying to comment #:

Log Out

« Return to Article