JDK-4779460 : OutOfMemory happens when the perm heap is filled by softly referenced objects
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 1.4.0
  • Priority: P3
  • Status: Closed
  • Resolution: Duplicate
  • OS: windows_nt
  • CPU: x86
  • Submitted: 2002-11-15
  • Updated: 2003-08-21
  • Resolved: 2003-08-21
Related Reports
Relates :  
JDK-4796926 - Loading java.lang.Shutdown when permanent generation is full crashes JVM
Relates :  
JDK-4730581 - Hopper will consume all the heap memory lastly
Description
OutOfMemory happens when the permanent generation is filled by 
softly referenced objects even if the total heap is not used up.

-------------------------------------------------------------------------------
To reproduce this bug, please use attached zip file and jar file.

src.zip includes following source files.

 MainEntry.java
  The entry point for the sample program. 
  It repeatedly creates a class loader, loads a target class,
  gets bean info using Introspector and remove class and class loader 
  objects.
 
 VariableJarClassLoader
  A Sample Class Loader which loads a jar file and retrieve a class.

 Target.java 
  Target class to be loaded.

Target.jar includes compiled Target class.


USAGE:

 1. Compile MainEntry.java and VariableJarClassLoader.java.
 
 2. Run MainEntry limiting the MaxPermSize as following. (Tested on Windows.)
  java -Xms64M -Xmx128M -XX:MaxPermSize=2M -verbose:gc        test_softref.MainEntry                                 <absolute path of target.jar>                          test_softref.Target


RESULTS:
 - JDK 1.3.1_0x and 1.4.1_0x
    After about 400 times of GC, The Introspector cache is filled by bean info 
    objects and OutOfMemory happens. It happens because the Introspector cache 
    is implemented as the HashTable in those versions of JDK. (BugID: 4730581)
    
 - JDK 1.4.0_0x
    The Introspector cache is implemented as the SoftReference.
    After about 100 times of normal GC, during the first full GC, VM tries 
    to unload softly referenced bean info objects in the Introspector cache. 
    However, the permanent generation is filled up by those objects and the 
    OutOfMemory happens. (This bug)

------------------------------------------------------------------------------
This bug is found in a licensee's J2EE application server which
uses many class loaders. It should be fixed soon because
it causes serious server crash.
Comments
EVALUATION I tried to reproduce this bug, using % java -showversion -Xms64M -Xmx128M -XX:MaxPermSize=2M -verbose:gc test_softref.MainEntry /net/jano.SFBay/export/disk20/GammaBase/4779460 test_softref.Target java version "1.4.2-beta" Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2-beta-b06) Java HotSpot(TM) Client VM (build 1.4.2-beta-b06, mixed mode) as it said in the bug report. It ran my machine out of virtual memory and then dumped core (1.5GB, my machine has 1GB of real memory). Here's the crash report from that: An unexpected exception has been detected in native code outside the VM. Unexpected Signal : 11 occurred at PC=0xFF237320 Function=strncpy+0x30 Library=/usr/lib/libc.so.1 Current Java thread: at java.util.zip.ZipFile.open(Native Method) at java.util.zip.ZipFile.<init>(ZipFile.java:112) at java.util.jar.JarFile.<init>(JarFile.java:127) at java.util.jar.JarFile.<init>(JarFile.java:92) at test_softref.VariableJarClassLoader.getClassBytes(VariableJarClassLoader.java:82) at test_softref.VariableJarClassLoader.findClass(VariableJarClassLoader.java:61) - locked <0xf10852c0> (a java.lang.Object) at test_softref.VariableJarClassLoader.loadClass(VariableJarClassLoader.java:41) at test_softref.MainEntry.<init>(MainEntry.java:32) at test_softref.MainEntry.main(MainEntry.java:48) Dynamic libraries: 0x10000 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/bin/java 0xff350000 /usr/lib/libthread.so.1 0xff390000 /usr/lib/libdl.so.1 0xff200000 /usr/lib/libc.so.1 0xff330000 /usr/platform/SUNW,Ultra-60/lib/libc_psr.so.1 0xfe000000 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/jre/lib/sparc/client/libjvm.so 0xff2d0000 /usr/lib/libCrun.so.1 0xff1e0000 /usr/lib/libsocket.so.1 0xff100000 /usr/lib/libnsl.so.1 0xff0d0000 /usr/lib/libm.so.1 0xff1b0000 /usr/lib/libsched.so.1 0xff310000 /usr/lib/libw.so.1 0xff0a0000 /usr/lib/libmp.so.2 0xff060000 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/jre/lib/sparc/native_threads/libhpi.so 0xff020000 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/jre/lib/sparc/libverify.so 0xfe7c0000 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/jre/lib/sparc/libjava.so 0xfe7a0000 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/jre/lib/sparc/libzip.so Heap at VM Abort: Heap def new generation total 7168K, used 725K [0xf1000000, 0xf1730000, 0xf1e30000) eden space 6976K, 7% used [0xf1000000, 0xf1085450, 0xf16d0000) from space 192K, 99% used [0xf1700000, 0xf172fff0, 0xf1730000) to space 192K, 0% used [0xf16d0000, 0xf16d0000, 0xf1700000) tenured generation total 58304K, used 20012K [0xf1e30000, 0xf5720000, 0xf9000000) the space 58304K, 34% used [0xf1e30000, 0xf31bb258, 0xf31bb400, 0xf5720000) compacting perm gen total 4096K, used 1146K [0xf9000000, 0xf9400000, 0xf9400000) the space 4096K, 27% used [0xf9000000, 0xf911ea10, 0xf911ec00, 0xf9400000) Local Time = Fri Nov 15 17:42:05 2002 Elapsed Time = 2798 # # The exception above was detected in native code outside the VM # # Java VM: Java HotSpot(TM) Client VM (1.4.2-beta-b06 mixed mode) # where the heap looks pretty modest, even the "compacting perm gen", where we load and unload classes seems pretty reasonable. The fact that it ran out of memory in ZipFile.open may be a red herring, as if we are running out of memory, it's just the call that pushes us over the edge that gets reported, not necessarily the code that's holding onto storage it shouldn't. I'm running it again with -XX:+PrintGC -XX:+PrintGCDetails, and the heap is again pretty well behaved: [GC [DefNew: 7167K->192K(7168K), 0.0342213 secs] 64830K->58464K(65472K), 0.0343855 secs] [GC [DefNew: 7167K->191K(7168K), 0.0411550 secs][Tenured: 58882K->1508K(58944K), 0.3011977 secs] 65440K->1508K(66112K), 0.3435108 secs] filling up a modest (not nearly -Xmx) heap and collecting down to almost nothing. Meanwhile, the process is out of control: % ps auxww | head -2 USER PID %CPU %MEM SZ RSS TT S START TIME COMMAND pbk 14477 50.7 70.5747848710056 pts/25 O 09:31:34 16:54 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/bin/java -showversion -Xms64M -Xmx128M -XX:MaxPermSize=2M -XX:+PrintGC -XX:+PrintGCDetails test_softref.MainEntry /net/jano.SFBay/export/disk20/GammaBase/4779460 test_softref.Target That looks like it's using 70% of my memory, which top(1) confirms: PID USERNAME THR PRI NICE SIZE RES STATE TIME CPU COMMAND 14477 pbk 11 0 10 870M 718M cpu0 20:47 50.34% java and I'm rapidly running out of swap space according to vmstat procs memory page disk faults cpu r b w swap free re mf pi po fr de sr s0 s1 s2 -- in sy cs us sy id 0 0 0 8096 4632 0 89 8 2 17 0 4 1 1 0 0 457 1082 513 34 1 65 ... 0 0 0 808048 29416 0 81 7 0 631 0 700 2 0 0 0 604 16871 739 33 21 45 (The first line is before I started the program. The second line is when I started worrying about it.) The bug report says it's a problem with SoftReferences, but the version of the program I got from the attachments has all the SoftReference uses commented out, so in fact there are no SoftReferences to get in trouble. I suggest that this is not a bug in the garbage collector, but rather a leak in some native library. Hmm, maybe it's that the main loop doesn't have any pauses in it. I'll put a Thread.sleep(10) in it and see if that helps. E.g., if ZipFile is depending on finalizers to clean up native buffers, that will give it a chance to catch up. ###@###.### 2002-11-18 ---------------------------------------------------------------- I don't think it's waiting for finalization. I added this code to the main loop: int count = 0; ... count += 1; if (count % 1000 == 0) { /* PBK: System.out.println("Sleeping ..."); */ try { Thread.sleep(100); } catch (InterruptedException ie) { } } with the println there it runs like Sleeping ... Sleeping ... Sleeping ... Sleeping ... 0.000: [GC 0.000: [DefNew: 6847K->192K(7040K), 0.0456920 secs] 6847K->853K(65344K), 0.0459222 secs] Sleeping ... Sleeping ... Sleeping ... Sleeping ... Sleeping ... 2.062: [GC 2.062: [DefNew: 7039K->191K(7040K), 0.0473603 secs] 7701K->1537K(65344K), 0.0476169 secs] so I'm pretty sure it's sleeping. Then letting it run in parallel with a "ps auxww | grep java | grep -v grep; sleep 60" in a loop, after 10 minutes it was at 559.080: [GC 559.080: [DefNew: 7167K->192K(7168K), 0.0338958 secs] 28255K->21890K(65472K), 0.0341093 secs] 561.777: [GC 561.777: [DefNew: 7167K->191K(7168K), 0.0471661 secs] 28866K->22500K(65472K), 0.0590032 secs] pbk 15489 40.4 36.7404160369136 pts/25 O 15:35:31 7:40 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/bin/java -showversion -Xms64M -Xmx128M -XX:MaxPermSize=2M -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps test_softref.MainEntry /net/jano.SFBay/export/disk20/GammaBase/4779460 test_softref.Target 564.367: [GC 564.367: [DefNew: 7167K->191K(7168K), 0.0341797 secs] 29475K->23110K(65472K), 0.0343957 secs] 566.918: [GC 566.921: [DefNew: 7167K->191K(7168K), 0.0343511 secs] 30086K->23721K(65472K), 0.0345776 secs] 569.433: [GC 569.433: [DefNew: 7167K->192K(7168K), 0.0314837 secs] 30697K->24331K(65472K), 0.0316820 secs] 571.951: [GC 571.952: [DefNew: 7167K->191K(7168K), 0.0341211 secs] 31307K->24941K(65472K), 0.0343331 secs] 574.489: [GC 574.489: [DefNew: 7167K->191K(7168K), 0.0344818 secs] 31917K->25552K(65472K), 0.0346860 secs] 577.017: [GC 577.017: [DefNew: 7167K->191K(7168K), 0.0335098 secs] 32528K->26163K(65472K), 0.0337184 secs] 579.536: [GC 579.536: [DefNew: 7167K->192K(7168K), 0.0417267 secs] 33139K->26773K(65472K), 0.0420458 secs] 582.147: [GC 582.148: [DefNew: 7167K->191K(7168K), 0.0302400 secs] 33749K->27383K(65472K), 0.0304459 secs] 584.659: [GC 584.659: [DefNew: 7167K->191K(7168K), 0.0320655 secs] 34359K->27994K(65472K), 0.0322691 secs] 587.207: [GC 587.207: [DefNew: 7167K->191K(7168K), 0.0307172 secs] 34970K->28604K(65472K), 0.0309219 secs] 589.719: [GC 589.719: [DefNew: 7167K->192K(7168K), 0.0313076 secs] 35580K->29214K(65472K), 0.0314997 secs] 592.280: [GC 592.280: [DefNew: 7167K->191K(7168K), 0.0343298 secs] 36190K->29824K(65472K), 0.0345155 secs] 594.788: [GC 594.788: [DefNew: 7167K->191K(7168K), 0.0334665 secs] 36800K->30435K(65472K), 0.0336905 secs] 597.304: [GC 597.305: [DefNew: 7167K->191K(7168K), 0.0325588 secs] 37411K->31046K(65472K), 0.0327815 secs] 599.815: [GC 599.815: [DefNew: 7167K->192K(7168K), 0.0327349 secs] 38022K->31656K(65472K), 0.0329368 secs] 602.457: [GC 602.457: [DefNew: 7167K->191K(7168K), 0.0318514 secs] 38632K->32266K(65472K), 0.0320508 secs] 604.999: [GC 604.999: [DefNew: 7167K->191K(7168K), 0.0350689 secs] 39242K->32877K(65472K), 0.0352934 secs] 607.559: [GC 607.559: [DefNew: 7167K->191K(7168K), 0.0304370 secs] 39853K->33487K(65472K), 0.0306356 secs] 610.078: [GC 610.079: [DefNew: 7167K->192K(7168K), 0.0320216 secs] 40463K->34098K(65472K), 0.0322235 secs] 612.617: [GC 612.617: [DefNew: 7167K->191K(7168K), 0.0311218 secs] 41074K->34708K(65472K), 0.0313270 secs] 615.140: [GC 615.140: [DefNew: 7167K->191K(7168K), 0.0342171 secs] 41684K->35318K(65472K), 0.0344415 secs] 617.663: [GC 617.663: [DefNew: 7167K->191K(7168K), 0.0296645 secs] 42294K->35929K(65472K), 0.0298756 secs] 620.311: [GC 620.311: [DefNew: 7167K->192K(7168K), 0.0347715 secs] 42905K->36539K(65472K), 0.0349709 secs] 622.949pbk 15489 40.5 39.8435760400736 pts/25 O 15:35:31 8:29 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/bin/java -showversion -Xms64M -Xmx128M -XX:MaxPermSize=2M -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps test_softref.MainEntry /net/jano.SFBay/export/disk20/GammaBase/4779460 test_softref.Target : [GC 622.958: [DefNew: 7167K->191K(7168K), 0.0380175 secs] 43515K->37149K(65472K), 0.0382305 secs] 625.482: [GC 625.482: [DefNew: 7167K->191K(7168K), 0.0345713 secs] 44125K->37760K(65472K), 0.0347612 secs] 628.010: [GC 628.010: [DefNew: 7167K->191K(7168K), 0.0347346 secs] 44736K->38371K(65472K), 0.0349319 secs] so it's used up 40% of my 1GB of real memory. (435MB size, 400MB resident). Occasionally, but not in the quoted interval, it does a tenured collection because the young generation promotes in to the old generation causing it to be too full: 469.185: [GC 469.185: [DefNew: 7167K->191K(7168K), 0.0344098 secs] 64212K->57846K(65472K), 0.0346357 secs] 471.696: [GC 471.696: [DefNew: 7167K->191K(7168K), 0.0347460 secs] 64822K->58457K(65472K), 0.0349706 secs] 474.226: [GC 474.226: [DefNew: 7167K->191K(7168K), 0.0391290 secs]474.266: [Tenured: 58875K->1554K(58944K), 0.2827334 secs] 65433K->1554K(66112K), 0.3232169 secs] 477.088: [GC 477.089: [DefNew: 6975K->191K(7168K), 0.0330400 secs] 8530K->2357K(65472K), 0.0332447 secs] 479.654: [GC 479.654: [DefNew: 7167K->191K(7168K), 0.0331417 secs] 9333K->2967K(65472K), 0.0333368 secs] 482.177: [GC 482.178: [DefNew: 7167K->191K(7168K), 0.0311761 secs] 9943K->3577K(65472K), 0.0313732 secs] But it doesn't look like it's in the heap. I wonder if it's leakage from the VM or some native code in the libraries. I tried changing the code in the loop to /* PBK: */ count += 1L; /* PBK: */ if ((count % (100L*1000L)) == 0L) { /* PBK: */ System.out.println("Collecting ..." + " count: " + Long.toString(count)); /* PBK: */ System.gc(); /* PBK: */ } and got 575.034: [GC 575.035: [DefNew: 7167K->191K(7168K), 0.0310230 secs] 13925K->7559K(65472K), 0.0312227 secs] 577.100: [GC 577.100: [DefNew: 7167K->191K(7168K), 0.0361367 secs] 14535K->8170K(65472K), 0.0363400 secs] pbk 15671 51.0 40.4484856406880 pts/25 O 16:11:43 9:53 /net/analemma.SFBay/export/home/analemma/pbk/deployed/JDK-1.4.2/bin/java -showversion -Xms64M -Xmx128M -XX:MaxPermSize=2M -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps test_softref.MainEntry /net/jano.SFBay/export/disk20/GammaBase/4779460 test_softref.Target 579.214: [GC 579.215: [DefNew: 7167K->191K(7168K), 0.0296191 secs] 15146K->8780K(65472K), 0.0298134 secs] 581.252: [GC 581.252: [DefNew: 7167K->192K(7168K), 0.0396193 secs] 15756K->9391K(65472K), 0.0398561 secs] 583.331: [GC 583.331: [DefNew: 7167K->191K(7168K), 0.0330194 secs] 16367K->10001K(65472K), 0.0332018 secs] 585.391: [GC 585.391: [DefNew: 7167K->191K(7168K), 0.0331047 secs] 16977K->10611K(65472K), 0.0333262 secs] 587.417: [GC 587.418: [DefNew: 7167K->191K(7168K), 0.0382271 secs] 17587K->11222K(65472K), 0.0386491 secs] 589.492: [GC 589.492: [DefNew: 7167K->192K(7168K), 0.0318006 secs] 18198K->11832K(65472K), 0.0319849 secs] 591.568: [GC 591.568: [DefNew: 7167K->191K(7168K), 0.0334933 secs] 18808K->12442K(65472K), 0.0337112 secs] 593.647: [GC 593.647: [DefNew: 7167K->191K(7168K), 0.0309984 secs] 19418K->13053K(65472K), 0.0311858 secs] 595.689: [GC 595.689: [DefNew: 7167K->191K(7168K), 0.0292268 secs] 20029K->13664K(65472K), 0.0294237 secs] 597.748: [GC 597.748: [DefNew: 7167K->192K(7168K), 0.0291649 secs] 20640K->14274K(65472K), 0.0293835 secs] Collecting ... count: 1500000 598.812: [Full GC 598.812: [Tenured: 14082K->479K(58304K), 0.1070254 secs] 17668K->479K(65472K), [Perm : 1148K->1148K(4096K)], 0.1073190 secs] 600.929: [GC 600.929: [DefNew: 6975K->191K(7168K), 0.0336447 secs] 7455K->1282K(65472K), 0.0338375 secs] so we've been forcing the full collections, but they aren't helping. ###@###.### 2002-11-18 ---------------------------------------------------------------- I really wanted to blame this on finalizers, so I changed the code I added to the main loop to /* PBK: Thread.yield(); */ /* PBK: */ count += 1; /* PBK: */ if ((count % (100*1000)) == 0) { /* PBK: */ System.out.println("Collecting ..." + /* PBK: */ " count: " + Integer.toString(count)); /* PBK: */ System.gc(); /* PBK: */ try { /* PBK: */ Thread.sleep(100); /* PBK: */ } catch (Interru
11-06-2004
SUGGESTED FIX The lifetime of softly referenced objects are calculated as milliseconds per free megabyte in the total heap. Free space in total heap (MB) x SoftRefLRU (MS) http://java.sun.com/docs/hotspot/PerformanceFAQ.html#175 However, it does not consider the free space in the permanent generation. This calculation should be fixed as if the lifetime is shorten when the free space in the permanent generation is small. For example, min( Free space in total heap x SoftRefLRU , Free space in the perm gen. x SoftRefLRU ) or Simply 0 lifetime when the free space in the permanent generation is small.
11-06-2004
EVALUATION ptedException ie) { /* PBK: */ } /* PBK: */ System.gc(); /* PBK: */ count = 0; /* PBK: */ } the first System.gc() should identify any unreachable objects. The Thread.sleep(100) is to allow any finalizers to run. The second System.gc() should collect any unreachable finalized objects. In fact, you can see the first collection doing most of the work (17820K->3027K), but the second collection does sometimes find objects to free (3027K->89K). James showed me how to use the Forte analyzer to look for memory leaks. % setenv PATH /net/guild.eng/export/D0/train_src/k2/dist/sparc-S2/bin:$PATH % collect -d /tmp -j on -H on -p 500 $Deployed/JDK-1.4.2/bin/java -showversion -Xms64M -Xmx128M -XX:MaxPermSize=2M -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps test_softref.MainEntry /net/jano.SFBay/export/disk20/GammaBase/4779460 test_softref.Target ... 263.140: [GC 263.140: [DefNew: 7167K->192K(7168K), 0.0341928 secs] 20791K->14425K(65472K), 0.0344049 secs] Collecting ... count: 200000 266.769: [Full GC 266.769: [Tenured: 14233K->3027K(58304K), 0.1087118 secs] 17820K->3027K(65472K), [Perm : 1149K->1149K(4096K)], 0.1090176 secs] 266.986: [Full GC 266.986: [Tenured: 3027K->89K(58304K), 0.0349338 secs] 3027K->89K(65472K), [Perm : 1149K->1148K(4096K)], 0.0352376 secs] 274.173: [GC 274.174: [DefNew: 6975K->191K(7168K), 0.0336515 secs] 7065K->891K(65472K), 0.0338605 secs] % analyzer -j $Deployed/JDK-1.4.2 /tmp/test.1.er and the top two leaks are Summary Results: Distinct Leaks = 1151, Total Instances = 213232, Total Bytes Leaked = 54230598 Leak #1, Instances = 194158, Bytes Leaked = 49704448 malloc + 0x00000150 <static>@0x1e78 + 0x00000194 Java_java_util_zip_ZipFile_open + 0x00000074 java.util.zip.ZipFile.open + 0x00000064 java.util.zip.ZipFile.<init> + 0x000001D0 test_softref.VariableJarClassLoader.getClassBytes + 0x00000074 test_softref.VariableJarClassLoader.findClass + 0x000001EC test_softref.VariableJarClassLoader.loadClass + 0x00000044 test_softref.MainEntry.<init> + 0x000002EC <Unknown> + 0xF9470B78 Interpreter + 0x00000DA4 call_stub + 0x00000058 JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*) + 0x00000274 jni_invoke_static(JNIEnv_*,JavaValue*,_jobject*,JNICallType,_jmethodID*,JNI_ArgumentPusher*,Thread*) + 0x00000218 jni_CallStaticVoidMethod + 0x0000013C main + 0x000013A4 _start + 0x00000108 Leak #2, Instances = 13000, Bytes Leaked = 3328000 malloc + 0x00000150 <static>@0x1e78 + 0x00000194 Java_java_util_zip_ZipFile_open + 0x00000074 java.util.zip.ZipFile.open + 0x00000064 java.util.zip.ZipFile.<init> + 0x000001D0 test_softref.VariableJarClassLoader.getClassBytes + 0x00000074 test_softref.VariableJarClassLoader.findClass + 0x000001EC test_softref.VariableJarClassLoader.loadClass + 0x00000044 Interpreter + 0x00000C50 Interpreter + 0x00000DA4 call_stub + 0x00000058 JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*) + 0x00000274 jni_invoke_static(JNIEnv_*,JavaValue*,_jobject*,JNICallType,_jmethodID*,JNI_ArgumentPusher*,Thread*) + 0x00000218 jni_CallStaticVoidMethod + 0x0000013C main + 0x000013A4 _start + 0x00000108 Note the correspondence between having run the program through somewhat more than 200000 iterations (from the "Collecting ... count: 200000" line), and analyzer's saying that Java_java_util_zip_ZipFile_open + 0x00000074 has leaked 194158 + 13000 = 207158 instances. These "only" account for 49704448 + 3328000 = 53032448 or 50MB, but that's because I only let it run that long. ###@###.### 2002-11-19 ---------------------------------------------------------------- The same program, without my calls to System.gc(), seems to run fine on JDK-1.4.2 on Windohs NT 4.0. Some sample output: 1393.988: [GC 1393.988: [DefNew: 4543K->447K(4544K), 0.0123936 secs] 7779K->3688K(65088K), 0.0125609 secs] 1396.388: [GC 1396.388: [DefNew: 4543K->448K(4544K), 0.0126421 secs] 7784K->3693K(65088K), 0.0128308 secs] 1398.766: [GC 1398.766: [DefNew: 4543K->447K(4544K), 0.0120823 secs] 7789K->3699K(65088K), 0.0122498 secs] Not Collecting ... count: 1700000 1401.158: [GC 1401.159: [DefNew: 4543K->448K(4544K), 0.0127583 secs] 7795K->3705K(65088K), 0.0129257 secs] 1403.542: [GC 1403.542: [DefNew: 4543K->447K(4544K), 0.0123052 secs] 7801K->3710K(65088K), 0.0124735 secs] 1405.943: [GC 1405.943: [DefNew: 4543K->448K(4544K), 0.0126366 secs] 7806K->3715K(65088K), 0.0128056 secs] So each young generation collection seems to be collecting about 4MB of garbage from the young generation, and promoting about 5KB to the old generation. The old generation will eventually fill up, at which point I'd expect it to either flush all the garbage, or run out of memory, depending on whether that stuff was live or not. At 5KB every 2.5 seconds, it's going to take about 9 hours to fill up the old generation. I'll just let it run. ###@###.### 2002-11-20 ---------------------------------------------------------------- One can severly limit the size of the heap to try to run it out of memory faster: % java -showversion -Xms1m -Xmx1m -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps test_softref.MainEntry $TMP/4779460 test_softref.Target (On SPARC, -Xms and -Xmx have to be about 5M if you don't want to crank a lot of other options way down.) On Windohs, that works pretty well: semeru $ $Deployed/JDK-1.4.2/bin/java -showversion -Xms1m -Xmx1m -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps test_softref.MainEntry $TMP/4779460 test_softref.Target java version "1.4.2-beta" Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2-beta-b06) Java HotSpot(TM) Client VM (build 1.4.2-beta-b06, mixed mode) ... 464.919: [GC 464.919: [DefNew: 569K->57K(576K), 0.0014742 secs] 943K->431K(960K), 0.0015495 secs] 465.199: [GC 465.199: [DefNew: 569K->57K(576K), 0.0014736 secs] 943K->431K(960K), 0.0015479 secs] 465.478: [GC 465.478: [DefNew: 569K->57K(576K), 0.1357599 secs] 943K->431K(960K), 0.1358709 secs] 465.890: [GC 465.890: [DefNew: 569K->57K(576K), 0.0014703 secs]465.892: [Tenured: 374K->383K(384K), 0.0345835 secs] 943K->431K(960K), 0.0362101 secs] 466.193: [GC 466.193: [DefNew: 511K->51K(576K), 0.0126147 secs] 895K->435K(1216K), 0.0126938 secs] 466.479: [GC 466.479: [DefNew: 563K->56K(576K), 0.0014439 secs] 947K->440K(1216K), 0.0015161 secs] 466.763: [GC 466.763: [DefNew: 568K->56K(576K), 0.0014494 secs] 952K->441K(1216K), 0.0015227 secs] ... 921.727: [GC 921.727: [DefNew: 569K->57K(576K), 0.0014810 secs] 1199K->687K(1216K), 0.0015583 secs] 922.010: [GC 922.010: [DefNew: 569K->57K(576K), 0.1322962 secs] 1199K->687K(1216K), 0.1324073 secs] 922.414: [GC 922.414: [DefNew: 569K->57K(576K), 0.0014769 secs]922.416: [Tenured: 630K->390K(640K), 0.0369599 secs] 1199K->390K(1216K), 0.0385771 secs] 922.742: [GC 922.743: [DefNew: 511K->57K(576K), 0.0038315 secs] 901K->447K(1216K), 0.0039089 secs] 923.024: [GC 923.024: [DefNew: 569K->57K(576K), 0.0014741 secs] 959K->447K(1216K), 0.0015457 secs] 923.308: [GC 923.308: [DefNew: 569K->57K(576K), 0.0014700 secs] 959K->448K(1216K), 0.0015411 secs] and I killed it shortly after that. I was asked to try it with JDK-1.4.0. That seems to be accumulating garbage much less quickly. Where JDK-1.4.2 only took 7+1/2 minutes to get to it's first collection (when a young generation collection couldn't guaranteee room in the old generation?), and then got there again in another 7+1/2 minutes, JDK-1.4.0 looks like: semeru $ $Deployed/JDK-1.4.0/bin/java -showversion -Xms1m -Xmx1m -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps test_softref.MainEntry $TMP/4779460 test_softref.Target java version "1.4.0" Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.0-b92) Java HotSpot(TM) Client VM (build 1.4.0-b92, mixed mode) ... 899.136: [GC 899.136: [DefNew: 567K->55K(576K), 0.0014255 secs] 860K->349K(960K), 0.0014980 secs] 899.421: [GC 899.421: [DefNew: 567K->55K(576K), 0.0013580 secs] 861K->348K(960K), 0.0014286 secs] 899.719: [GC 899.719: [DefNew: 567K->55K(576K), 0.0014402 secs] 860K->349K(960K), 0.0015139 secs] 900.011: [GC 900.011: [DefNew: 567K->54K(576K), 0.0013580 secs] 861K->348K(960K), 0.0014277 secs] 900.307: [GC 900.307: [DefNew: 566K->55K(576K), 0.0013898 secs] 860K->349K(960K), 0.0014629 secs] 900.6: [GC 900.6: [DefNew: 567K->54K(576K), 0.0013899 secs] 861K->348K(960K), 0.0014592 secs] 900.885: [GC 900.885: [DefNew: 566K->55K(576K), 0.0014385 secs] 860K->349K(960K), 0.0015110 secs] ... 1424.42: [GC 1424.42: [DefNew: 567K->54K(576K), 0.0013689 secs] 941K->429K(960K), 0.0014408 secs] 1424.72: [GC 1424.72: [DefNew: 566K->55K(576K), 0.0013862 secs] 941K->429K(960K), 0.0016419 secs] 1425.01: [GC 1425.01: [DefNew: 567K->55K(576K), 0.0014263 secs] 941K->429K(960K), 0.0015003 secs] 1425.3: [GC 1425.3: [DefNew: 567K->55K(576K), 0.0014088 secs]1425.3: [Tenured: 374K->195K(384K), 0.0283865 secs] 941K->195K(960K), 0.0299476 secs] 1425.59: [GC 1425.59: [DefNew: 511K->52K(576K), 0.0015621 secs] 707K->248K(960K), 0.0016409 secs] 1425.88: [GC 1425.88: [DefNew: 564K->55K(576K), 0.0014986 secs] 760K->253K(960K), 0.0015690 secs] 1426.17: [GC 1426.17: [DefNew: 567K->55K(576K), 0.0014683 secs] 765K->253K(960K), 0.0015426 secs] So it's doing fine at 15 minutes, and takes until 23 minutes to get to where it needs a full collection. Then it's back to a small old generation again, and I have no reason to think it won't just cycle like that. I assume the differences between JDK-1.4.0 and JDK-1.4.2 are from library differences, not JVM changes, but I've been wrong before. So, I can't reproduce the problem that the bug is complaining about, but I am having what looks like a storage leak from ZipFiles on Solaris. I'll file a bug against that. ###@###.### 2002-11-26 ---------------------------------------------------------------- Using the command line java -showversion -Xms64M -Xmx128M -XX:MaxPermSize=2M -verbose:gc -XX:+PrintHeapAtGC test_softref.MainEntry <path_to>/target.jar test_softref.Target I am now able to reproduce the problem on Windohs, on both JDK-1.4.0 and JDK-1.4.2 I'm reopening the bug. ###@###.### 2002-11-27 I've discovered the reason -XX:MaxPermGen=2M was crashing JDK-1.4.2, and filed 4796926: Loading java.lang.Shutdown when permanent generation is full crashes JVM to track it. I now consider this bug closed as far as JDK-1.4.2 is concerned. ###@###.### 2002-12-20 ---------------------------------------------------------------- See 4785314 which is tracking the storage leak from ZipFile. ###@###.### 2003-08-21 ----------------------------------------------------------------
21-08-2003