I have recently found a bug that causes a NullPointerException. The exception is caught and logged using a standard slf4j statement. Abridged code below:
for(Action action : actions.getActions()) { try { context = action.execute(context); } catch (Exception e) { logger.error("...", e); break; } }
As you can see, nothing fancy. However, of all the exception logging statements that we have, just this one does not print a stack trace. All it prints is the message (represented as "...") and the name of the exception class (java.lang.NullPointerException).
Since the stack trace on an exception is lazy loaded, I thought maybe there is a instruction reordering issue of some sort and decided to call e.getStackTrace() before the log statement. This made no difference.
So I decided to restart with the debug agent enabled. However, because I even attached to the process, I noticed that now the stack traces were printing. So clearly the presence of the debug agent caused some additional debug information to become available.
I have since then fixed the root cause of the exception. But I would like to learn why the stack trace was unavailable without a debugger. Anyone know?
Clarification: this is not a logging issue. Imagine the same try/catch clause, but in the catch, I print the value of:
e.getStackTrace().length
Without a debugger this prints '0', with a debugger it prints a positive number (9 in this case).
More info: this is happening on JDK 1.6.0_13, 64bit, amd64, linux 2.6.9
With the JVM flag -XX:-OmitStackTraceInFastThrow you can disable the performance optimization of the JVM for this use case. IF this parameter is given, which disables the flag, the stacktrace will be available.
For more information please have a look at the following release notes:
"The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow." http://java.sun.com/j2se/1.5.0/relnotes.html
Is it possible that this code is in an inner loop? Then then JIT compiler might be compiling the call stack for this to native code, losing the stack information. Then when you attach the debugger it disables the JIT, making the information available again.
The other manual exceptions keep displaying the information as the JIT is not optimising.
It looks like this can sometimes happen for others from a comment in this class source code at line 102:
http://logging.apache.org/log4j/1.2/xref/org/apache/log4j/spi/LocationInfo.html
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With