Heap line goes down at the beginning of GCs

[blacelle]

Hello, I just start using GCViewer, and I'm not sure to understand the Heap line on GC occurence.

• Used Heap:
  o Blue line that shows used heap size
• GC Times Rectangles:
  o Dark grey rectangle at every Full GC
  o Light grey rectangle at every Incremental GC
  o Grey rectangle at every 'normal' GC

Given this spec, I would expect the Heap line to go break down when the GC completed. As of now, it breaks down when the GC starts. The direct effect is I don't see my application generates memory at a fast rate, since the Heap line ramp-up from the start of current GC to the start of next GC (while it actually ramps up from the end of current GC to the start of next GC).

Maybe this is due to the fact the GC are considered Incremental GC instead of Full-GC, and GCviewer considers data could be generated during the GC. In which case, the issue is rather a mis-interpretation of the following lines:
2014-04-07T16:30:39.333+0200: 7697.688: [GC 319512145K->221329036K(354522304K), 13.0523460 secs]
2014-04-07T16:31:10.359+0200: 7728.714: [GC 325257100K->222378851K(357732160K), 201.8840210 secs]
2014-04-07T16:35:00.670+0200: 7959.025: [GC 325929865K->223445781K(357492672K), 69.9374930 secs]
2014-04-07T16:36:40.672+0200: 8059.027: [GC 327001237K->225038174K(358217408K), 24.1651550 secs]

I read a Full GC line should be prefixed by "[Full GC" instead of "[GC". However, I'm pretty confident the app was doing Full-GCs as it was not responding anymore.

But anyway, I changed the fill to simulate all GC to be FullGC, and the Heap line still breaks down at the beginning of the GC.

The apps runs over a JDK6.

[chewiebug]

Hi Benoit,

You are right, the "used heap" line doesn't take the length of the pause into account. I have fixed that, you may download the latest version.

In the interpretation of your log you are probably mislead. I suspect, you don't use the -XX:+PrintGCDetails option, so you never know much about the collections. If you didn't turn that option on, try it and you will see that there is more information about each collection making interpretation much easier.

Concerning "incremental GC": That is a left over of JDK 1.3, that is still supported by GCViewer; you won't find them in your logs with JDK 6.

"GC" is never a "Full GC" even though yours take an awful lot of time. There are several possible reasons, why a "GC" event may take so long, but without the details in the log, it's very hard (impossible?) to find out.

Best regards,
Jörg

[blacelle]

Hello Jörg,

Thanks for the improvement. Nice to see you differentiated the behaviour between GC (with a ramp down during the GC) and Full GC (with a break down at the beginning of the GC and flat during GC).

Maybe it would be more relevant to be flat during the GC, and have a break down at the end of the GC ? (instead of at the beginning)

About XX:+PrintGCDetails, the system admin had set XX:-PrintGCDetails but it is now fixed.

Thanks for the Incremental GC info. I initially thought it was the alternative for FullGC, but it is rather a third option.

Thanks again for telling GC are never Full GC. It my case, I thought they last very long because the VM has a very large heap (300GB in this case) which is long to Full GC. However, the rest of my gc.log is full of such long pauses and there is not a single FullGC. I'll check again with the additional details, but I'm still convinced there is StopOfTheWorld pauses hidden behind these GC. I may provide more feedback with the new log.

Anyway, please keep up the good work!

[chewiebug]

Hi Benoit,

You are welcome! It is not me that makes that difference in drawing but
the GC algorithm. Now it should just draw exactly what's in the log
file. Since I have no idea, when exactly during a collection the memory
is freed, the line is drawn straight between begin and end of a pause.
If you see something that doesn't show what's in the log, I'd appreciate
the log line and a screenshot.

A "GC" is always a Stop-the-world (STW) pause. And they most probably
will be long, because your heap is huge. GC collections usually only
collect objects from the young generation - in the detailed log, you see
with some gc algorithms, that other generations are collected as well
without it being marked as a Full GC. A Full GC always collects from all
generations. To avoid STW collections you may try to use concurrent
algorithms like CMS or G1. They strive to do all the work in the
background with as little STW pauses as possible.

If you are interested in background information about gc algorithms,
you'll find links in the "links" section of my wiki. If you need support
tuning your VM, you might want to ask hotspot-gc-use@openjdk.java.net.

Best regards,
Jörg

[chewiebug]

closing this one, because I believe, it is fixed.