CODEWITHSUNDEEP
javajava-8garbage-collectionsolarisg1gc
Florent Bayle
Florent Bayle

Reputation: 11890

Why are G1 garbage collector Unloading times increasing over time?

I'm experiencing a strange behavior when using the G1 garbage collector when running Glassfish under Solaris (SPARC) with the JDK 8u172, the Unloading time of the Remark phase is very long and increasing over time.

Here is an extract of the logs just after the start-up of the application server :

2018-10-18T10:08:28.362+0200: 9528.430: [GC remark 2018-10-18T10:08:28.362+0200: 9528.430: [Finalize Marking, 0.0012164 secs] 2018-10-18T10:08:28.363+0200: 9528.431: [GC ref-proc, 0.1783250 secs] 2018-10-18T10:08:28.541+0200: 9528.609: [Unloading, 1.4087725 secs], 1.5954223 secs] [Times: user=10.79 sys=0.04, real=1.60 secs]

And after some days :

2018-10-22T20:24:52.070+0200: 392111.556: [GC remark 2018-10-22T20:24:52.070+0200: 392111.556: [Finalize Marking, 0.0010811 secs] 2018-10-22T20:24:52.072+0200: 392111.557: [GC ref-proc, 0.1432306 secs] 2018-10-22T20:24:52.215+0200: 392111.701: [Unloading, 5.4160564 secs], 5.5672543 secs] [Times: user=41.16 sys=0.06, real=5.57 secs]

As you can see, the Unloading time grew from 1.6s to 5.6s.

Here is a graph of the Unloading times over time :

increasing unloading times over time

As you can see, it's increasing more or less linearly over time.

Here are the relevant command line flags :

-XX:+AlwaysPreTouch -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=8589934592 -XX:MaxHeapSize=8589934592 -XX:MetaspaceSize=536870912 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:+UseLargePages -XX:+UseLargePagesInMetaspace

The flag -XX:+UseLargePagesInMetaspace was added after reading this blog post, but unfortunately it doesn't solve the problem. I also had a look at this other blog post and this question, but unfortunately, none of the proposed solutions seems to apply in this case.

I can't reproduce this bug when the Glassfish server is running under other Operating Systems/architectures.

Upvotes: 2

Views: 819

Answers (1)

Florent Bayle
Florent Bayle

Reputation: 11890

This is a bug in the JDK : JDK-8199406 : Performance drop with Java JDK 1.8.0_162-b32.

From the bug description, and this discussion thread, this bug :

  • is a regression introduced in JDK 8u161 affecting Garbage Collecting
  • is specific to Solaris : "there are reports of performance drops on Solaris SPARC 64" ; "On x86 it is really fast."
  • increases class-unloading time : "This is a regression that got introduced in 8u161 that increased the class-unloading times from an average of 0.65 secs to 10s of seconds for the customer."
  • is fixed in JDK 8u181/8u182.

The migration to JDK 8u192 fixed the bug, the Unloading times are now much smaller and constants :

2018-10-24T11:57:48.479+0200: 96295.786: [GC remark 2018-10-24T11:57:48.480+0200: 96295.786: [Finalize Marking, 0.0012370 secs] 2018-10-24T11:57:48.481+0200: 96295.787: [GC ref-proc, 0.0960026 secs] 2018-10-24T11:57:48.577+0200: 96295.883: [Unloading, 0.2760147 secs], 0.3796341 secs] [Times: user=1.51 sys=0.02, real=0.38 secs]

Upvotes: 3

Related Questions