Name: mf23781 Date: 07/20/98


The following test program demonstrates several design and
implementation flaws in the Win32 JVM garbage collector.
All the test program does is try to allocate all possible memory first,
then return about one fifth of them back to the JVM, then try
to allocate all memory again.

---------- start of MemTest.java

public class MemTest {
    byte[] buf; //buffer
    MemTest next; //points to next object in the list


    MemTest(int size, MemTest next) {
        buf = new byte[size]; //allocate requested size of memory
        this.next = next; //add to the list

    }


    static StringBuffer s = new StringBuffer(200); //preallocated message
buffer, not affected by OutOfMemory
    static void println(String header, int n, int size) {
        s.setLength(0); //reset buffer
        s.append(header); s.append(n); s.append(" Objects, approximate size
= "); s.append(size);

        System.out.println(s.toString());

    }


    // run "java -msNm -mxNm -verbosegc MemTest [size]" to test
    public static void main(String[] args) {
        MemTest list = null; //all allocated objects are in one list
        int size = args.length > 0 ? Integer.parseInt(args[0]) : 1000;
//buffer size

        int n1 = 0, n2, n3 = 0;



        try {
            for (n1 = 0; ; ++n1) //allocate all possible memory
                list = new MemTest(size, list);
        } catch (OutOfMemoryError e) {
            System.out.println("----- step1: Allocate and Out of Memory");
        }


        for (n2 = n1/5; --n2 >= 0;) //delete and unreference n1/5 objects
from the list

            list = list.next;
        System.out.println("----- step2: n2 Objects Deleted");


        try {
            for (n3 = 0; ; ++n3) //allocate all possible memory again
                list = new MemTest(size, list);
        } catch (OutOfMemoryError e) {
            System.out.println("----- step3: Allocate and Out of Memory");
        }


        System.out.println("----- n1 = " + n1 + ", n2 = " + n1/5 + ", n3 = "
+ n3);

    }

}

---------- start of MemTest.java

[1] First, run "java -verbosegc MemTest", this generates the
output below (This occurs on 1.1.6 and 1.1.7D):

java -verbosegc MemTest

<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freeing class java.lang.Compiler>

<GC: unloaded and freed 1 class>

<GC: freed 201 objects, 6480 bytes in 9 ms, 0% free (7216/838856)>
  <GC: init&scan: 5 ms, scan handles: 4 ms, sweep: 0 ms, compact: 0
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 274432 to 1113288 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 5 objects, 872 bytes in 25 ms, 0% free (7216/1113288)>
  <GC: init&scan: 0 ms, scan handles: 4 ms, sweep: 1 ms, compact: 20
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 364544 to 1477832 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 6 objects, 400 bytes in 15 ms, 0% free (1072/1477832)>
  <GC: init&scan: 1 ms, scan handles: 5 ms, sweep: 0 ms, compact: 9
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 495616 to 1973448 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 8 objects, 512 bytes in 20 ms, 0% free (1072/1973448)>
  <GC: init&scan: 2 ms, scan handles: 5 ms, sweep: 1 ms, compact: 12
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 659456 to 2632904 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 11 objects, 1048 bytes in 24 ms, 0% free (1072/2632904)>
  <GC: init&scan: 2 ms, scan handles: 6 ms, sweep: 0 ms, compact: 16
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 880640 to 3513544 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 14 objects, 688 bytes in 32 ms, 0% free (1072/3513544)>
  <GC: init&scan: 2 ms, scan handles: 7 ms, sweep: 1 ms, compact: 22
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 1171456 to 4685000 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 18 objects, 272 bytes in 43 ms, 0% free (1072/4685000)>
  <GC: init&scan: 6 ms, scan handles: 8 ms, sweep: 1 ms, compact: 28
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 1564672 to 6249672 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 24 objects, 320 bytes in 56 ms, 0% free (1072/6249672)>
  <GC: init&scan: 5 ms, scan handles: 10 ms, sweep: 1 ms, compact: 40
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 2084864 to 8334536 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 32 objects, 448 bytes in 73 ms, 0% free (1072/8334536)>
  <GC: init&scan: 4 ms, scan handles: 12 ms, sweep: 1 ms, compact: 56
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 2781184 to 11115720 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 43 objects, 920 bytes in 91 ms, 0% free (1072/11115720)>
  <GC: init&scan: 3 ms, scan handles: 16 ms, sweep: 1 ms, compact: 71
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: tried to expand object space over limit>
<GC: managing allocation failure. need 1008 bytes, type=1, action=5>
<GC: totally out of heap space>

----- step1: Allocate and Out of
Memory

----- step2: n2 Objects Deleted
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 4307 objects, 2202008 bytes in 19 ms, 19% free
(2202048/11115720)>
  <GC: init&scan: 3 ms, scan handles: 13 ms, sweep: 3 ms, compact: 0
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: expanded object space by 774144 to 11889864 bytes, 25% free>
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 46 objects, 992 bytes in 100 ms, 0% free (1472/11889864)>
  <GC: init&scan: 5 ms, scan handles: 17 ms, sweep: 1 ms, compact: 77
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: tried to expand object space over limit>
<GC: managing allocation failure. need 1008 bytes, type=1, action=5>
<GC: totally out of heap space>

----- step3: Allocate and Out of
Memory

----- n1 = 10753, n2 = 2150, n3 = 2905


It shows that the GC does not expand the memory all the way to
the maximum mapped object heap memory (= 80% of 16M = 13421772.8
by default). It also shows that the object heap can still be
expanded from 11115720 to 11889864 after the first
OutOfMemory error.
That means the first OutOfMemory is not really out of memory yet.

[2] To fully utilize the memory, one should set the -ms value
to the same as -mx.
For example, run "java -ms16m -verbosegc MemTest" will use up
all the default object heap spave available as shown by the
output below:

java -ms16m -verbosegc MemTest

<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freeing class java.lang.Compiler>

<GC: unloaded and freed 1
class>
<GC: freed 393 objects, 8032 bytes in 65 ms, 0% free (8240/13421768)>
  <GC: init&scan: 7 ms, scan handles: 38 ms, sweep: 20 ms, compact: 0
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: tried to expand object space over limit>
<GC: managing allocation failure. need 1008 bytes, type=1, action=5>
<GC: totally out of heap space>

----- step1: Allocate and Out of
Memory

----- step2: n2 Objects Deleted
<GC: managing allocation failure. need 1008 bytes, type=1, action=1>
<GC: freed 5205 objects, 2661784 bytes in 60 ms, 19% free
(2668992/13421768)>
  <GC: init&scan: 3 ms, scan handles: 34 ms, sweep: 23 ms, compact: 0
ms>

<GC: managing allocation failure. need 1008 bytes, type=1,
action=2>
<GC: managing allocation failure. need 1008 bytes, type=1, action=3>
<GC: managing allocation failure. need 1008 bytes, type=1, action=4>
<GC: tried to expand object space over limit>
<GC: managing allocation failure. need 1008 bytes, type=1, action=5>
<GC: totally out of heap space>

----- step3: Allocate and Out of
Memory

----- n1 = 12998, n2 = 2599, n3 = 0


Here we do see the object heap is expanded to its maximum.
However, it shows that we can not allocate any MemTest
object (n3 = 0) even after we returned 2599 objects
back to the heap. Therefore we failed to allocate 1008 bytes
while there are 2668992 bytes available! The situation is
worse with higher -ms and -mx values.
For example, when both are 32m we failed with 5344152 bytes of
free space!!


This bug is due to Win32 JVM's 25% pre-allocation policy. The
GC will not succeed if the free memory collected is less than
25% of the maximum object heap memory.
In the case of -mx=16m, the required free memory is
13421768*0.25 = 3355442.

As we can see, the higher the -mx the higher the
requirement.

[3] In the code of the 25% pre-allocation policy mentioned above
(see manageAllocFailure() of src\share\java\runtime\gc.c),
FreeObjectCtr is used for the measurement.
However, it is possible that, due to pinned blocks, even though
the total free memory is larger than 25% of the max object heap,
there is no one free block larger than the requested block size.
In this case, gc() will return successfully, but the allocation
will fail again and gc() is called again, and again, which
leads to an infinite loop. It is not easy to create
a test case for this scenario, but we indeed have seen this
happened before.

This was raised by the San Francisco project.

======================================================================