Crash course on JVM crash analysis

Posted by kohsuke on February 19, 2009 at 5:32 PM PST

One cannot call oneself a Java geek if you haven't done JVM crash dump analysis. I mean, a C programmer would laugh at you if you tell them you don't know how to look at the stack dump. Well, I just had the pleasure of doing an analysis, so I'll show you how to do it, in case you don't know how :-) — This is on Windows, BTW.

Everything starts with the hs_err_pid*.log file that JVM creates upon a crash. First you look at the cause of the death, which is at the very top of the crash dump file:

#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x6d962f80, pid=3628, tid=628

...

siginfo: ExceptionCode=0xc0000005, reading address 0x00000000

So it's trying to read from a NULL pointer, resulted in an access violation. This is the native equivalent of NullPointerException.

Now that we know why it's dead, next we check where it's dead. For this, you look at the reconstructed stack trace:


<span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">Stack: [0x0ae60000,0x0aeb0000],  sp=0x0aeae810,  free space=314k</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">V  [jvm.dll+0xd2f80]</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">C  [hudson-remoting38602.jnidispatch.dll+0x764c]</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">j  com.sun.jna.Native.initIDs()V+0</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">j  com.sun.jna.Native.</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;clinit&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">()V+70</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span><span class="pln" style="color: rgb(0, 0, 0); ">v  ~StubRoutines::call_stub</span><span class="tag" style="color: rgb(0, 0, 136); ">&lt;br</span><span class="pln" style="color: rgb(0, 0, 0); "> </span><span class="tag" style="color: rgb(0, 0, 136); ">/&gt;</span>

Unlike Java, in the native land the stack trace reconstruction cannot be reliably done, so this may contain some wrong information (in fact it turns out it was missing one stack frame in this case.) But it's always good approximation to start with.

From this we can see that my native code (which is com.sun.jna.Native.initIDs() — this is a native method) called into JNI and that killed it. So now the question is, which line in initIDs() called which JNI method with what parameters? The initIDs method is 20-30 lines long, so it's not obvious which part of this is offset 0x764c.

So now we need to disassemble the DLL to pin-point where the offset 0x764c is. The tool you use for this purpose is dumpbin, and you can install it through free Visual C++ Express Edition.

First, check the loading address, as below. In this case, this DLL wants to be loaded to 0x10000000, so all the disassembly you'll see starts from 0x10000000. In other words,jnidispatch.dll+0x764c should appear as 0x1000764c.

$ dumpbin /headers jnidispatch.dll | less
...
OPTIONAL HEADER VALUES
             10B magic # (PE32)
            2.56 linker version
            A800 size of code
            4A00 size of initialized data
             800 size of uninitialized data
            1060 entry point (10001060)
            1000 base of code
            C000 base of data
        10000000 image base (10000000 to 1004BFFF)

Now disassemble the DLL:

$ dumpbin /exports /disam jnidispatch.dll > jnidispatch.asm

... and look for 1000764c:

  10007633: 8B 45 EC           mov         eax,dword ptr [ebp-14h]
  10007636: 8B 84 85 68 FF FF  mov         eax,dword ptr [ebp+eax*4+FFFFFF68h]
            FF
  1000763D: 89 44 24 04        mov         dword ptr [esp+4],eax
  10007641: 8B 45 08           mov         eax,dword ptr [ebp+8]
  10007644: 89 04 24           mov         dword ptr [esp],eax
  10007647: E8 50 EF FF FF     call        1000659C
  1000764C: 89 C2              mov         edx,eax
  1000764E: 8B 45 08           mov         eax,dword ptr [ebp+8]
  10007651: 8B 08              mov         ecx,dword ptr [eax]
  10007653: 89 54 24 0C        mov         dword ptr [esp+0Ch],edx
  10007657: 8B 45 F0           mov         eax,dword ptr [ebp-10h]
  1000765A: 89 44 24 08        mov         dword ptr [esp+8],eax
  1000765E: 8B 45 F4           mov         eax,dword ptr [ebp-0Ch]
  10007661: 89 44 24 04        mov         dword ptr [esp+4],eax
  10007665: 8B 45 08           mov         eax,dword ptr [ebp+8]
  10007668: 89 04 24           mov         dword ptr [esp],eax
  1000766B: 8B 81 68 02 00 00  mov         eax,dword ptr [ecx+00000268h]
  10007671: FF D0              call        eax
  10007673: 83 EC 10           sub         esp,10h
  10007676: 8D 45 EC           lea         eax,[ebp-14h]
  10007679: FF 00              inc         dword ptr [eax]
  1000767B: E9 31 FF FF FF     jmp         100075B1
  10007680: 8D 65 F8           lea         esp,[ebp-8]
  10007683: 5E                 pop         esi
  10007684: 5F                 pop         edi
  10007685: 5D                 pop         ebp
  10007686: C2 08 00           ret         8

OK, so it's calling into 0x1000659c, and now we know that the reconstructed stack frame in the hs_err_pid*.log file missed this frame.
Also, we notice that the "ret 8" statement is very close, so this must be almost at the very end of the initIDs function (for some reasons, Visual C++ compiler never seem to produce multiple ret statements for a function.)

So this must be the assembly for the following line in the C source code:

      (*env)->SetStaticObjectField(env, cls, fid, newJavaPointer(env, types[i]));
    }
  }

In reality, you should spend some time looking at the native code to make sure the mapping between C code and assembly is correct. If you have the *.pdb file produced by the linker for the DLL, this step is substantially simplified because of the debug information produced in the PDB file. dumpbin is capable of loading it and using it for disassembly if it's available side-by-side with the DLL.

Now, let's see what's in the function 0x1000659c. The corresponding C code is the following, so if our guess is right, it should be a fairly short function:

jobject 
newJavaPointer(JNIEnv *env, void *p)
{
    jobject obj = NULL;
    if (p != NULL) {
      obj = (*env)->NewObject(env, classPointer, MID_Pointer_init, A2L(p));
    }
    return obj;
}

And indeed, the disassembly is simple, and matches this C code exactly:

  1000659C: 55                 push        ebp
  1000659D: 89 E5              mov         ebp,esp
  1000659F: 83 EC 18           sub         esp,18h
  100065A2: C7 45 FC 00 00 00  mov         dword ptr [ebp-4],0
            00
  100065A9: 83 7D 0C 00        cmp         dword ptr [ebp+0Ch],0
  100065AD: 74 35              je          100065E4
  100065AF: 8B 45 08           mov         eax,dword ptr [ebp+8]
  100065B2: 8B 08              mov         ecx,dword ptr [eax]
  100065B4: 8B 45 0C           mov         eax,dword ptr [ebp+0Ch]
  100065B7: BA 00 00 00 00     mov         edx,0
  100065BC: 89 44 24 0C        mov         dword ptr [esp+0Ch],eax
  100065C0: 89 54 24 10        mov         dword ptr [esp+10h],edx
  100065C4: A1 40 F4 00 10     mov         eax,dword ptr ds:[1000F440h]
  100065C9: 89 44 24 08        mov         dword ptr [esp+8],eax
  100065CD: A1 30 F2 00 10     mov         eax,dword ptr ds:[1000F230h]
  100065D2: 89 44 24 04        mov         dword ptr [esp+4],eax
  100065D6: 8B 45 08           mov         eax,dword ptr [ebp+8]
  100065D9: 89 04 24           mov         dword ptr [esp],eax
  100065DC: 8B 41 70           mov         eax,dword ptr [ecx+70h]
  100065DF: FF D0              call        eax
  100065E1: 89 45 FC           mov         dword ptr [ebp-4],eax
  100065E4: 8B 45 FC           mov         eax,dword ptr [ebp-4]
  100065E7: C9                 leave
  100065E8: C3                 ret

So at this point it looks like the NewObject call crashed. So now, what are the actual parameter values that we passed? Was one of them null?

To answer this question, we go back to the hs_err_pid*.log and look at the stack top:

Top of Stack: (sp=0x0aeae810)
0x0aeae810:   6d9634fa 0aeae8e4 1000c068 06be9978
0x0aeae820:   0adf4800 0ad80be8 0000021e 6da7ab04
0x0aeae830:   0adf4800 00000006 00000004 0aeae8e4
0x0aeae840:   1000c068 0aeae948 06be9978 0adf4800
0x0aeae850:   0ad80be8 0000021e 6da7ab04 100065e1
0x0aeae860:   0adf4914 00000000 00000000 1000e610
0x0aeae870:   00000000 00000000 0aeae948 1000764c
0x0aeae880:   0adf4914 1000e610 0aeae890 0ad80bf4

In C, parameters are passed through stack, so if we are lucky and the JVM didn't use that many stack before it dies, we can see our parameters in this list.
The key to find it is to look for a known value, which is the return address of the call. See, we know that the newJavaPointer method will return to jnidispatch.dll+0x764c. So if we can locate this in the stack, we can locate the parameters.

To do this, we first check the DLL table to see what address our DLL is actually loaded into. This information is also captured in hs_err_pid*.log:

Dynamic libraries:
0x00400000 - 0x00423000 	C:\jdk1.6.0_10\bin\java.exe
0x7c900000 - 0x7c9b0000 	C:\WINDOWS\system32\ntdll.dll
0x7c800000 - 0x7c8f4000 	C:\WINDOWS\system32\kernel32.dll
0x77dd0000 - 0x77e6b000 	C:\WINDOWS\system32\ADVAPI32.dll
0x77e70000 - 0x77f01000 	C:\WINDOWS\system32\RPCRT4.dll
0x7c340000 - 0x7c396000 	C:\jdk1.6.0_10\jre\bin\msvcr71.dll
0x6d890000 - 0x6dae6000 	C:\jdk1.6.0_10\jre\bin\client\jvm.dll
0x77d40000 - 0x77dd0000 	C:\WINDOWS\system32\USER32.dll
0x77f10000 - 0x77f58000 	C:\WINDOWS\system32\GDI32.dll
0x76b40000 - 0x76b6d000 	C:\WINDOWS\system32\WINMM.dll
0x6d340000 - 0x6d348000 	C:\jdk1.6.0_10\jre\bin\hpi.dll
0x76bf0000 - 0x76bfb000 	C:\WINDOWS\system32\PSAPI.DLL
0x6d840000 - 0x6d84c000 	C:\jdk1.6.0_10\jre\bin\verify.dll
0x6d3e0000 - 0x6d3ff000 	C:\jdk1.6.0_10\jre\bin\java.dll
0x6d880000 - 0x6d88f000 	C:\jdk1.6.0_10\jre\bin\zip.dll
0x10000000 - 0x1004c000 	C:\WINDOWS\Temp\hudson-remoting38602.jnidispatch.dll
0x77c10000 - 0x77c68000 	C:\WINDOWS\system32\msvcrt.dll

So we can see that our DLL is loaded to 0x10000000, exactly where it wanted to be loaded to (but this is not always the case.) So, jnidispatch.dll+0x764c=0x1000764c. Do we see it in the top of the stack? Yes!

Top of Stack: (sp=0x0aeae810)
0x0aeae810:   6d9634fa 0aeae8e4 1000c068 06be9978
0x0aeae820:   0adf4800 0ad80be8 0000021e 6da7ab04
0x0aeae830:   0adf4800 00000006 00000004 0aeae8e4
0x0aeae840:   1000c068 0aeae948 06be9978 0adf4800
0x0aeae850:   0ad80be8 0000021e 6da7ab04 100065e1
0x0aeae860:   0adf4914 00000000 00000000 1000e610
0x0aeae870:   00000000 00000000 0aeae948 1000764c
0x0aeae880:   0adf4914 1000e610 0aeae890 0ad80bf4

From here, we can see the two parameters to the newJavaPointer, which are env=0x0adf4914, and p=0x1000e610. Looks OK so far.

Then you mentally trace through the code. 0x0aeae948 must be the result of push ebp, then sub esp,18h must have put esp to 0x0aeae85c.

  1000659C: 55                 push        ebp
  1000659D: 89 E5              mov         ebp,esp
  1000659F: 83 EC 18           sub         esp,18h

Then by comparing a bunch of mov statements and C code, you can see that the parameters are the following. The next item in the stack is 100065e1 which corresponds to the return address from the NewObject call, so we've got everything accounted for:

                              0xadf4914
                              |    0x00000000    0x00000000        0x000000001000e610
                              |    |             |                 |
                              v    v             v                 v
      obj = (*env)->NewObject(env, classPointer, MID_Pointer_init, A2L(p));

And indeed, we are passing NULLs! Aha!

So, I hope you (and in particular me in 6 months) get the idea of how to do this. You saw that hs_err_id*.log file is full of useful information.

And please, for the love of God, create the map file and the PDB file and keep them somewhere. The forensic analysis like this would be so much easier if you have them.


Hi,

THanks for you post. It's very useful. But I do have an issue regarding this process. I don't find a hs_err_pid*.log file in my folder. Actually, not all the times. It's generated some times and sometimes it's not. Is there a definite way to make sure that this log file is generated?

Regards,

Murali V

http://weblogs.java.net/blog/kohsuke/archive/2009/02/crash_course_on.html
发布了430 篇原创文章 · 获赞 415 · 访问量 925万+
展开阅读全文

没有更多推荐了,返回首页

©️2019 CSDN 皮肤主题: 编程工作室 设计师: CSDN官方博客

分享到微信朋友圈

×

扫一扫,手机浏览