Option -gc true considered harmful

[Aleksey Shipilev]

On 05/02/2017 12:34 PM, Jens Wilke wrote:
> On Dienstag, 2. Mai 2017 16:49:32 ICT Aleksey Shipilev wrote:
>>> 30.998: [GC (System.gc()) [PSYoungGen: 144096K->3840K(153088K)] ....
>>> 31.004: [Full GC (System.gc()) [PSYoungGen: 3840K->0K(153088K)]....
>>>
>>> So probably the benchmark iteration starts while the full GC is in
>>> progress. NB: G1 only generates one event for a forced garbage
>>> collection.
>>
>> Oh. Notice that in the log above, two events are just 6 milliseconds apart.
> 
> Ooops. That was an example for the events only. I didn't pick a "correct" 
> sample from the middle of the runs, which may cause the trouble. 

So, what is the average/maximum interval between the events you saw?


>> We might just wait a little before continuing then, like this:
>>  http://cr.openjdk.java.net/~shade/jmh/gc-wait-settle.patch
> 
> Not convinced. I would say for CMS you need to wait for at least two counter 
> increments and for G1 only for one. Which makes the counter a fragile 
> interface for that purpose.

I'm not sure you need two events for CMS. In my experiments with 8u111 and
9b161, there is only a single "Full GC" event with CMS...


> What might work is to detect the correct increment first by trying to issue two 
> forced GCs. Or, maybe always issue two GCs to make sure the counter increment 
> came from the one we triggered and was the full GC. A reasonable interface 
> would be nice. Any GC specialists here?

There is no "reasonable" interface, because it would be very GC specific. E.g.
there is the reflective GC event interception mechanism in GC profiler -- but
that does not solve the race anyway, because users may call _their own_
System.gc() at the end of the benchmark, and we will confuse Runner logic with it.

You would need to "tag" the System.gc() requests to match them up in checking
logic. But you can't, because the API is not ready for it. So, the only
non-insane thing we can do is to tune up our detection code to cover for most
basic cases.

In the presence of finalization, I think it still makes sense to do two GCs and
run finalization to boot:
  http://cr.openjdk.java.net/~shade/jmh/gc-wait-settle-2.patch


> Anyhow, it still needs to be verified that this is really causing the different 
> throughput values. Best would be to check with a patched version and increment 
> of two for CMS.

As I said before, we mostly concern ourselves with foobar-ing GC heuristics with
explicit System.gc() calls. I have a gut feeling that would be the first-order
effect, and the possible GC cycle overlap would be the second-order one. There
is a reason why -gc is "false" by default, and the attempts to fix every last
aspect of it are doomed to fail.

Thanks,
-Aleksey