• Snarky (unregistered)

    Frist? ISTR that Log4Net is marginally quicker if you check if error is on before calling Error log. Though... really? Anyway there's piles of 'if error logging on then log error' code here too... thousands of calls...

  • Snarky (unregistered) in reply to Snarky

    Here: https://logging.apache.org/log4net/release/sdk/html/P_log4net_ILog_IsDebugEnabled.htm Though that doesn't excuse the string concatenation mess....

  • J. (unregistered) in reply to Snarky

    Well, if you construct expensive data for your log statement (i.e., not use the first form which does the string interpolation later, hopefully after the log level check), manually checking whether logging would succeed can speed up your code. But using the first form should cost around the same as having a separate check and branch, at least as long as your logging framework is halfway well written.

  • Cpt (unregistered) in reply to Snarky

    +1

    Checking for applicability of a log-line writing is encouraged when it is expensive to construct the log-message. Alternatively (with Java 8) you could think about writing a Supplier<String>, but then you'd have to write your own log.error(String, Supplier<String>) and log.error(String, Supplier<String>, Throwable).

    But the real WTF is the formatting overkill, I've once seen a variation of this: log.error(String.format("A regular string"));

  • NickJ (unregistered)

    What if getFileName() is an expensive operation? if logging is disabled, it will still be called here, and that's a waste of time:

    LOG.error("Error generating file {}", getFileName(), e);

    that's why it's good practice to check LOG.isErrorEnabled() before.

    Admittedly I'm a Java dev, not .NET, so maybe there's some .NET trickery I don't know about which renders my argument invalid?

  • someone (unregistered)

    So the other programmer didn't know off-hand the full functionality of the logging functions, and instead wrote something more long-winded that still did the job.

    Must be a slow day; this doesn't exactly elicit cries of "WTF?!"

  • (nodebb) in reply to someone

    instead wrote something more long-winded that still did the job.

    Well, the logging function is still going to do its formatting, so if by some mischance / malice / stupidity, the filename contains {}, bad things will happen, so no, he wrote something more long-winded that does the job inefficiently and potentially incorrectly and even crashingly.

  • (nodebb) in reply to NickJ

    There isn't any .NET trickery to bypass the call to getFileName if logging isn't enabled, which is why most .NET logging systems now take delegates (the closest analogue in Java is a functional interface, like Runnable) so you can pass a lambda that calls the function, or pass the function directly without calling it.

    Then again, this is Java code (System.out.println()), so maybe there's some Java trickery I don't know about...

  • Mike (unregistered)

    The if prevent the string concatenation from being performed which would be done regardless of the log level that is enabled. The token replacement method is better, but those methods were not always available in older code bases. Prior to that method being available, it was quite common to see the check for the enabled log level to prevent unnecessary operations from being performed.

  • Sven (unregistered)

    If I recall correctly in earlier versions of log4net you had to do the check yourself. So that part is not so strange.

  • eric bloedow (unregistered)

    reminds me of an old story: someone was told to write something that would help figure out what was wrong with a program...what he came up with was a stupid program that did this: if (error type one) occurs print "an error occurred". if (error type 2) occurs print "an error occurred". and so on, 30 different tests with the EXACT same response for ALL of them! completely missing the point of the tests!

  • (nodebb)

    print getFileName()

    My{}File.log

    Uh oh.

  • Eric Gregory (github) in reply to someone

    Tell that to whoever has to go back and clean all this up, generate a giant pull request that touches files throughout the project, the poor sap who has to review it, and whoever has to fix the inevitable merge conflicts when this PR is merged after a bunch of other changes inevitably go in.

  • Mike5 (unregistered) in reply to NickJ

    Wrapping your code in if-clause to avoid needlessly complex execution is so 2010. Use lambda and be done with it.

  • Pesdi (unregistered) in reply to someone

    I agree, as WTFs go, this is extremely weak. It does the job in a manner that is clear and readable and produces the correct output. It's not the right way of doing it, sure, but on a 1-10 scale of wrongness, this is like a 2, maybe a 3.

  • Jimmy (unregistered)

    I think this article reflects the inexperience of both the submitter and editor.

    Basically, look at all the comments, the post by Snarky and, for the java/log4j version, see logging.apache.org/log4j/2.0/manual/api.html (in particular the note on Java 8 lambdas, which provides a way out of it).

    The submitter, unsurprisingly, also misses the distinction between passing an exception object to the logger, which can format it they way it likes, typically including a stack trace, vs. exception.toString(), which does not include a stack trace. It may very well be that the right choice is to include a stack trace, or it may be that the original code tried to avoid the stack trace. But hey, let's make the code great again and not really think about the details.

  • Object delete. (unregistered) in reply to Steve_The_Cynic

    Didn't you always want to see your application crashing from an unhandled exception in the logger?

  • (nodebb) in reply to TwelveBaud

    maybe there's some Java trickery I don't know about...

    Java's got extremely little trickery in most of the language, and none in this area.

  • RandomPasserby (unregistered)

    In Scala you can use pass-by reference parameters to silently turn inputs into Supplier[T]'s without the caller being aware of it. So Log.error("string for {} call", expensiveOp()) is actually run in the JVM as Log.error("string for {} call", () -> expensiveOp()).

  • freaky (unregistered)

    I can see the case for the log level being checked before the actual log call if e.g. the getFileName() method is expensive and/or the log method is called a lot but the current log level would discard the message. But in this case we are talking about an error message. I don't know who would disable error logging in an application. And even so, if an application would write so many error messages that the overhead if the logging code would become an issue, I guess it would be time to question other things apart from logging...

  • Robert (unregistered) in reply to someone

    Not even long winded. The original method (checking first) is explicitly stated as the prefered method for performance critical applications in the documentation of the most widely used logging framework there is.

    TRWTF is that Graham made a huge effort and change request to make to code slightly worse than before without checking the documentation AND thought he was so right despite being wrong, that he submitted it AND Remy fell for it as well.

  • Trupik (unregistered)

    We once had a colleague, who stored his flags in negated state:

    if (isSomething == 0) { // means YES, something IS happening

    I pointed out that the standard here is the other way around and he should invert it. What he did was this:

    if (isNotSomething == 1) { // means YES, something IS happening

    At this point a capitulated, which in retrospect was somewhat poor decision, since the colleague is years gone, but his landmines still remain plaguing the code base.

  • Erica K (unregistered)

    As others have already mentioned, checking the logging level is indeed recommended before doing complex string construction for Java logging. The code was correct in that part at least

  • doubting_poster (unregistered)

    The real WTF is this WTF.... the correction is bad! The original code is recommended practice when you're in high performance code - constructing strings can eat into massive amounts of processor time if you're in loops with high volume. The 'fix' can actually completely destroy performance of applications regardless of the log levels used.

    Replacing all of the occurences of this pattern without doing an in-depth check of execution amounts is enough to get your ass fired, if the company is worth anything.

  • I dunno LOL ¯\(°_o)/¯ (unregistered)

    ...and this is where you get bitten when someone creates a file name with a '%' in it and the program mysteriously crashes, followed by Edicts From Above to never use file names with anything other than [A-Za-z0-9]

    The format string should always be a constant literal unless you really know what you're doing. It should never contain externally sourced text.

  • David (unregistered) in reply to doubting_poster

    You don't have to obfuscate your code with "ifs" just to gain performance. The idiomatic way to do it is to leverage the implicit toString() call on passed in objects. E.g. instead of getFilename() you would pass in a file object whose toString() implementation delegates to getFilename(). If the log level is not ERROR (which btw. is not a performance critical log level, this thing is more important for DEBUG or TRACE, maybe INFO in some cases) LOG.error returns right away without evaluating any of its arguments.

  • 🤷 (unregistered)

    ITT: People wondering if it's really worth saving a few milliseconds on logging in a program that runs for 30 minutes.

  • Bobby (unregistered)

    Am not sure "Graham" really understands code if he thinks this is worth posting about. But I've only been in the biz for ~20 years.

  • Bobby (unregistered) in reply to 🤷

    The fact that you think it takes ms makes me thing you need to grow a little. Who cares, even if it does take 1 ms? Writing the "if" line didn't take long, is already done, doesn't have to happen again, and it's causing more time wasted here than in the product.

  • Bobby (unregistered) in reply to Steve_The_Cynic

    You don't know what "if" means, do you?

  • (nodebb)

    Still, the poster doesn't seem to understand the point of slf4j. By using the {} notation, you can do lazy invocation of the toString() method only if the log level is high enough for the message to be printed. By putting a method invocation there, this argument is always evaluated.

    Now, in this particular case, it happens inside an exception handler, so it's not such a big deal, but it does strike me as suspicious.

Leave a comment on “An Error on Logging”

Log In or post as a guest

Replying to comment #:

Log Out

« Return to Article