6 ms·

Oh yes, I’ve seen several programs that spend ~30% of their CPU cycles formatting strings that are immediately thrown away because the log level is not high eno

• dmurray 5y ago
  In Java? Surely one of the benefits of the JIT is to compile logger.debug() into a no-op if the log level is not high enough.
  • clon 5y ago
    You would still be doing the job of concatenating together the error message, possibly rendering some complex objects to a string, that is then fed to the no-op. The point parent was making is that there is also a performance aspect to this, in addition to the security aspect.
    • chrisseaton 5y ago
      > You would still be doing the job of concatenating together the error message, possibly rendering some complex objects to a string, that is then fed to the no-op. Why would you still do be doing that work? If a value goes into a no-op, then the value isn't computed. (In theory - I'm sure it doesn't always work out 100% of the time in practice.)
      • christophilus 5y ago
        Unless the JVM is sure the logic is not effectful, it couldn’t eliminate it.
        • chrisseaton 5y ago
          The JVM knows what string concatenation does.
          • envp 5y ago
            But what if one of the arguments is a function call? Then it isn't easy to prove there are no side effects
            • chrisseaton 5y ago
              If it’s too big to in-line then yes.
              • vlovich123 5y ago
                That’s says absolutely nothing about whether the function has a side effect.
                • chrisseaton 5y ago
                  If you can inline it into the compilation unit, then you can see if it has side effects or not.
                  • deleted 5y ago
                    [deleted]
          • alserio 5y ago
            Isn't the point that you don't generally stuff your log of things that are only strings but of things that can become strings? (Asking since I know of your work with truffle)
            • chrisseaton 5y ago
              I assumed things like the names of resources that are already strings because you’re using them in the actual program?
              • alserio 5y ago
                A typical logger.info("user {} did the thing", user) can skip the actual string interpolation and user value stringification, if the log level is not > info. However, logger.info("user " + user + " did the thing") cannot avoid at least the execution of user.toString(), even after jit optimizations, unless the jit could prove that toString does not have side effects. But I don't believe the jvm jit tries to do that. Am I wrong?
        • mumblemumble 5y ago
          There's an even simpler reason why the JIT compiler can't prune it: it's possible to dynamically change the logging level at run time.
          • barrkel 5y ago
            That is actually a reason that a JIT compiler can prune where an AOT compiler can't. JIT can deoptimize when assumptions change. One of the bigger wins with the JVM is assuming that a virtual method can be called statically if there are no derived classes. That's a huge win for every leaf class in the class tree. The assumption can change every time a class is loaded of course. The optimization is called devirtualization and it can be combined with inlining to get even bigger wins.
            • mumblemumble 5y ago
              Fair point... but it seem like, even so, doing that to monitor whether a single integer variable might change sounds like a lot of added complexity. Are there other use cases that would help to justify it? Reducing the impact of failing to follow logging best practices doesn't seem like an obviously sufficient cause.
              • chrisseaton 5y ago
                It's a standard part of the JVM https://docs.oracle.com/javase/7/docs/api/java/lang/invoke/SwitchPoint.html https://docs.oracle.com/javase/7/docs/api/java/lang/invoke/S....
  • isbvhodnvemrwvn 5y ago
    Logger levels are mutable to allow switching them at runtime, JIT can not make an assumption that the log level will stay the same.
    • akvadrako 5y ago
      Sure it can, since the JIT has access to runtime information and all the code. It could reorder the steps so first the log level is checked, then that block is run.
      • hamburglar 5y ago
        log.debug(“foo count: “ + fooHandler.incrementAndReturnFooCount()); Should the JIT call incrementAndReturnFooCount if debug logs are disabled? This is a long-recognized pitfall of C preprocessor macros that look like function calls but may simply be defined away, causing unexpected behavior.
        • akvadrako 5y ago
          It should call it if it has side effects, otherwise not. Java isn't C; the runtime can be a lot smarter.
          • hamburglar 5y ago
            I guess I’m not up on the state of the art with respect to the JRE’s ability to determine whether arbitrary code has side effects. That’s quite a broad problem. If I write fizzbuzz but use log.debug for output, does it optimize my main() to be empty unless I run it with debug enabled?
    • alserio 5y ago
      I believe the problem is just that the toString methods implicitly called when concatenating strings and objects, can execute side effects. And the JIT has to keep those effects if it cannot prove they are just heating up your CPU
  • millerm 5y ago
    How could it? The log level is not a constant. It is evaluated at runtime, every time. You can’t compile that out. Am I wrong?
    • alserio 5y ago
      The JIT works by making assumptions using runtime information, and by discarding compiled code when the conditions change and the assumptions are not valid anymore.
  • vbezhenar 5y ago
    JVM is not that smart.
• jboy55 5y ago
  Years ago we had a system that was performing really badly. It turns out that it spent over 50% of its time on log.debug(xmldoc) The debug method took a string, and Java was converting the xmldoc to a string. This was back in the 1.4/1.5 days.