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

shanliang shanliang.jiang at oracle.com
Tue Aug 20 08:42:24 UTC 2013


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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20130820/37922902/attachment.htm>


More information about the hotspot-gc-dev mailing list