What does BufferBlob::Interpreter in JVM crash log mean?
Asked Answered
U

1

7

I am investigating a JVM crash which happens occasionally in my application. The hs_err file contains the following details about the crash.

#  SIGSEGV (0xb) at pc=0x065e68f4, pid=20208, tid=570166160
#
# Java VM: Java HotSpot(TM) Server VM (10.0-b23 mixed mode linux-x86)

...

# Problematic frame:
# V  [libjvm.so+0x5e68f4]

...

Current thread (0x099ea800):  JavaThread "Thread-315" daemon [_thread_in_vm, id=25782, stack(0x21fa3000,0x21fc1000)]

...

vm_info: Java HotSpot(TM) Server VM (10.0-b23) for linux-x86 JRE (1.6.0_07-b06), built on Jun 10 2008 01:20:15 by "java_re" with gcc 3.2.1-7a (J2SE release)

So this tells me that the JVM hit a segfault when running some Java code. The error log also contains information about the stack of the thread which crashed.

Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x5e68f4]
V  [libjvm.so+0x1c054f]
V  [libjvm.so+0x1bfef2]
V  [libjvm.so+0x1bf57f]
V  [libjvm.so+0x592495]
V  [libjvm.so+0x365c4e]
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
J  org.myapp.AppClass.getBytes()Lorg/myapp/ByteHolder;

I have used GDB to connect to the core file from the crash and get more detail about the stack. This gives me the following output.

#5  <signal handler called>
#6  0x065e68f4 in interpretedVFrame::monitors() const ()
   from /usr/java/jdk1.6.0_07/jre/lib/i386/server/libjvm.so
#7  0x061c054f in get_or_compute_monitor_info(JavaThread*) ()
   from /usr/java/jdk1.6.0_07/jre/lib/i386/server/libjvm.so
#8  0x061bfef2 in revoke_bias(oopDesc*, bool, bool, JavaThread*) ()
   from /usr/java/jdk1.6.0_07/jre/lib/i386/server/libjvm.so
#9  0x061bf57f in BiasedLocking::revoke_and_rebias(Handle, bool, Thread*) ()
   from /usr/java/jdk1.6.0_07/jre/lib/i386/server/libjvm.so
#10 0x06592495 in ObjectSynchronizer::fast_enter(Handle, BasicLock*, bool, Thread*) ()
   from /usr/java/jdk1.6.0_07/jre/lib/i386/server/libjvm.so
#11 0x06365c4e in InterpreterRuntime::monitorenter(JavaThread*, BasicObjectLock*) ()
   from /usr/java/jdk1.6.0_07/jre/lib/i386/server/libjvm.so

This shows that the six libjvm.so frames listed in the original bug report were related to grabbing a Java lock. However, I can't find any code within org.myapp.AppClass.getBytes() which uses any locks.

What do the BufferBlob::Interpreter lines in the stack mean? Are these Java stack frames? JVM stack frames? Is it possible to work out what was being called in these stack frames?

NOTE: Please don't suggest that I try to switch to a newer Hotspot JVM. I rely on the CMS collector and none of the more recent V1.6 Hotspot JVMs are stable enough with the CMS collector.

EDIT: This document (http://www.oracle.com/technetwork/java/javase/tsg-vm-149989.pdf) states that a "v" frame is a "VM generated stub frame". Any idea what this means?

EDIT2: org.myapp.AppClass.getBytes() reads from a DataInputStream. This could involve the following stack trace:

AppClass.getBytes()
AppClass.readByte()
DataInputStream.readByte()
SocketInputStream.read()
SocketInputStream.read(byte[],int,int)
PlainSocketImpl.aquireFD()

This final method grabs a lock. This could be the source of the eventual call into the JVM code listed above. This stack above has the neat feature that there are 5 Java stack frames below getBytes(). This would match up neatly with the 5 lines of BufferBlob::Interpreter in the list of "Java frames".

This raises a couple of new questions:

  • Is it possible that the 5 lines of BufferBlob::Interpreter under the "Native frames" section are just duplicates of the same lines under the "Java frames" section?
  • Why doesn't the error log show the details for these 5 stack frames?

EDIT3 - This Oracle bug looks likely to be the same/similar bug: https://bugs.java.com/bugdatabase/view_bug?bug_id=6676175

The stack trace shown isn't identical but it mentions a rare race condition in revoke_and_rebias which was fixed in 6u14.

EDIT4 - The bounty message should say "familiar with the Hotspot implementation"

Ultrastructure answered 28/10, 2011 at 12:3 Comment(0)
M
4

VM generated stub frame just means that the code that is executing has been generated by the JVM.

The stack itself (from gdb) shows the VM is attempting to reach a safepoint because it is revoking a biased lock. You can read about biased locking in this blog. This means that some thread has acquired a monitor which biases that monitor towards that thread. Later some other thread wants the lock so it has to revoke the bias which requires a safepoint to be reached (i.e. no thread is executing byte code aka stop the world).

Your error may also be indicative of the JVM crashing during deoptimisation of some methods. This means the JVM has optimised (compiled) certain methods already but then hit a code path that causes it to need to deoptimise because the compiled method is no longer valid. You're unlikely to find a fix for this without a JVM upgrade.

It looks like you have 2 workarounds you might want to try

  1. if it's driven by biased locking, turn it off (-XX:-UseBiasedLocking)
  2. if it's driven by deoptimisation, find the offending method and tell hotspot not to compile it in the first place, instructions on how to do this on this link

Both approaches may have a performance impact.

NB this will be less frustrating if you can work out a test scenario that reliably reproduces the problem.

Methylene answered 28/10, 2011 at 13:7 Comment(4)
"means that the code that is executing has been generated by the JVM, i.e. compiled (optimised) code" - The JVM manages to name "org.myapp.AppClass.getBytes()" despite it being a compiled method (as per the tag "J"). Is the JVM sometimes unable to name the method being executed? Or do the "BufferBlob::Interpreter" lines refer to bits of implicit work which the JVM has inserted into my program?Ultrastructure
I edited that bit out as it's not what I meant to say. A simple compiled method still appears as a J as far as I know. The Interpreter lines do refer to code the JVM has created. The JVM does do lots of things (GC, optimisation) other run your code.Methylene
Hmmm that makes sense except that I'm fairly certain that my method in the stack (org.myapp.AppClass.getBytes()) doesn't do any locking. That's why I was assuming the BufferBlob::Interpreter lines must represent further method calls. Is this possible? I thought GC and JIT happened in their own threads.Ultrastructure
there's some information on how deoptimization actually happens in this paper - cs.princeton.edu/picasso/mats/HotspotOverview.pdf - and a summary of bias revocation here - oracle.com/technetwork/java/javase/tech/… - both require a safepoint to be reached which means forcing the threads to stop. I think the interpreter stuff refers to interpreted frames so it may have switched back from a compiled method to the deoptimized version. I'd be inclined to use -XX:+PrintCompilation to see what is happening in some more detail.Methylene

© 2022 - 2024 — McMap. All rights reserved.