RFR (S): 8023101 java/lang/management/MemoryMXBean/ResetPeakMemoryUsage.java fails

Staffan Larsen staffan.larsen at oracle.com
Wed Aug 21 08:53:15 UTC 2013


We haven't seen this happen with CMS.

/Staffan

On 20 aug 2013, at 21:07, Srinivas Ramakrishna <ysr1729 at 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 at 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 at 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 at 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 at 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
>>>> 
>>>> 
>>>> 
>>>> 
>>>> 
>> 




More information about the hotspot-gc-dev mailing list