Support for ShenandoahGC in non unified jvm logging format

[jborgers]

Hi,

As a GC tuner I'd like GCViewer to support ShenandoahGC, the ultra low pause time collector.
See https://wiki.openjdk.java.net/display/shenandoah/Main

Best, Jeroen

[chewiebug]

Hi Jeroen Did you check the latest SNAPSHOT version (https://github.com/chewiebug/GCViewer/wiki/Changelog)? Is it missing something concerning Shenandoah support? Best regards, Jörg

[jborgers]

Hi Jorg,
Ah, missed it. Thanks, I will check it out.
Regards,
Jeroen

[jborgers]

Hi Jorg,

It fails to parse the gc logfile, I get:

INFO [DataReaderFacade]: GCViewer version 1.36-SNAPSHOT (2018-05-30T19:10:38+0000)
SEVERE [DataReaderFactory]: Failed to recognize file format.
content:
14458.511: [Concurrent marking 1968M->1973M(2048M), 8.679 ms]
14458.520: [Concurrent precleaning 1975M->1975M(2048M), 0.162 ms]
14458.522: [Pause Final Mark 1978M->166M(2048M), 30.514 ms]
14458.553: [Concurrent reset bitmaps 167M->171M(2048M), 1.421 ms]
14467.156: [Pause Init Mark, 1.715 ms]
14467.158: [Concurrent marking 1966M->1980M(2048M), 12.657 ms]
14467.171: [Pause Final Mark 1980M->174M(2048M), 0.558 ms]
14467.172: [Concurrent reset bitmaps 174M->178M(2048M), 0.659 ms]
14475.315: [Pause Init Mark, 1.830 ms]
..

These are the first 3 lines in de log:
OpenJDK 64-Bit Server VM (25.161-b14) for linux-amd64 JRE (1.8.0_161-b14), built on Jan 9 2018 19:54:33 by "mockbuild" with gcc 4.8.5 20150623 (Red Hat 4.8.5-16)
Memory: 4k page, physical 8002012k(4357532k free), swap 2097148k(1656904k free)
CommandLine flags: -XX:HeapDumpPath=/work -XX:InitialHeapSize=2147483648 -XX:LogFile=/log/jvm.log -XX:+LogVMOutput -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseNUMA -XX:+UseShenandoahGC

Regards,
Jeroen

[chewiebug]

Hi Jeroen, Ah, now I see! You are using Shenandoah with Java 8, which uses the "old" gc format. GCViewers implementation is only able to parse Shenandoah with the Unified Logging Format available starting with JDK 9. Out of curiosity: Is there a particular reason, why you are using Shenandoah with Java 8? If you attach a full sample file to this issue, I might be able to add support for the "old" format, as well. Best regards, Jörg

[jborgers]

Hi Jorg,

Right :-)
The (commercial) product is not ready for JDK 9 yet.
Will attach 2 fragments.
gc-tcp-begin.log
gc-tcp-middle.log
Is this good enough?

Regards,
Jeroen

[chewiebug]

Hi Jeroen Hmm, I see, that my last answer didn't make it back to github... The files are nice! I have pushed a commit, which is able to parse both files (you may download <https://github.com/chewiebug/GCViewer/wiki/Changelog> the latest SNAPSHOT build). I see, that you didn't use -XX:+PrintGCDetails. Usually, the addition of that option adds more information for gc analysis (and also needs more tweaking of the parser). Are you able to provide a sample file with this option turned on? Or was there a special reason, why you didn't use that option? Best regards, Jörg

[jborgers]

Hi Jörg,

Ah, great, will try.
Good point, I will ask the team to put the extra param in.

Regards,
Jeroen

[jborgers]

Hi Jörg,

See attachment.
gc_server.log.1.current.zip

I cannot get the tool analyze the file. I get:
INFO [DataReaderFacade]: GCViewer version 1.36-SNAPSHOT (2018-05-30T19:10:38+0000)
SEVERE [DataReaderFactory]: Failed to recognize file format.

Regards,
Jeroen

[chewiebug]

Hi Jeroen, Thank you for the sample file! If you use the latest 1.36-SNAPSHOT version of GCViewer (2018-08-01T15:37:51+0000), the parser will recognise the file, but show a lot of warnings. I'll probably release a fix for those warnings, soon. Regards, Jörg

[chewiebug]

Hi Jeroen,

I have pushed the fix. The latest SNAPSHOT version is able to parse your sample file.

Regards,
Jörg

[jborgers]

Hi Jörg,

Great! it works. Very nice.

What I however not understand is why the results are different in GCEasy. There the max gc pause is 0,029 s. while in GCViewer it is 0,020 s.

I will attach two more Shenandoah gc log files for which GCViewer shows several Warnings; it would be nice if those get fixed as well.

Regards,
Jeroen

[jborgers]

gc_server.log.0.current.zip
gc-tcp.zip

[chewiebug]

Great to hear, that it works!

What I however not understand is why the results are different in GCEasy. There the max gc pause is 0,029 s. while in GCViewer it is 0,020 s.

I have done some comparing numbers with the results gceasy.io provides. I don't really understand the differences.

Comparing numbers with "Shenandoah Collection Phases Statistics" in gceasy and "Event details" in GCViewer, I see no difference.

"Shenandoah GC Time" -> "Pause Time" shows different numbers. I'd expect them to match the "Shenandoah Collection Phases Statistics" and GCViewers "Pause" -> "Total Pause" numbers, but they dont' (apart from the total pause time of 12.54s).

I will attach two more Shenandoah gc log files for which GCViewer shows several Warnings; it would be nice if those get fixed as well.

I'll have a look.

Regards,
Jörg

[jborgers]

Hi,

In the lastest version (2018-10-23) I don't get to see anything useful when loading our Shenandoah gc log file. Only ParseExceptions. I attached a log file.
gc_Shenandoah_Tue.log.0.zip
Regards, Jeroen

[chewiebug]

I have improved the parser. I think, it won't parse the latest sample you attached, because Shenandoah changed it's output significantly.

Please open another issue, if you find issues with Shenandoah, again.

[chewiebug]

By the way: There is a new release 1.36

[jborgers]

Thanks! Kind regards, met vriendelijke groet, Jeroen Borgers drs. Jeroen Borgers Principal Consultant jPinpoint Performance Services, jpinpoint com, The Netherlands. Mobile: +31(0)6-30128951, e-mail: jborgers at jpinpoint com Op za 30 nov. 2019 om 23:00 schreef chewiebug <notifications@github.com>:

…

By the way: There is a new release 1.36 <https://github.com/chewiebug/GCViewer/releases/tag/1.36> — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#198?email_source=notifications&email_token=AF3TVW2277KBEWDTOIEVEFTQWLO3HA5CNFSM4FD7F6QKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEFQUYRY#issuecomment-560024647>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AF3TVW2F7UQA7IAUUQZXYVTQWLO3HANCNFSM4FD7F6QA> .