3

Later Edit: (why I don't think it's the same situation as here )

All the action is done in an instance method, in-and-out, one time for each file I process. The local field which I extract (instead of inlining) is not used anywhere else, so GC clears it anyway after an iteration...

--

In a standard J2SE app (main method ran from Eclipse), while using apache pdfbox and pdf2dom for some pdf to html conversion, I wanted to clear some unneeded INFO log entries.

The unexpected situation:

This piece of code works fine every time:

    Logger logger = Logger.getLogger("org.mabb.fontverter.opentype.TtfInstructions.TtfInstructionParser");
    logger.setLevel(Level.WARNING);

But, if I inline the logger variable, it starts to behave unexpectedly:

Logger.getLogger("org.mabb.fontverter.opentype.TtfInstructions.TtfInstructionParser").setLevel(Level.WARNING);

In the second case, the changes on the logger only take effect after a small time interval is allowed to pass:

  • either if I debug and spend a few seconds inspecting the line
  • or if I process more than one pdf file, meaning the entire execution take slightly longer...

What is the explanation for this ?

Thank you.

Martin Serrano
  • 3,727
  • 1
  • 35
  • 48
Serban
  • 592
  • 1
  • 4
  • 24
  • I'm just guessing but it could be related to garbage collection and how you are keeping a reference to the `logger` variable. Which logging library are you using? There might be a better way to filter which logs are displayed. – JoseM Mar 01 '18 at 16:20
  • The 3rd party libraries which I use are using slf4j. The code that does the actual work, calling functionality from those libraries (pdfbox, pdf2dom) is right below the line with "Logger.getLogger", in the same method. This method gets called for each of the pdf files. Since the logging config change DOES take effect at the second iteration, my guess is that GC has not cleared the logger away... – Serban Mar 01 '18 at 16:33
  • slf4j is just an interface to many different logging libraries (the implementation can be like logback or log4j). Which implementation are you using in your dependencies? – JoseM Mar 01 '18 at 21:17
  • I'm not sure how to answer that... ; The library which creates the unneeded log entries is "pdf2dom"; after inspecting the maven dependencies, I see that it brings along also slf4j-api, but nothing else logging-related. If I debug the code and inspect the `logger` variable from the two lines of code above, it is a simple `java.util.logging.Logger` object. – Serban Mar 02 '18 at 15:28
  • Not the same situations. In my case, everything is done in the body of a non-static method, in-and-out. If I do more than 1 file, then I enter the method again. The "logger" local variable which I create is not used anywhere else, so there is nothing to prevent the GC from clearing it... – Serban Mar 06 '18 at 09:33
  • Could it be that in the first case that very `logger` variable is used to log to while in the second case the loggers logged to are different objects? – mkl Mar 06 '18 at 14:37
  • I don't do anything with that `logger` variable. It's some imported libraries that cause the unneeded log entries. – Serban Mar 06 '18 at 16:19

1 Answers1

1

In short, adding the local reference extends the life of an object just enough.

Vladimir Ivanov from Oracle explains this in [PATCH] Reduce Chance Of Mistakenly Early Backing Memory Cleanup on the OpenJDK core-libs mailing list:

JIT-compilers in HotSpot aggressively prune dead locals, but they do that based on method bytecode analysis (and not on optimized IR). So, any usage of a local extends its live range, even if that usage is eliminated in generated code. It means an oop in that local will live past its last usage in generated code and all safepoints (in generated code) till last usage (on bytecode level) will enumerate the local it is held in.

If there were GC-only safepoints supported, then JITs could still prune unused locals from oop maps, but HotSpot doesn't have them and all safepoints in generated code keep full JVM state, so it's always possible to deoptimize at any one of them (and then run into the code which is eliminated in generated code).

If there are no safepoints till the end of the method, then nothing will keep the object alive. But there's no way for GC to collect it, since GCs rely on safepoints to mark thread stack. (That's why I mentioned GC-only safepoints earlier.)

So as long as the local ref extends the life of the logger object such that Logger.getLogger returns the logger that was created and held by the local var, it will all work.

For logging, do not use a method local reference. Instead hold the reference to the logger in a wider scope and set the level once preferably before the loggers start publishing records.

jmehrens
  • 10,580
  • 1
  • 38
  • 47