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 >>>> >>>> >>>> >>>> >>>> >>
