G1 Collector execute 50 times per seconds

Question

Using Java 1.6.0_45 with G1 I have one of my application that run almost indefinitely G1 collector. Beside that seems to waste some CPU it also fill my gc log pretty fast at the lowest setting I could find.

I'm wondering what's going on here. Is it normal?

These are my JVM flags:

-XX:ParallelGCThreads=4
-XX:+DisableExplicitGC
-XX:+PrintAdaptiveSizePolicy
-XX:MaxGCPauseMillis=500
-XX:+UnlockExperimentalVMOptions
-XX:+AggressiveOpts
-XX:+DoEscapeAnalysis
-XX:+UseCompressedOops
-XX:InitiatingHeapOccupancyPercent=60
-XX:+UseG1GC
-XX:+PrintGCDateStamps
-XX:HeapDumpPath=JavaLogs\uat
-XX:+HeapDumpOnOutOfMemoryError
-Xloggc:jvm.log
-XX:+PrintGC

2014-05-14T08:22:11.173-0400: 495.992: [GC pause (partial) 1177M->1176M(2000M), 0.0178429 secs]
2014-05-14T08:22:11.188-0400: 496.011: [GC pause (partial) 1177M->1176M(2000M), 0.0085317 secs]
2014-05-14T08:22:11.188-0400: 496.021: [GC pause (partial) 1177M->1176M(2000M), 0.0022702 secs]
2014-05-14T08:22:11.204-0400: 496.025: [GC pause (partial) 1177M->1176M(2000M), 0.0028976 secs]
2014-05-14T08:22:11.204-0400: 496.029: [GC pause (partial) 1177M->1176M(2000M), 0.0021763 secs]
2014-05-14T08:22:11.204-0400: 496.032: [GC pause (partial) 1177M->1176M(2000M), 0.0020172 secs]
2014-05-14T08:22:11.204-0400: 496.035: [GC pause (partial) 1177M->1176M(2000M), 0.0020475 secs]
2014-05-14T08:22:11.219-0400: 496.039: [GC pause (partial) 1177M->1176M(2000M), 0.0022187 secs]
2014-05-14T08:22:11.219-0400: 496.042: [GC pause (partial) 1177M->1176M(2000M), 0.0020149 secs]
2014-05-14T08:22:11.219-0400: 496.045: [GC pause (partial) 1177M->1176M(2000M), 0.0021635 secs]
2014-05-14T08:22:11.219-0400: 496.049: [GC pause (partial) 1177M->1176M(2000M), 0.0019517 secs]
2014-05-14T08:22:11.219-0400: 496.052: [GC pause (partial) 1177M->1176M(2000M), 0.0022797 secs]
2014-05-14T08:22:11.235-0400: 496.055: [GC pause (partial) 1177M->1176M(2000M), 0.0020060 secs]
2014-05-14T08:22:11.235-0400: 496.058: [GC pause (partial) 1177M->1176M(2000M), 0.0019567 secs]
2014-05-14T08:22:11.235-0400: 496.062: [GC pause (partial) 1177M->1176M(2000M), 0.0019677 secs]
2014-05-14T08:22:11.235-0400: 496.065: [GC pause (partial) 1177M->1176M(2000M), 0.0019333 secs]
2014-05-14T08:22:11.251-0400: 496.068: [GC pause (partial) 1177M->1176M(2000M), 0.0021960 secs]
2014-05-14T08:22:11.251-0400: 496.071: [GC pause (partial) 1177M->1176M(2000M), 0.0020410 secs]
2014-05-14T08:22:11.251-0400: 496.075: [GC pause (partial) 1177M->1176M(2000M), 0.0019669 secs]
2014-05-14T08:22:11.251-0400: 496.078: [GC pause (partial) 1177M->1176M(2000M), 0.0018926 secs]
2014-05-14T08:22:11.251-0400: 496.081: [GC pause (partial) 1177M->1176M(2000M), 0.0019296 secs]
2014-05-14T08:22:11.266-0400: 496.084: [GC pause (partial) 1177M->1176M(2000M), 0.0025533 secs]
2014-05-14T08:22:11.266-0400: 496.088: [GC pause (partial) 1177M->1176M(2000M), 0.0022381 secs]
2014-05-14T08:22:11.266-0400: 496.091: [GC pause (partial) 1177M->1177M(2000M), 0.0020359 secs]
2014-05-14T08:22:11.266-0400: 496.094: [GC pause (partial) 1178M->1177M(2000M), 0.0018670 secs]
2014-05-14T08:22:11.266-0400: 496.097: [GC pause (partial) 1178M->1177M(2000M), 0.0021041 secs]
2014-05-14T08:22:11.282-0400: 496.101: [GC pause (partial) 1178M->1177M(2000M), 0.0022645 secs]
2014-05-14T08:22:11.282-0400: 496.104: [GC pause (partial) 1178M->1177M(2000M), 0.0020740 secs]
2014-05-14T08:22:11.282-0400: 496.107: [GC pause (partial) 1178M->1177M(2000M), 0.0020746 secs]
2014-05-14T08:22:11.282-0400: 496.110: [GC pause (partial) 1178M->1177M(2000M), 0.0019408 secs]
2014-05-14T08:22:11.282-0400: 496.113: [GC pause (partial) 1178M->1177M(2000M), 0.0021309 secs]
2014-05-14T08:22:11.297-0400: 496.117: [GC pause (partial) 1178M->1177M(2000M), 0.0020609 secs]
2014-05-14T08:22:11.297-0400: 496.120: [GC pause (partial) 1178M->1177M(2000M), 0.0019799 secs]
2014-05-14T08:22:11.297-0400: 496.123: [GC pause (partial) 1178M->1177M(2000M), 0.0019292 secs]
2014-05-14T08:22:11.297-0400: 496.126: [GC pause (partial) 1178M->1177M(2000M), 0.0019674 secs]
2014-05-14T08:22:11.297-0400: 496.129: [GC pause (partial) 1178M->1177M(2000M), 0.0021726 secs]
2014-05-14T08:22:11.313-0400: 496.133: [GC pause (partial) 1178M->1177M(2000M), 0.0021274 secs]
2014-05-14T08:22:11.313-0400: 496.136: [GC pause (partial) 1178M->1177M(2000M), 0.0019959 secs]
2014-05-14T08:22:11.313-0400: 496.139: [GC pause (partial) 1178M->1177M(2000M), 0.0019370 secs]
2014-05-14T08:22:11.313-0400: 496.142: [GC pause (partial) 1178M->1177M(2000M), 0.0019042 secs]
2014-05-14T08:22:11.313-0400: 496.145: [GC pause (partial) 1178M->1177M(2000M), 0.0021778 secs]
2014-05-14T08:22:11.329-0400: 496.149: [GC pause (partial) 1178M->1177M(2000M), 0.0020659 secs]
2014-05-14T08:22:11.329-0400: 496.152: [GC pause (partial) 1178M->1177M(2000M), 0.0019820 secs]
2014-05-14T08:22:11.329-0400: 496.155: [GC pause (partial) 1178M->1177M(2000M), 0.0019167 secs]

score 1 · Answer 1 · answered May 14 '14 at 12:43

1

That's not normal. You are probably creating too much objects and GC tries to find some free space. But we cannot help you without any other clues. Try some profiling - for example jVisualVM, open sampler, memory and watch for number of object instances. If there is no memory leak, you can try to increase the memory available to your application.

answered May 14 '14 at 12:43

Kojotak

2,020
2
16
29

Actually, it is almost certainly NOT a problem with creating too many objects. It *might* be a storage leak, but it might also be an issue with either the heap size, or "making the wrong choices" on GC tuning. The immediate cause of the problem is almost certainly GC tuning. – Stephen C May 16 '14 at 02:14

Stephen C · Answer 2 · 2014-05-16T02:17:03.007

That is definitely not "normal" behaviour.

However, it looks like this is exactly what the GC options you have chosen stipulate:

The heap size is 2000Mb. (I don't know if this is the default size, or if you have specified it.) 2000Mb is too small for an application that appears to have a working set¹ of ~1200Mb ... this point in time.
You have told the JVM to trigger a garbage collection when the heap reaches 60%. 60% of 2000Mb is, ~1200Mb (!).

So what is the solution?

The best solution would be to increase the heap size. If you keep the other JVM parameters the same, and the program working set stays the same, then I'd recommend a minimum heap size of 5Gb; i.e. 3 times the size of the working set + 40%.
If you were prepared to squeeze the 60% occupancy trigger, you could run with a smaller (than 5Gb) heap ... but with an increased risk of longer pauses.
If you squeeze the "3 times the size" to 2 times or less, you increase the frequency of GC runs, and correspondingly increase the GC overheads. (The GC overheads increase asymptotically as the GC triggering point approach your program's working set size.)
If you were prepared to use the Throughput collector instead of a low-pause collector, your GC overheads would most likely reduce. The Throughput collector only triggers when a "space" actually fills up. Of course, the downside would be GC pauses.

If the heap size and pause time requirements are set in stone, then your only practical option is to try to reduce your program's working set size. If your program is leaking memory, fix the leaks. Otherwise, look for data structure changes that would reduce memory utilization.

^{1 - In this context, the working set is the set of objects that are found to be reachable when the GC runs.}

What I read from the GC log is that it run when there is not much garbage created since last GC, which after days of research end-up to that bug -> http://bugs.java.com/bugdatabase/view_bug.do?bug_id=7181612 I do use an old JVM without support so the bug may not have been fixed. — Sebastien Tardif, May 20 '14 at 10:04
What makes you think it is *that* bug? Have you any evidence that this is caused by an undersized Eden space? (BTW: if it really is that bug, it is unlikely to be fixed ...) — Stephen C, May 20 '14 at 13:46

score 0 · Answer 3 · answered May 15 '14 at 12:46

The GC seems to be able to reclaim just 1 MB per invocation (1177M->1176M). That's obviously waste of time and you need to give your process more memory. Then you'll see something like 2177M->1176M and the frequency of GC will be reduced by a factor of 1000.

G1 Collector execute 50 times per seconds

3 Answers3