eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.28k stars 721 forks source link

DTFJ Javacore parser is missing stack traces etc. with current Javacore files #16043

Closed ajohnson1 closed 2 years ago

ajohnson1 commented 2 years ago

The DTFJ Javacore parser is meant to extract information from the javacore.xxxx.txt file generated by the JVM.

It works, but not as well as it used to as it does not extract Java and native stack traces from the javacore file. This is probably because the javacore file format has been enhanced with additional information, but this confuses the parser. Removing some of the extra lines from the javacore file lets DTFJ extract more information. The DTFJ parser should be improved to ignore those extra lines, or better still, make any additional information be available from DTFJ, while still being able to parse javacore files from older JVMs.

3XMTHREADINFO      "Attach API wait loop" J9VMThread:0x0000000000020200, omrthread_t:0x0000019E939C5100, java/lang/Thread:0x00000007225AB140, state:CW, prio=10
3XMJAVALTHREAD            (java/lang/Thread getId:0x20, isDaemon:true)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x000000072254DA00)
3XMTHREADINFO1            (native thread ID:0xFC50, native priority:0xA, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000481)
3XMCPUTIME               CPU usage total: 0.0 secs, user: 0.0 secs, system: 0.0 secs, current category="System-JVM"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Thread.sleep(Native Method)
4XESTACKTRACE                at java/lang/Thread.sleep(Thread.java:993)
4XESTACKTRACE                at openj9/internal/tools/attach/target/WaitLoop.checkReplyAndCreateAttachment(WaitLoop.java:142)
4XESTACKTRACE                at openj9/internal/tools/attach/target/WaitLoop.waitForNotification(WaitLoop.java:117)
4XESTACKTRACE                at openj9/internal/tools/attach/target/WaitLoop.run(WaitLoop.java:157)
3XMTHREADINFO3           Native callstack:
4XENATIVESTACK               NtWaitForSingleObject+0x14 (0x00007FFB961CEDF4 [ntdll+0x9edf4])
4XENATIVESTACK               WaitForSingleObjectEx+0x8e (0x00007FFB93799ADE [KERNELBASE+0x39ade])
4XENATIVESTACK               omrthread_sleep_interruptable+0xfc (0x00007FFB828E32AC [j9thr29+0x32ac])
4XENATIVESTACK               J9_GetInterface+0x399c1 (0x00007FFB46A8DF41 [j9vm29+0x10df41])
4XENATIVESTACK               (0x00007FFB46994D14 [j9vm29+0x14d14])
4XENATIVESTACK               (0x00000000002219C0)
4XENATIVESTACK               (0x0000000000020200)
4XENATIVESTACK               (0x0000008AD987F308)
4XENATIVESTACK               (0x0000008AD987F310)

See https://github.com/eclipse-openj9/openj9/blob/52ab41fa82505d2b245129429bd419591b7d17d1/jcl/src/openj9.dtfj/share/classes/com/ibm/dtfj/javacore/parser/j9/section/thread/ThreadSectionParser.java#L155 which might get confused by 3XMHEAPALLOC etc.

Ideally we would review the current Javacore files and see what extra information could be extracted for DTFJ, as Eclipse Memory Analyzer can process PHD files with the associate Javacore and could use that information.

ajohnson1 commented 2 years ago

The tags missing from the parser are:

3XMJAVALTHREAD
3XMTHREADCCL
3XMHEAPALLOC

Also 3XMCPUTIME comes before 3XMTHREADBLOCK. Has that always been true or does the parse need to cope with either order?

Currently it seems that OpenJ9 Java 17 is not generating a line:

3XMTHREADINFO2            (native stack address range from:0x00007F8B7318E000, to:0x00007F8B731CE000, size:0x40000)

though the parser should cope with that. I'll give some suggested code changes.

keithc-ca commented 2 years ago

I see 3XMTHREADINFO2 in javacores from jdk17; which specific version and platform did you use that did not include that line?

ajohnson1 commented 2 years ago

The tag from my previous comment is actually 3XMJAVALTHRCCL not 3XMTHREADCCL

The javacore is javacore.20220930.053619.81568.0001.txt created from Eclipse Memory Analyzer triggering a javacore from running jconsole.exe from 'JRE 17 Windows 11 amd64-64 (build 17.0.4.1+1)'

keithc-ca commented 2 years ago

3XMTHREADINFO2 is only presented on platforms where omrthread_get_stack_range() is supported; Windows is not one of those platforms, see omrthreadinspect.c.

keithc-ca commented 2 years ago

Also 3XMCPUTIME comes before 3XMTHREADBLOCK. Has that always been true or does the parse need to cope with either order?

Based on the history of javadump.cpp, 3XMCPUTIME has always come before 3XMTHREADBLOCK, so reversing the two lines in ThreadSectionParser.processThreadandStackTrace() to

    IAttributeValueMap cpuTimes = processTagLineOptional(T_3XMCPUTIME);
    IAttributeValueMap blockerInfo = processTagLineOptional(T_3XMTHREADBLOCK);

is all that is strictly necessary to fix this.