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.lar...@oracle.com> wrote: > We haven't seen this happen with CMS. > > /Staffan > > On 20 aug 2013, at 21:07, Srinivas Ramakrishna <ysr1...@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.lar...@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 <ysr1...@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.ji...@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.ch...@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 >
