CMS: "premature" minor GCs w/ ParNew
Hi, I see minor GCs occurring when young gen occupancy is very low, e.g.: [ParNew: 8446K->7381K(943744K), 0.0274200 secs] Does anybody know what provokes such "premature" GCs? There's no CMS concurrent cycle running or any other interesting GC events occurred around that moment - just a sequence of minor GCs with such outlier. Such premature minor GCs occur on a regular basis. JDK version: 6u37, 64-Bit Server VM (20.12-b01, mixed mode) Best regards, Vladimir Ivanov
Does it happen with a specific application? You might want to print the gc cause and see. It could be related to allocating very large objects (arrays). +PrintGCDetails and +PrintHeapAtGC would provide additional data (but probably not the cause, although that may have changed in more recent builds (JDK 8/hs25+? have lost track..) -- ramki On Wed, May 15, 2013 at 8:05 AM, Vladimir Ivanov <vladimir.x.ivanov@oracle.com> wrote:
Hi,
I see minor GCs occurring when young gen occupancy is very low, e.g.: [ParNew: 8446K->7381K(943744K), 0.0274200 secs]
Does anybody know what provokes such "premature" GCs?
There's no CMS concurrent cycle running or any other interesting GC events occurred around that moment - just a sequence of minor GCs with such outlier.
Such premature minor GCs occur on a regular basis.
JDK version: 6u37, 64-Bit Server VM (20.12-b01, mixed mode)
Best regards, Vladimir Ivanov
Hi, On Wed, 2013-05-15 at 09:58 -0700, Srinivas Ramakrishna wrote:
Does it happen with a specific application?
You might want to print the gc cause and see. It could be related to allocating very large objects (arrays). +PrintGCDetails and +PrintHeapAtGC would provide additional data (but probably not the cause, although that may have changed in more recent builds (JDK 8/hs25+? have lost track..)
You can use -XX:+UnlockDiagnosticVMOptions -XX:G1LogLevel=finest to get most detail. PrintGCDetail by maps to G1LogLevel=finer or so (one level coarser) iirc. Thomas
Hi, forget that last message, I was looking at a similar issue lately with G1, but this is ParNew/CMS. The options I suggested are G1 options. Sorry, Thomas On Wed, 2013-05-15 at 19:27 +0200, Thomas Schatzl wrote:
Hi,
On Wed, 2013-05-15 at 09:58 -0700, Srinivas Ramakrishna wrote:
Does it happen with a specific application?
You might want to print the gc cause and see. It could be related to allocating very large objects (arrays). +PrintGCDetails and +PrintHeapAtGC would provide additional data (but probably not the cause, although that may have changed in more recent builds (JDK 8/hs25+? have lost track..)
You can use -XX:+UnlockDiagnosticVMOptions -XX:G1LogLevel=finest to get most detail. PrintGCDetail by maps to G1LogLevel=finer or so (one level coarser) iirc.
Thomas
Ramki,
Does it happen with a specific application? Yes, I see it for a particular application (running a Cassandra instance). I analyzed a GC log and was confused by such suspicious minor GCs.
You might want to print the gc cause and see. It could be related to allocating very large objects (arrays). +PrintGCDetails and +PrintHeapAtGC would provide additional data (but probably not the cause, although that may have changed in more recent builds (JDK 8/hs25+? have lost track..) Unfortunately, -XX:+PrintGCCause isn't available in jdk6 and other diagnostic output doesn't give any clue why a particular GC was started.
I was under impression that allocation of large arrays can provoke only Full GC (or CMS concurrent cycle), but not just a minor GC. Was I wrong? Best regards, Vladimir Ivanov
-- ramki
On Wed, May 15, 2013 at 8:05 AM, Vladimir Ivanov <vladimir.x.ivanov@oracle.com> wrote:
Hi,
I see minor GCs occurring when young gen occupancy is very low, e.g.: [ParNew: 8446K->7381K(943744K), 0.0274200 secs]
Does anybody know what provokes such "premature" GCs?
There's no CMS concurrent cycle running or any other interesting GC events occurred around that moment - just a sequence of minor GCs with such outlier.
Such premature minor GCs occur on a regular basis.
JDK version: 6u37, 64-Bit Server VM (20.12-b01, mixed mode)
Best regards, Vladimir Ivanov
Hi Vladimir, Can you run with an early access jdk8? If so then enable the flag PrintGCCause and you should get the reasons for these GCs. How do the timestamps of these premature GCs compare to the previous GC? Are they back to back with a non-premature GC? Does it look like the application didn't run between a normal GC and the premature GC? You can use PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime to see how long the application runs between safepoints. These premature GCs could be GC locker related. When the last thread exits a critical region there is a slight window before the GC locker initiated GC where another application can nip in and successfully schedule a regular GC. JohnC On 5/15/2013 8:05 AM, Vladimir Ivanov wrote:
Hi,
I see minor GCs occurring when young gen occupancy is very low, e.g.: [ParNew: 8446K->7381K(943744K), 0.0274200 secs]
Does anybody know what provokes such "premature" GCs?
There's no CMS concurrent cycle running or any other interesting GC events occurred around that moment - just a sequence of minor GCs with such outlier.
Such premature minor GCs occur on a regular basis.
JDK version: 6u37, 64-Bit Server VM (20.12-b01, mixed mode)
Best regards, Vladimir Ivanov
John,
Can you run with an early access jdk8? If so then enable the flag PrintGCCause and you should get the reasons for these GCs. What I have right now is just a GC log. But I'll try to get the data for JDK8 build.
How do the timestamps of these premature GCs compare to the previous GC? Are they back to back with a non-premature GC? It starts right after the previous GC (see attached excerpt from the GC log). Normally, minor GCs are scheduled every 5 secs.
Does it look like the application
didn't run between a normal GC and the premature GC? You can use PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime to see how long the application runs between safepoints. It may be the case (at least it seems so - there's no output from application in between). Thanks for the suggestion. I'll try to experiment with these flags.
These premature GCs could be GC locker related. When the last thread exits a critical region there is a slight window before the GC locker initiated GC where another application can nip in and successfully schedule a regular GC. Can you elaborate on this a little? I don't grasp how it can lead to a premature GC. Don't we schedule a GC anyway? Or does GC locker initiated GC have some special treatment?
Best regards, Vladimir Ivanov
JohnC
On 5/15/2013 8:05 AM, Vladimir Ivanov wrote:
Hi,
I see minor GCs occurring when young gen occupancy is very low, e.g.: [ParNew: 8446K->7381K(943744K), 0.0274200 secs]
Does anybody know what provokes such "premature" GCs?
There's no CMS concurrent cycle running or any other interesting GC events occurred around that moment - just a sequence of minor GCs with such outlier.
Such premature minor GCs occur on a regular basis.
JDK version: 6u37, 64-Bit Server VM (20.12-b01, mixed mode)
Best regards, Vladimir Ivanov
John, So, I got some more data on that [1] (unfortunaltey, no log w/ GC reason yet). Application does some work in between, but it's tiny (worked for 0.1ms & allocated ~1Mb). Best regards, Vladimir Ivanov [1] 101220.389: [GC 101220.390: [ParNew Desired survivor size 53673984 bytes, new threshold 3 (max 3) - age 1: 929440 bytes, 929440 total - age 2: 2864592 bytes, 3794032 total - age 3: 1028480 bytes, 4822512 total : 845730K->7106K(943744K), 0.0838040 secs] 4111626K->3273982K(14575232K), 0.0844520 secs] [Times: user=0.52 sys=0.00, real=0.09 secs] Total time for which application threads were stopped: 0.0874230 seconds Application time: 0.0001460 seconds 101220.477: [GC 101220.477: [ParNew Desired survivor size 53673984 bytes, new threshold 3 (max 3) - age 1: 2104 bytes, 2104 total - age 2: 927096 bytes, 929200 total - age 3: 3913192 bytes, 4842392 total : 8148K->5665K(943744K), 0.0186370 secs] 3275023K->3273571K(14575232K), 0.0191650 secs] [Times: user=0.27 sys=0.00, real=0.02 secs] Total time for which application threads were stopped: 0.0222120 seconds Application time: 8.6636930 seconds 101229.163: [GC 101229.164: [ParNew Desired survivor size 53673984 bytes, new threshold 3 (max 3) - age 1: 1012848 bytes, 1012848 total - age 3: 872344 bytes, 1885192 total : 844577K->3631K(943744K), 0.0860900 secs] 4112483K->3274358K(14575232K), 0.0867710 secs] [Times: user=0.28 sys=0.00, real=0.09 secs] On 5/15/13 9:00 PM, John Cuthbertson wrote:
Hi Vladimir,
Can you run with an early access jdk8? If so then enable the flag PrintGCCause and you should get the reasons for these GCs. How do the timestamps of these premature GCs compare to the previous GC? Are they back to back with a non-premature GC? Does it look like the application didn't run between a normal GC and the premature GC? You can use PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime to see how long the application runs between safepoints.
These premature GCs could be GC locker related. When the last thread exits a critical region there is a slight window before the GC locker initiated GC where another application can nip in and successfully schedule a regular GC.
JohnC
On 5/15/2013 8:05 AM, Vladimir Ivanov wrote:
Hi,
I see minor GCs occurring when young gen occupancy is very low, e.g.: [ParNew: 8446K->7381K(943744K), 0.0274200 secs]
Does anybody know what provokes such "premature" GCs?
There's no CMS concurrent cycle running or any other interesting GC events occurred around that moment - just a sequence of minor GCs with such outlier.
Such premature minor GCs occur on a regular basis.
JDK version: 6u37, 64-Bit Server VM (20.12-b01, mixed mode)
Best regards, Vladimir Ivanov
participants (4)
-
John Cuthbertson
-
Srinivas Ramakrishna
-
Thomas Schatzl
-
Vladimir Ivanov