Time for which application threads were stopped depicted twice

[VsevolodGolovanov]

Java HotSpot(TM) 64-Bit Server VM (24.80-b11) for linux-amd64 JRE (1.7.0_80-b15), built on Apr 10 2015 19:53:14 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 16333776k(6882328k free), swap 2097144k(2097144k free)
CommandLine flags: -XX:GCHeapFreeLimit=10 -XX:GCTimeLimit=80 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Data/test/bin/ -XX:InitialHeapSize=2608857088 -XX:MaxHeapSize=2608857088 -XX:MaxPermSize=536870912 -XX:+PrintGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseCompressedOops -XX:+UseGCOverheadLimit -XX:+UseLargePages -XX:+UseParallelGC -XX:+UseParallelOldGC 

This log: gcstats.log.txt Is depicted as: Both by 1.34.1 and a current build. The problem is the same Total time for which application threads were stopped: 51.4019890 seconds seems to be depicted twice: as a GC pause (the green line) and as a VM operation (the red rectangle). This event has a timestamp of 13:04:03. For context, at 13:04:14 the server logged an OutOfMemoryError. I suspect this 51 second pause is a failed Full GC. Or a heap dump. Or both.

[chewiebug]

Hi,

Thank you for reporting this special situation!

I see the following sequence of events in the log (including some timestamps for context): Application stopped: 2.51s

Full Gc: 2.034s Application stopped : 2.035s

13:03:05.418 Full Gc: 6.53s 13:03:11.958 Application stopped : 6.54s

13:04:03.362 Application stopped : 51s

13:04:03.366 Full Gc : 5.11s Application stopped : 5.31s

Full Gc : 2.47s

Here my interpretations:

• there was no full gc that took 51s, it was something else (I think, if you Google for "safepoint statistics" you will find out more about possible reasons)
• GCViewer depicts all pause durations and events correctly BUT There is still a bug shown by your issue : apparently the timestamps of normal gc events are the beginning of the event. For the "application stopped" ones, the timestamp marks the end of the event.

So, after the fix, the big red rectangle should be moved to the left in the chart.

Best regards, Jörg

-------- Original Message -------- From: VsevolodGolovanov [email protected] Sent: 1 June 2016 17:14:48 CEST To: chewiebug/GCViewer [email protected] Subject: [chewiebug/GCViewer] Time for which application threads were stopped depicted twice (#170)

Java HotSpot(TM) 64-Bit Server VM (24.80-b11) for linux-amd64 JRE (1.7.0_80-b15), built on Apr 10 2015 19:53:14 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 16333776k(6882328k free), swap 2097144k(2097144k free)
CommandLine flags: -XX:GCHeapFreeLimit=10 -XX:GCTimeLimit=80 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Data/test/bin/ -XX:InitialHeapSize=2608857088 -XX:MaxHeapSize=2608857088 -XX:MaxPermSize=536870912 -XX:+PrintGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseCompressedOops -XX:+UseGCOverheadLimit -XX:+UseLargePages -XX:+UseParallelGC -XX:+UseParallelOldGC 

This log: gcstats.log.txt Is depicted as: Both by 1.34.1 and a current build. The problem is the same Total time for which application threads were stopped: 51.4019890 seconds seems to be depicted twice: as a GC pause and as a VM operation. This event has a timestamp of 13:04:03. For context, at 13:04:16 the server logged an OutOfMemoryError. I suspect this 51 second pause is a failed Full GC.

---

You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/chewiebug/GCViewer/issues/170

[VsevolodGolovanov]

After some reproducing I'm positive that these 51 seconds were taken by -XX:+HeapDumpOnOutOfMemoryError.

@chewiebug, isn't the green line a bug too, since this is not GC?

[chewiebug]

Ah, ok.

If I remember right, then the green line just marks pause times, but I will have to check once I am near a computer again.

Best regards, Jörg

[VsevolodGolovanov]

Hm, well I was going by these descriptions:

[chewiebug]

Thank you for the Screenshots! I'll definitely have to look into this (maybe just rewrite the documentation).

-------- Original Message -------- From: VsevolodGolovanov [email protected] Sent: 2 June 2016 15:25:58 CEST To: chewiebug/GCViewer [email protected] Cc: chewiebug [email protected], Mention [email protected] Subject: Re: [chewiebug/GCViewer] Time for which application threads were stopped depicted twice (#170)

Hm, well I was going by these descriptions:

---

You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/chewiebug/GCViewer/issues/170#issuecomment-223290437