Deciphering the contents of a hs_err_pid*.log file

[Mike Fourier]

In the last couple weeks, our production system's JVM has twice gone AWOL overnight. The java process is simply not there anymore, nothing to be found in any application log(4j) files.

In the bin directory, we found a couple of those hs_err_pid.log files, and it contains all sorts of information as to what the state of the JVM was, when it decided to die.

(more from me, after this dump)

#
# An unexpected error has been detected by HotSpot Virtual Machine:
#
#  SIGSEGV (0xb) at pc=0x404f5178, pid=4779, tid=1774807984
#
# Java VM: Java HotSpot(TM) Server VM (1.4.2_14-b05 mixed mode)
# Problematic frame:
# V  [libjvm.so+0x393178]
#
 
---------------  T H R E A D  ---------------
 
Current thread (0x080b9d68):  VMThread [id=4780]
 
siginfo:si_signo=11, si_errno=0, si_code=1, si_addr=0x00000008
 
Registers:
EAX=0x00000000, EBX=0x4078dce4, ECX=0x00000008, EDX=0x679f1ad8
ESP=0x69c95fe8, EBP=0x69c95ff0, ESI=0x000026e5, EDI=0x00000001
EIP=0x404f5178, CR2=0x00000008, EFLAGS=0x00010202
 
Top of Stack: (sp=0x69c95fe8)
0x69c95fe8:   4078dce4 659f0290 69c96008 404f4dd6
0x69c95ff8:   4078dce4 00000002 4079cf88 69c96028
0x69c96008:   69c96018 405ddfe8 407836e8 4078dce4
0x69c96018:   69c96034 405b12f0 4079cf88 407836e8
0x69c96028:   4078dce4 00000002 00000001 69c96054
0x69c96038:   403f30e9 4079cf88 4078dce4 08064c30
0x69c96048:   00000001 00000001 69c96098 69c960b8
0x69c96058:   403f5830 08064c30 00000001 00000000 
 
Instructions: (pc=0x404f5178)
0x404f5168:   89 70 04 8b 40 0c 8b 54 90 fc 8b 42 04 8d 48 08
0x404f5178:   8b 40 08 52 51 8b 40 5c ff d0 83 c4 08 8b 83 90 
 
Stack: [0x69c24000,0x69c97000),  sp=0x69c95fe8,  free space=455k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x393178]
V  [libjvm.so+0x392dd6]
V  [libjvm.so+0x47bfe8]
V  [libjvm.so+0x44f2f0]
V  [libjvm.so+0x2910e9]
V  [libjvm.so+0x293830]
V  [libjvm.so+0x2934bf]
V  [libjvm.so+0x29f2a8]
V  [libjvm.so+0x437ea4]
V  [libjvm.so+0x290dbc]
V  [libjvm.so+0x2924cf]
V  [libjvm.so+0x468fc9]
V  [libjvm.so+0x468dfd]
V  [libjvm.so+0x468097]
V  [libjvm.so+0x468331]
V  [libjvm.so+0x467f5a]
V  [libjvm.so+0x3c2423]
C  [libpthread.so.0+0x5cb7]
 
VM_Operation (0x6cd58024): full generation collection, mode: safepoint, requested by thread 0x6c1a7868

and looking up that thread, I find it is:

  0x6c11fc90 JavaThread "JBoss System Threads(1)-1" daemon [_thread_in_native, id=4796]
0x6c1a7868 JavaThread "GC Daemon" daemon [_thread_blocked, id=4795]
  0x6c1a74a0 JavaThread "RMI Reaper" [_thread_blocked, id=4794]

(the middle one)

The above snips are found in one of the dump files, and are representative of those found in the other. The current VM operation is "full generation collection" and the current thread is "GC Daemon", in both. So, I assume the JVM is dying, when it attempts a full GC.

Question 1 Is that a reasonable deduction to make? (it dies attempting a full GC)?

What changed in the past few weeks?
No JVM updates.
No hardware updates.
No OS config changes.
A small code update (we patched a few bugs)

My thoughts so far:
1) the small code updates we did, while not *in themselves* buggy, now exercise a previously existing condition in our JVM/environment. For example, if the new code is slightly more efficient with memory, then GC's don't happen as often as they used to, and perhaps that causes problems "down the road".

2) hardware? (is one of our RAM sticks dying?)

3) a genuine bug in the JVM (ha!)

Question 2 What else should I be looking at/thinking of?
[ August 20, 2008: Message edited by: Mike Fourier ]

[Santhosh Kumar]

Bottom line is that whatever Java code you execute, JVM should never crash. If it does, it is just a JVM bug. So try to log a defect with Sun with all details and hopefully they will look into that.

To get going in your production, try to upgrade/downgrade the jvm to next/previous update and see if it fixes the issue. I think you would waste more time in debugging why it crashed than trying out newer/older JVM updates.

[Mike Fourier]

I forgot to add these:

Heap
 def new generation   total 52416K, used 2120K [0x459f0000, 0x492d0000, 0x492d0000)
  eden space 46592K,   4% used [0x459f0000, 0x45c02280, 0x48770000)
  from space 5824K,   0% used [0x48770000, 0x48770000, 0x48d20000)
  to   space 5824K,   0% used [0x48d20000, 0x48d20000, 0x492d0000)
 tenured generation   total 466048K, used 52111K [0x492d0000, 0x659f0000, 0x659f0000)
   the space 466048K,  11% used [0x492d0000, 0x4c5b3f78, 0x4c5b4000, 0x659f0000)
 compacting perm gen  total 31744K, used 31718K [0x659f0000, 0x678f0000, 0x699f0000)
   the space 31744K,  99% used [0x659f0000, 0x678e99d8, 0x678e9a00, 0x678f0000)

and

Heap
 def new generation   total 52416K, used 2163K [0x459f0000, 0x492d0000, 0x492d0000)
  eden space 46592K,   4% used [0x459f0000, 0x45c0ce30, 0x48770000)
  from space 5824K,   0% used [0x48770000, 0x48770000, 0x48d20000)
  to   space 5824K,   0% used [0x48d20000, 0x48d20000, 0x492d0000)
 tenured generation   total 466048K, used 53488K [0x492d0000, 0x659f0000, 0x659f0000)
   the space 466048K,  11% used [0x492d0000, 0x4c70c058, 0x4c70ce00, 0x659f0000)
 compacting perm gen  total 33280K, used 33203K [0x659f0000, 0x67a70000, 0x699f0000)
   the space 33280K,  99% used [0x659f0000, 0x67a5cc90, 0x67a5ce00, 0x67a70000)

Tenured gen is only 11%, so not sure why a full GC is being called for. Perhaps though, the 11% represents what the tenured gen was able to be drained to, at the time the JVM fell over. (that is: it *was* higher, like 90% used, and the VM was able to get it down to 11%, and then experienced a fatal error).

Yes/No?