Re: RFR (S): 8023101 java/lang/management/MemoryMXBean/ResetPeakMemoryUsage.java fails
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable. But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ? Thanks, /Staffan On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Stafan, There is a GC flag ExplicitGCInvokesConcurrent which causes a system.GC() to be done concurrently. This means that the application can be allocating during a GC so heap usage can go up. This affects both CMS and G1. Were you aware of this option and its consequences? Ask more questions if I missed the point here. Jon On 8/16/2013 12:00 AM, Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Shd be ok here since presumably the test is run in its own vm where no other allocation activity is happening other than what's in the test... (Staffan/Mandy?) ysr1729 On Aug 16, 2013, at 7:39, Jon Masamitsu <jon.masamitsu@oracle.com> wrote:
Stafan,
There is a GC flag ExplicitGCInvokesConcurrent which causes a system.GC() to be done concurrently. This means that the application can be allocating during a GC so heap usage can go up. This affects both CMS and G1. Were you aware of this option and its consequences?
Ask more questions if I missed the point here.
Jon
On 8/16/2013 12:00 AM, Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
There isn't a guarantee for Runtime.gc() to reclaim any space. On the other hand, the test relies on the knowledge of our implementation (at least serial, parallel, concurrent collectors) does collect the large object array that is allocated in the old gen. With G1, the behavior is probably different. Perhaps another way to fix the test is to attempt GC a few times? Mandy On 8/16/2013 12:00 AM, Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Yes, with G1 and CMS there isn't a guarantee that this is collected if ExplicitGCInvokesConcurrent is enabled. But the test seems to be run without the option... May be it should explicitly turn off the option. In that case the size should definitely decrease by at least the size of the object reclaimed...? --Ramki ysr1729 On Aug 16, 2013, at 8:30, Mandy Chung <mandy.chung@oracle.com> wrote:
There isn't a guarantee for Runtime.gc() to reclaim any space. On the other hand, the test relies on the knowledge of our implementation (at least serial, parallel, concurrent collectors) does collect the large object array that is allocated in the old gen. With G1, the behavior is probably different. Perhaps another way to fix the test is to attempt GC a few times?
Mandy
On 8/16/2013 12:00 AM, Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before". Our experience is that System.gc does not have a guarantee, so we usually have to call it many times. I think it might be better to add something like the following code before Line 117: int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); } Shanliang Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Hi Shanliang -- That's curious. If the array is unreachable, and you do a full gc (of the stop world variety -- either serial/parallel, or CMS/G1 with ExplicitGCInvokesConcurrent switched off) then the array should be reclaimed and if free space book-keeping is correct, the memory usage after should end up strictly less than memory usage before. Are you suggesting that GC returns without actually doing anything? Or that the reduction in usage does not reflect in the "used" ? Both of those would seem to be "bugs" (in the intention of HotSpot's implementation, from what i can recall) albeit not violating the spec of system.gc(). Confused. -- ramki On Sun, Aug 18, 2013 at 9:26 AM, shanliang <shanliang.jiang@oracle.com> wrote:
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before".
Our experience is that System.gc does not have a guarantee, so we usually have to call it many times.
I think it might be better to add something like the following code before Line 117:
int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); }
Shanliang
Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Bengt in the GC group helped me out in making sense of this. Here is my interpretation of his analysis (any errors are mine). Pasted below is the output of the test with -XX:+PrintGCDetails added. This shows that a concurrent GC was started when the large object was allocated. After the object reference has been set to null mbean.gc() is called. But since the concurrent GC is already running, this call did nothing and the heap usage after the call was the same as before. The reason the concurrent GC was started in the first place is that by allocating the large object (~36 MB) we would have a heap occupancy above InitiatingHeapOccupancyPercent (45% by default). The heap in this case was 64 MB and set implicitly by the JVM. One way to make sure the concurrent GC isn't started is to explicitly set the heap size to a larger value so that we don't reach 45% occupancy when allocating the large object. I choose -Xms256m to achieve this and with that value I could run the test for 1000 iterations with no failure. Here is an update webrev that removes my previous fix and instead adds -Xms256m to the command line. I also added -XX:+PrintGCDetails so that we have more information the next tie this test fails. webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.01/ Thanks, /Staffan ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) REASON: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage TIME: 0.34 seconds messages: command: main -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage reason: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage elapsed time (seconds): 0.34 STDOUT: Selected memory pool: Memory Pool name: G1 Old Gen Type: Heap memory Memory Usage: init = 57671680(56320K) used = 0(0K) committed = 57671680(56320K) max = 1073741824(1048576K) Threshold: 0 Manager = [G1 Old Generation] Before big object array (of size 9000000) is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0022050 secs] [Parallel Time: 1.9 ms, GC Workers: 2] [GC Worker Start (ms): Min: 124.0, Avg: 124.9, Max: 125.8, Diff: 1.9] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 0.6] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.6, Max: 1.2, Diff: 1.2, Sum: 1.2] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.0, Avg: 1.0, Max: 1.9, Diff: 1.9, Sum: 1.9] [GC Worker End (ms): Min: 125.9, Avg: 125.9, Max: 125.9, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(8192.0K)->0.0B(7168.0K) Survivors: 0.0B->1024.0K Heap: 827.8K(64.0M)->485.9K(64.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0007420 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0000750 secs] [GC remark [GC ref-proc, 0.0000810 secs], 0.0008080 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After the object is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC cleanup 34M->34M(64M), 0.0002890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After GC: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Heap garbage-first heap total 65536K, used 35642K [0x68400000, 0x6c400000, 0xa8400000) region size 1024K, 2 young (2048K), 1 survivors (1024K) Metaspace total 2435K, used 1943K, reserved 6448K data space 2240K, used 1751K, reserved 4400K class space 195K, used 192K, reserved 2048K STDERR: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) at ResetPeakMemoryUsage.testPool(ResetPeakMemoryUsage.java:118) at ResetPeakMemoryUsage.main(ResetPeakMemoryUsage.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:491) at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94) at java.lang.Thread.run(Thread.java:724) On 20 aug 2013, at 09:57, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Shanliang --
That's curious.
If the array is unreachable, and you do a full gc (of the stop world variety -- either serial/parallel, or CMS/G1 with ExplicitGCInvokesConcurrent switched off) then the array should be reclaimed and if free space book-keeping is correct, the memory usage after should end up strictly less than memory usage before.
Are you suggesting that GC returns without actually doing anything? Or that the reduction in usage does not reflect in the "used" ? Both of those would seem to be "bugs" (in the intention of HotSpot's implementation, from what i can recall) albeit not violating the spec of system.gc().
Confused. -- ramki
On Sun, Aug 18, 2013 at 9:26 AM, shanliang <shanliang.jiang@oracle.com> wrote:
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before".
Our experience is that System.gc does not have a guarantee, so we usually have to call it many times.
I think it might be better to add something like the following code before Line 117:
int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); }
Shanliang
Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Thanks Staffan for sharing the info, it explain why we got failed sometime on our memory leak tests and we had to call System.gc several times. I looked at the System.gc Javadoc: --------------------------------------------- Calling the gc method suggests that the Java Virtual Machine expend effort toward recycling unused objects in order to make the memory they currently occupy available for quick reuse. When control returns from the method call, the Java Virtual Machine has made a best effort to reclaim space from all discarded objects. --------------------------------------------- "Best effect" seems not ensure that a free object would be always reclaimed by System.gc(). Thanks, Shanliang Staffan Larsen wrote:
Bengt in the GC group helped me out in making sense of this. Here is my interpretation of his analysis (any errors are mine).
Pasted below is the output of the test with -XX:+PrintGCDetails added. This shows that a concurrent GC was started when the large object was allocated. After the object reference has been set to null mbean.gc() is called. But since the concurrent GC is already running, this call did nothing and the heap usage after the call was the same as before.
The reason the concurrent GC was started in the first place is that by allocating the large object (~36 MB) we would have a heap occupancy above InitiatingHeapOccupancyPercent (45% by default). The heap in this case was 64 MB and set implicitly by the JVM.
One way to make sure the concurrent GC isn't started is to explicitly set the heap size to a larger value so that we don't reach 45% occupancy when allocating the large object. I choose -Xms256m to achieve this and with that value I could run the test for 1000 iterations with no failure.
Here is an update webrev that removes my previous fix and instead adds -Xms256m to the command line. I also added -XX:+PrintGCDetails so that we have more information the next tie this test fails.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.01/
Thanks, /Staffan
ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) REASON: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage TIME: 0.34 seconds messages: command: main -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage reason: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage elapsed time (seconds): 0.34 STDOUT: Selected memory pool: Memory Pool name: G1 Old Gen Type: Heap memory Memory Usage: init = 57671680(56320K) used = 0(0K) committed = 57671680(56320K) max = 1073741824(1048576K) Threshold: 0 Manager = [G1 Old Generation] Before big object array (of size 9000000) is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0022050 secs] [Parallel Time: 1.9 ms, GC Workers: 2] [GC Worker Start (ms): Min: 124.0, Avg: 124.9, Max: 125.8, Diff: 1.9] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 0.6] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.6, Max: 1.2, Diff: 1.2, Sum: 1.2] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.0, Avg: 1.0, Max: 1.9, Diff: 1.9, Sum: 1.9] [GC Worker End (ms): Min: 125.9, Avg: 125.9, Max: 125.9, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(8192.0K)->0.0B(7168.0K) Survivors: 0.0B->1024.0K Heap: 827.8K(64.0M)->485.9K(64.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0007420 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0000750 secs] [GC remark [GC ref-proc, 0.0000810 secs], 0.0008080 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After the object is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC cleanup 34M->34M(64M), 0.0002890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After GC: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Heap garbage-first heap total 65536K, used 35642K [0x68400000, 0x6c400000, 0xa8400000) region size 1024K, 2 young (2048K), 1 survivors (1024K) Metaspace total 2435K, used 1943K, reserved 6448K data space 2240K, used 1751K, reserved 4400K class space 195K, used 192K, reserved 2048K STDERR: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) at ResetPeakMemoryUsage.testPool(ResetPeakMemoryUsage.java:118) at ResetPeakMemoryUsage.main(ResetPeakMemoryUsage.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:491) at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94) at java.lang.Thread.run(Thread.java:724)
On 20 aug 2013, at 09:57, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Shanliang --
That's curious.
If the array is unreachable, and you do a full gc (of the stop world variety -- either serial/parallel, or CMS/G1 with ExplicitGCInvokesConcurrent switched off) then the array should be reclaimed and if free space book-keeping is correct, the memory usage after should end up strictly less than memory usage before.
Are you suggesting that GC returns without actually doing anything? Or that the reduction in usage does not reflect in the "used" ? Both of those would seem to be "bugs" (in the intention of HotSpot's implementation, from what i can recall) albeit not violating the spec of system.gc().
Confused. -- ramki
On Sun, Aug 18, 2013 at 9:26 AM, shanliang <shanliang.jiang@oracle.com> wrote:
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before".
Our experience is that System.gc does not have a guarantee, so we usually have to call it many times.
I think it might be better to add something like the following code before Line 117:
int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); }
Shanliang
Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Staffan, Nice summary. Change looks good to me. Bengt On 8/20/13 10:31 AM, Staffan Larsen wrote:
Bengt in the GC group helped me out in making sense of this. Here is my interpretation of his analysis (any errors are mine).
Pasted below is the output of the test with -XX:+PrintGCDetails added. This shows that a concurrent GC was started when the large object was allocated. After the object reference has been set to null mbean.gc() is called. But since the concurrent GC is already running, this call did nothing and the heap usage after the call was the same as before.
The reason the concurrent GC was started in the first place is that by allocating the large object (~36 MB) we would have a heap occupancy above InitiatingHeapOccupancyPercent (45% by default). The heap in this case was 64 MB and set implicitly by the JVM.
One way to make sure the concurrent GC isn't started is to explicitly set the heap size to a larger value so that we don't reach 45% occupancy when allocating the large object. I choose -Xms256m to achieve this and with that value I could run the test for 1000 iterations with no failure.
Here is an update webrev that removes my previous fix and instead adds -Xms256m to the command line. I also added -XX:+PrintGCDetails so that we have more information the next tie this test fails.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.01/
Thanks, /Staffan
ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) REASON: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage TIME: 0.34 seconds messages: command: main -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage reason: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage elapsed time (seconds): 0.34 STDOUT: Selected memory pool: Memory Pool name: G1 Old Gen Type: Heap memory Memory Usage: init = 57671680(56320K) used = 0(0K) committed = 57671680(56320K) max = 1073741824(1048576K) Threshold: 0 Manager = [G1 Old Generation] Before big object array (of size 9000000) is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0022050 secs] [Parallel Time: 1.9 ms, GC Workers: 2] [GC Worker Start (ms): Min: 124.0, Avg: 124.9, Max: 125.8, Diff: 1.9] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 0.6] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.6, Max: 1.2, Diff: 1.2, Sum: 1.2] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.0, Avg: 1.0, Max: 1.9, Diff: 1.9, Sum: 1.9] [GC Worker End (ms): Min: 125.9, Avg: 125.9, Max: 125.9, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(8192.0K)->0.0B(7168.0K) Survivors: 0.0B->1024.0K Heap: 827.8K(64.0M)->485.9K(64.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0007420 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0000750 secs] [GC remark [GC ref-proc, 0.0000810 secs], 0.0008080 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After the object is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC cleanup 34M->34M(64M), 0.0002890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After GC: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Heap garbage-first heap total 65536K, used 35642K [0x68400000, 0x6c400000, 0xa8400000) region size 1024K, 2 young (2048K), 1 survivors (1024K) Metaspace total 2435K, used 1943K, reserved 6448K data space 2240K, used 1751K, reserved 4400K class space 195K, used 192K, reserved 2048K STDERR: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) at ResetPeakMemoryUsage.testPool(ResetPeakMemoryUsage.java:118) at ResetPeakMemoryUsage.main(ResetPeakMemoryUsage.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:491) at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94) at java.lang.Thread.run(Thread.java:724)
On 20 aug 2013, at 09:57, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Shanliang --
That's curious.
If the array is unreachable, and you do a full gc (of the stop world variety -- either serial/parallel, or CMS/G1 with ExplicitGCInvokesConcurrent switched off) then the array should be reclaimed and if free space book-keeping is correct, the memory usage after should end up strictly less than memory usage before.
Are you suggesting that GC returns without actually doing anything? Or that the reduction in usage does not reflect in the "used" ? Both of those would seem to be "bugs" (in the intention of HotSpot's implementation, from what i can recall) albeit not violating the spec of system.gc().
Confused. -- ramki
On Sun, Aug 18, 2013 at 9:26 AM, shanliang <shanliang.jiang@oracle.com> wrote:
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before".
Our experience is that System.gc does not have a guarantee, so we usually have to call it many times.
I think it might be better to add something like the following code before Line 117:
int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); }
Shanliang
Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Hi Staffan -- Thanks for the explanation. I see. Can you check if you can replicate that behaviour with CMS also? I submit that, as Shanliang states, this is not a best efforts behavior. As I recall, in CMS, we used the full gc counts to ensure that the system gc would take effect. I'd assume that G1 should do the same thing. I am surprised that a system.gc() short circuits when a concurrent cycle is already in progress. The behaviour should be that multiple concurrent invocations to system.gc() are possibly satisfied with a single invocation, but that an already-in-progress cycle cannot be witness to satisfying an invocation that came after the concurrent cycle had already begun. I recall having thought about these semantics for CMS and made an attempt to ensure that the inetnded semantics of "best effort" was satisfied. The behaviour that you indicate seems to me like a bug. If you reproduce the same behaviour with CMS, please let me know and I can take a look at the code. (It's been a while since I looked at it, so I don't recall all the details, except that it's fairly straightfoward.) -- ramki On Tue, Aug 20, 2013 at 1:31 AM, Staffan Larsen <staffan.larsen@oracle.com> wrote:
Bengt in the GC group helped me out in making sense of this. Here is my interpretation of his analysis (any errors are mine).
Pasted below is the output of the test with -XX:+PrintGCDetails added. This shows that a concurrent GC was started when the large object was allocated. After the object reference has been set to null mbean.gc() is called. But since the concurrent GC is already running, this call did nothing and the heap usage after the call was the same as before.
The reason the concurrent GC was started in the first place is that by allocating the large object (~36 MB) we would have a heap occupancy above InitiatingHeapOccupancyPercent (45% by default). The heap in this case was 64 MB and set implicitly by the JVM.
One way to make sure the concurrent GC isn't started is to explicitly set the heap size to a larger value so that we don't reach 45% occupancy when allocating the large object. I choose -Xms256m to achieve this and with that value I could run the test for 1000 iterations with no failure.
Here is an update webrev that removes my previous fix and instead adds -Xms256m to the command line. I also added -XX:+PrintGCDetails so that we have more information the next tie this test fails.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.01/
Thanks, /Staffan
ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) REASON: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage TIME: 0.34 seconds messages: command: main -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage reason: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage elapsed time (seconds): 0.34 STDOUT: Selected memory pool: Memory Pool name: G1 Old Gen Type: Heap memory Memory Usage: init = 57671680(56320K) used = 0(0K) committed = 57671680(56320K) max = 1073741824(1048576K) Threshold: 0 Manager = [G1 Old Generation] Before big object array (of size 9000000) is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0022050 secs] [Parallel Time: 1.9 ms, GC Workers: 2] [GC Worker Start (ms): Min: 124.0, Avg: 124.9, Max: 125.8, Diff: 1.9] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 0.6] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.6, Max: 1.2, Diff: 1.2, Sum: 1.2] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.0, Avg: 1.0, Max: 1.9, Diff: 1.9, Sum: 1.9] [GC Worker End (ms): Min: 125.9, Avg: 125.9, Max: 125.9, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(8192.0K)->0.0B(7168.0K) Survivors: 0.0B->1024.0K Heap: 827.8K(64.0M)->485.9K(64.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0007420 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0000750 secs] [GC remark [GC ref-proc, 0.0000810 secs], 0.0008080 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After the object is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC cleanup 34M->34M(64M), 0.0002890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After GC: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Heap garbage-first heap total 65536K, used 35642K [0x68400000, 0x6c400000, 0xa8400000) region size 1024K, 2 young (2048K), 1 survivors (1024K) Metaspace total 2435K, used 1943K, reserved 6448K data space 2240K, used 1751K, reserved 4400K class space 195K, used 192K, reserved 2048K STDERR: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) at ResetPeakMemoryUsage.testPool(ResetPeakMemoryUsage.java:118) at ResetPeakMemoryUsage.main(ResetPeakMemoryUsage.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:491) at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94) at java.lang.Thread.run(Thread.java:724)
On 20 aug 2013, at 09:57, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Shanliang --
That's curious.
If the array is unreachable, and you do a full gc (of the stop world variety -- either serial/parallel, or CMS/G1 with ExplicitGCInvokesConcurrent switched off) then the array should be reclaimed and if free space book-keeping is correct, the memory usage after should end up strictly less than memory usage before.
Are you suggesting that GC returns without actually doing anything? Or that the reduction in usage does not reflect in the "used" ? Both of those would seem to be "bugs" (in the intention of HotSpot's implementation, from what i can recall) albeit not violating the spec of system.gc().
Confused. -- ramki
On Sun, Aug 18, 2013 at 9:26 AM, shanliang <shanliang.jiang@oracle.com> wrote:
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before".
Our experience is that System.gc does not have a guarantee, so we usually have to call it many times.
I think it might be better to add something like the following code before Line 117:
int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); }
Shanliang
Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
We haven't seen this happen with CMS. /Staffan On 20 aug 2013, at 21:07, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Staffan --
Thanks for the explanation. I see. Can you check if you can replicate that behaviour with CMS also? I submit that, as Shanliang states, this is not a best efforts behavior. As I recall, in CMS, we used the full gc counts to ensure that the system gc would take effect. I'd assume that G1 should do the same thing. I am surprised that a system.gc() short circuits when a concurrent cycle is already in progress. The behaviour should be that multiple concurrent invocations to system.gc() are possibly satisfied with a single invocation, but that an already-in-progress cycle cannot be witness to satisfying an invocation that came after the concurrent cycle had already begun. I recall having thought about these semantics for CMS and made an attempt to ensure that the inetnded semantics of "best effort" was satisfied.
The behaviour that you indicate seems to me like a bug. If you reproduce the same behaviour with CMS, please let me know and I can take a look at the code. (It's been a while since I looked at it, so I don't recall all the details, except that it's fairly straightfoward.)
-- ramki
On Tue, Aug 20, 2013 at 1:31 AM, Staffan Larsen <staffan.larsen@oracle.com> wrote:
Bengt in the GC group helped me out in making sense of this. Here is my interpretation of his analysis (any errors are mine).
Pasted below is the output of the test with -XX:+PrintGCDetails added. This shows that a concurrent GC was started when the large object was allocated. After the object reference has been set to null mbean.gc() is called. But since the concurrent GC is already running, this call did nothing and the heap usage after the call was the same as before.
The reason the concurrent GC was started in the first place is that by allocating the large object (~36 MB) we would have a heap occupancy above InitiatingHeapOccupancyPercent (45% by default). The heap in this case was 64 MB and set implicitly by the JVM.
One way to make sure the concurrent GC isn't started is to explicitly set the heap size to a larger value so that we don't reach 45% occupancy when allocating the large object. I choose -Xms256m to achieve this and with that value I could run the test for 1000 iterations with no failure.
Here is an update webrev that removes my previous fix and instead adds -Xms256m to the command line. I also added -XX:+PrintGCDetails so that we have more information the next tie this test fails.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.01/
Thanks, /Staffan
ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) REASON: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage TIME: 0.34 seconds messages: command: main -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage reason: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage elapsed time (seconds): 0.34 STDOUT: Selected memory pool: Memory Pool name: G1 Old Gen Type: Heap memory Memory Usage: init = 57671680(56320K) used = 0(0K) committed = 57671680(56320K) max = 1073741824(1048576K) Threshold: 0 Manager = [G1 Old Generation] Before big object array (of size 9000000) is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0022050 secs] [Parallel Time: 1.9 ms, GC Workers: 2] [GC Worker Start (ms): Min: 124.0, Avg: 124.9, Max: 125.8, Diff: 1.9] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 0.6] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.6, Max: 1.2, Diff: 1.2, Sum: 1.2] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.0, Avg: 1.0, Max: 1.9, Diff: 1.9, Sum: 1.9] [GC Worker End (ms): Min: 125.9, Avg: 125.9, Max: 125.9, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(8192.0K)->0.0B(7168.0K) Survivors: 0.0B->1024.0K Heap: 827.8K(64.0M)->485.9K(64.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0007420 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0000750 secs] [GC remark [GC ref-proc, 0.0000810 secs], 0.0008080 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After the object is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC cleanup 34M->34M(64M), 0.0002890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After GC: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Heap garbage-first heap total 65536K, used 35642K [0x68400000, 0x6c400000, 0xa8400000) region size 1024K, 2 young (2048K), 1 survivors (1024K) Metaspace total 2435K, used 1943K, reserved 6448K data space 2240K, used 1751K, reserved 4400K class space 195K, used 192K, reserved 2048K STDERR: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) at ResetPeakMemoryUsage.testPool(ResetPeakMemoryUsage.java:118) at ResetPeakMemoryUsage.main(ResetPeakMemoryUsage.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:491) at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94) at java.lang.Thread.run(Thread.java:724)
On 20 aug 2013, at 09:57, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Shanliang --
That's curious.
If the array is unreachable, and you do a full gc (of the stop world variety -- either serial/parallel, or CMS/G1 with ExplicitGCInvokesConcurrent switched off) then the array should be reclaimed and if free space book-keeping is correct, the memory usage after should end up strictly less than memory usage before.
Are you suggesting that GC returns without actually doing anything? Or that the reduction in usage does not reflect in the "used" ? Both of those would seem to be "bugs" (in the intention of HotSpot's implementation, from what i can recall) albeit not violating the spec of system.gc().
Confused. -- ramki
On Sun, Aug 18, 2013 at 9:26 AM, shanliang <shanliang.jiang@oracle.com> wrote:
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before".
Our experience is that System.gc does not have a guarantee, so we usually have to call it many times.
I think it might be better to add something like the following code before Line 117:
int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); }
Shanliang
Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
Thx Staffan. This looks fine for now, but I suggest a CR to keep track of the G1 failure and to fix it. That CR probably belongs in the GC category, and is low priority because it's a quality of implementation issue rathe than a correctness issue wrt spec. Thanks. --Ramki ysr1729 On Aug 21, 2013, at 1:53, Staffan Larsen <staffan.larsen@oracle.com> wrote:
We haven't seen this happen with CMS.
/Staffan
On 20 aug 2013, at 21:07, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Staffan --
Thanks for the explanation. I see. Can you check if you can replicate that behaviour with CMS also? I submit that, as Shanliang states, this is not a best efforts behavior. As I recall, in CMS, we used the full gc counts to ensure that the system gc would take effect. I'd assume that G1 should do the same thing. I am surprised that a system.gc() short circuits when a concurrent cycle is already in progress. The behaviour should be that multiple concurrent invocations to system.gc() are possibly satisfied with a single invocation, but that an already-in-progress cycle cannot be witness to satisfying an invocation that came after the concurrent cycle had already begun. I recall having thought about these semantics for CMS and made an attempt to ensure that the inetnded semantics of "best effort" was satisfied.
The behaviour that you indicate seems to me like a bug. If you reproduce the same behaviour with CMS, please let me know and I can take a look at the code. (It's been a while since I looked at it, so I don't recall all the details, except that it's fairly straightfoward.)
-- ramki
On Tue, Aug 20, 2013 at 1:31 AM, Staffan Larsen <staffan.larsen@oracle.com> wrote:
Bengt in the GC group helped me out in making sense of this. Here is my interpretation of his analysis (any errors are mine).
Pasted below is the output of the test with -XX:+PrintGCDetails added. This shows that a concurrent GC was started when the large object was allocated. After the object reference has been set to null mbean.gc() is called. But since the concurrent GC is already running, this call did nothing and the heap usage after the call was the same as before.
The reason the concurrent GC was started in the first place is that by allocating the large object (~36 MB) we would have a heap occupancy above InitiatingHeapOccupancyPercent (45% by default). The heap in this case was 64 MB and set implicitly by the JVM.
One way to make sure the concurrent GC isn't started is to explicitly set the heap size to a larger value so that we don't reach 45% occupancy when allocating the large object. I choose -Xms256m to achieve this and with that value I could run the test for 1000 iterations with no failure.
Here is an update webrev that removes my previous fix and instead adds -Xms256m to the command line. I also added -XX:+PrintGCDetails so that we have more information the next tie this test fails.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.01/
Thanks, /Staffan
ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) REASON: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage TIME: 0.34 seconds messages: command: main -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage reason: User specified action: run main/othervm -XX:+PrintGCDetails -XX:+UseG1GC -Xmn8m -XX:G1HeapRegionSize=1m ResetPeakMemoryUsage elapsed time (seconds): 0.34 STDOUT: Selected memory pool: Memory Pool name: G1 Old Gen Type: Heap memory Memory Usage: init = 57671680(56320K) used = 0(0K) committed = 57671680(56320K) max = 1073741824(1048576K) Threshold: 0 Manager = [G1 Old Generation] Before big object array (of size 9000000) is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 0 Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0022050 secs] [Parallel Time: 1.9 ms, GC Workers: 2] [GC Worker Start (ms): Min: 124.0, Avg: 124.9, Max: 125.8, Diff: 1.9] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 0.6] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.6, Max: 1.2, Diff: 1.2, Sum: 1.2] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.0, Avg: 1.0, Max: 1.9, Diff: 1.9, Sum: 1.9] [GC Worker End (ms): Min: 125.9, Avg: 125.9, Max: 125.9, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(8192.0K)->0.0B(7168.0K) Survivors: 0.0B->1024.0K Heap: 827.8K(64.0M)->485.9K(64.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0007420 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0000750 secs] [GC remark [GC ref-proc, 0.0000810 secs], 0.0008080 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After the object is allocated: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) [GC cleanup 34M->34M(64M), 0.0002890 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] After GC: Current Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Peak Usage: Initial size = 57671680 (56320K) Used size = 34400384 (33594K) Committd size = 57671680 (56320K) Max size = 1073741824 (1048576K) Heap garbage-first heap total 65536K, used 35642K [0x68400000, 0x6c400000, 0xa8400000) region size 1024K, 2 young (2048K), 1 survivors (1024K) Metaspace total 2435K, used 1943K, reserved 6448K data space 2240K, used 1751K, reserved 4400K class space 195K, used 192K, reserved 2048K STDERR: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be > After GC: used = 34400384 (33594K) at ResetPeakMemoryUsage.testPool(ResetPeakMemoryUsage.java:118) at ResetPeakMemoryUsage.main(ResetPeakMemoryUsage.java:60) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:491) at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94) at java.lang.Thread.run(Thread.java:724)
On 20 aug 2013, at 09:57, Srinivas Ramakrishna <ysr1729@gmail.com> wrote:
Hi Shanliang --
That's curious.
If the array is unreachable, and you do a full gc (of the stop world variety -- either serial/parallel, or CMS/G1 with ExplicitGCInvokesConcurrent switched off) then the array should be reclaimed and if free space book-keeping is correct, the memory usage after should end up strictly less than memory usage before.
Are you suggesting that GC returns without actually doing anything? Or that the reduction in usage does not reflect in the "used" ? Both of those would seem to be "bugs" (in the intention of HotSpot's implementation, from what i can recall) albeit not violating the spec of system.gc().
Confused. -- ramki
On Sun, Aug 18, 2013 at 9:26 AM, shanliang <shanliang.jiang@oracle.com> wrote:
I think the test was to test whether mbean.gc() did its job, so the test has to make sure that the MemoryUsage "after" must be LESS "before".
Our experience is that System.gc does not have a guarantee, so we usually have to call it many times.
I think it might be better to add something like the following code before Line 117:
int = 0; while (usage2.getUsed() >= usage1.getUsed() && i++ < 600) { mbean.gc(); Thread.sleep(200); }
Shanliang
Staffan Larsen wrote:
It maybe only happens with G1, but I don't think there is a guarantee that mbean.gc() will always cause all "freed" objects to be reclaimed. By allowing for the heap usage to be the same both before and after mbean.gc() I was hoping to make the test more stable.
But perhaps someone from the GC side can comment on what the guarantees are for mbean.gc() (which calls Runtime.gc() which calls JVM_GC() which does Universe::heap()->collect(GCCause::_java_lang_system_gc)) ?
Thanks, /Staffan
On 15 aug 2013, at 21:41, Mandy Chung <mandy.chung@oracle.com> wrote:
Hi Staffan,
Is this issue specific to G1 such as mbean.gc() doesn't collect the "freed" obj? The test wants to verify the peak usage won't change when GC frees up some space.
Mandy
On 8/15/2013 12:05 PM, Staffan Larsen wrote:
Please review this small update to the test. The fix allows for no change in heap usage to happen during a GC.
webrev: http://cr.openjdk.java.net/~sla/8023101/webrev.00/ bug: http://bugs.sun.com/view_bug.do?bug_id=8023101 (not available yet) jbs: https://jbs.oracle.com/bugs/browse/JDK-8023101
Thanks, /Staffan
participants (6)
-
Bengt Rutisson
-
Jon Masamitsu
-
Mandy Chung
-
shanliang
-
Srinivas Ramakrishna
-
Staffan Larsen