<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
  <meta content="text/html;charset=ISO-8859-1" http-equiv="Content-Type">
  <title></title>
</head>
<body bgcolor="#ffffff" text="#000000">
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.<br>
<br>
I looked at the System.gc Javadoc:<br>
---------------------------------------------<br>
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. <br>
---------------------------------------------<br>
"Best effect" seems not ensure that a free object would be always
reclaimed by System.gc().<br>
<br>
Thanks,<br>
Shanliang<br>
<br>
<br>
Staffan Larsen wrote:
<blockquote cite="mid:F4E1CC85-82C5-47A9-AE59-748D6DB46E7F@oracle.com"
 type="cite">
  <pre wrap="">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: <a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sla/8023101/webrev.01/">http://cr.openjdk.java.net/~sla/8023101/webrev.01/</a>

Thanks,
/Staffan



ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Before GC: used = 34400384 (33594K) expected to be &gt; 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)-&gt;0.0B(7168.0K) Survivors: 0.0B-&gt;1024.0K Heap: 827.8K(64.0M)-&gt;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-&gt;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 &gt; 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 <a class="moz-txt-link-rfc2396E" href="mailto:ysr1729@gmail.com">&lt;ysr1729@gmail.com&gt;</a> wrote:

  </pre>
  <blockquote type="cite">
    <pre wrap="">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 <a class="moz-txt-link-rfc2396E" href="mailto:shanliang.jiang@oracle.com">&lt;shanliang.jiang@oracle.com&gt;</a> wrote:
    </pre>
    <blockquote type="cite">
      <pre wrap="">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() &gt;= usage1.getUsed() &amp;&amp; i++ &lt; 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()-&gt;collect(GCCause::_java_lang_system_gc)) ?

Thanks,
/Staffan

On 15 aug 2013, at 21:41, Mandy Chung <a class="moz-txt-link-rfc2396E" href="mailto:mandy.chung@oracle.com">&lt;mandy.chung@oracle.com&gt;</a> 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: <a class="moz-txt-link-freetext" href="http://cr.openjdk.java.net/~sla/8023101/webrev.00/">http://cr.openjdk.java.net/~sla/8023101/webrev.00/</a>
bug: <a class="moz-txt-link-freetext" href="http://bugs.sun.com/view_bug.do?bug_id=8023101">http://bugs.sun.com/view_bug.do?bug_id=8023101</a> (not available yet)
jbs: <a class="moz-txt-link-freetext" href="https://jbs.oracle.com/bugs/browse/JDK-8023101">https://jbs.oracle.com/bugs/browse/JDK-8023101</a>

Thanks,
/Staffan





      </pre>
    </blockquote>
  </blockquote>
  <pre wrap=""><!---->
  </pre>
</blockquote>
<br>
</body>
</html>