views:

509

answers:

4

We've turned on verbose GC logging to keep track of a known memory leak and got the following entries in the log:

...
3607872.687: [GC 471630K->390767K(462208K), 0.0325540 secs]
3607873.213: [GC-- 458095K->462181K(462208K), 0.2757790 secs]
3607873.488: [Full GC 462181K->382186K(462208K), 1.5346420 secs]
...

I understand the first and third of those, but what does the "GC--" one mean?

A: 

It is not on the Java GC FAQ

http://java.sun.com/docs/hotspot/gc1.4.2/faq.html

Nor is anything like that mentioned in the Java GC examples page

http://java.sun.com/docs/hotspot/gc1.4.2/example.html

I've never seen that before.

Do you have any special Garbage Collector running? What VM are you running? Does it always occur before Full GC? Are you calling System.gc()?

e5
Hi e5, no special garbage collector. Normal Sun VM. I only see it occasionally, so no, it's not before every Full GC (but I couldn't say if every time it occurs it is directly before one). No System.gc().
RodeoClown
+1  A: 

I got the following from here:

The first two lines indicate you had two minor collections and one major one. The numbers before and after the arrow indicate the combined size of live objects before and after garbage collection, respectively. After minor collections the count includes objects that aren't necessarily alive but can't be reclaimed, either because they are directly alive, or because they are within or referenced from the tenured generation. The number in parenthesis s the total available space, not counting the space in the permanent generation, which is the total heap minus one The format for the major collection in the third line is similar. The flag -XX:+PrintGCDetails prints additional information about the collections. The additional information printed with this flag is liable to change with each version of the virtual machine. The additional output with the -XX:+PrintGCDetails flag in particular changes with the needs of the development of the Java Virtual Machine. of the survivor spaces. The minor collection took about a quarter of a second.

northpole
A: 

Yishai said in the comments:

Given the timestamps and memory amounts I would guess it performed a garbage collection but lost available memory (because other objects were created in parallel)

RodeoClown
A: 

Actually, after encountering this in our own logs, a co-worker and I have an alternative explanation that seems to fit the facts more tightly.

You'll notice in this example that a Full GC follows this weird minor GC line. I can confirm that this is always the case when it crops up in our logs. You can also see that the beginning and end size of the Young Gen is equal, and I can again confirm that this is always the case.

We believe that what is happening here is that the VM has started a Minor GC and, after either not being able to free anything or spending too long without being able to free anything, decides to do a Full instead.