G1 with Solr - thread from dev at lucene.apache.org

[Shawn Heisey]

On 12/30/2014 3:12 AM, Thomas Schatzl wrote:
> Great to hear about field experience with G1 - a late Christmas present
> for us particularly because they are good.
> 
>> It looks like parallel reference
>> processing and waiting for a later Java 7 release were the secrets to
>> using G1 effectively.
> 
> You really might want to try 8u40: the small logs you provided indicate
> that there is at least some amount of large object allocation going on
> ("occupancy higher than threshold [...] cause: G1 Humongous
> Allocation"). 8u40 added some special handling for those which allows
> fast and cheap reclamation of these in some cases, which improves
> throughput by decreasing GC frequency.

I do have plans to roll out some Java 8 servers for a new project, and
ultimately I expect we will upgrade to Java 8 for the existing servers,
but it won't be an immediate thing.

> Nothing worrying I think given these logs, but these
> allocations/messages seem frequent enough that it could be considered
> useful.
> 
>> After I've got a few hours (and ultimately a few days) of runtime on the
>> new settings, I will grab the log and graph it again.
> 
> Would be really nice to have them for analysis.
> 
> Maybe they could be used to tweak the threshold that starts concurrent
> cycles to reduce the number of GCs. 

I've now got almost a full week of runtime on these new settings.
Here's the log:

https://www.dropbox.com/s/yla4le5l5jrhiir/gc-idxa1-g1-7u72-with-refproc-one-week.zip?dl=0

Trying to graph this log with gcviewer-1.34.jar, it found five entries
in the log that it didn't know how to deal with.  The times on these
lines do look fairly significant, and I assume that they are probably
not in the resulting graph.

INFO [DataReaderFacade]: GCViewer version 1.34 (2014-11-30T14:40:14+0100)
INFO [DataReaderFactory]: File format: Sun 1.6.x G1 collector
INFO [DataReaderSun1_6_0G1]: Reading Sun 1.6.x / 1.7.x G1 format...
WARNING [DataReaderSun1_6_0G1]:
com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type:
'M->' Line 47280:  5987M->1658M(6144M), 2.3640370 secs]
WARNING [DataReaderSun1_6_0G1]:
com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type:
'M->' Line 155388:  2928M->1721M(6104M), 2.7344030 secs]
WARNING [DataReaderSun1_6_0G1]:
com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type:
'M->' Line 190388:  2615M->1550M(6018M), 2.3079810 secs]
WARNING [DataReaderSun1_6_0G1]:
com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type:
'M->' Line 392918:  6003M->1602M(6138M), 2.1626330 secs]
WARNING [DataReaderSun1_6_0G1]:
com.tagtraum.perf.gcviewer.imp.UnknownGcTypeException: Unknown gc type:
'M->' Line 397195:  6031M->1707M(6138M), 3.0746840 secs]
INFO [DataReaderSun1_6_0G1]: Done reading.

What it DID graph looks fairly good, but there are a handful of long
collections in there.  Only one of those longer collections looked like
a long enough pause that it would trigger a failed load balancer health
check (every five seconds, with a 4990 millisecond timeout), but most of
them are long enough that a user would definitely notice the delay on a
single search.  That probably wouldn't be enough of a problem for them
to lodge a complaint or decide that the site sucks, because the search
would be fast on the next query.  The overall graph shows that a typical
collection happens *very* quickly, so perhaps those few outliers are not
enough of a problem to cause me much concern.  If Java 8 can smooth down
those rough edges, I think we have a clear winner.  Even with Java 7, I
am very excited about these results.

Are there any alternate tools for producing nice graphs from GC logs,
tools that can understand everything in a log from a modern JVM?

Thanks,
Shawn