Name: ks84122 Date: 02/14/2003


Please see original description from HP below. The SpecJBB application is attached to this bug report. Reproducible with the latest mantis build (16) on solaris.

HP's report:
============

I see unnecessary scavenges when running SpecJBB with the following options. The scavenges appear as consecutive pairs when one at a time would have been sufficient. This effectively doubles the overall GC pause time, slowing down the run.

The following run is on a 2 proc/Linux/IA32/750 Mhz machine but I've been able to reproduce the problem on HP's JVM also.

$JAVA_HOME/bin/java
-classpath ./jbb.jar:./jbb_no_precompile.jar:./check.jar:./reporter.jar
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xmn150m -Xms200m -Xmx200m -XX:+UseParallelGC -XX:+UseAdaptiveSizePolicy
spec.jbb.JBBmain -propfile SPECjbb.props


(Note: Use a higher -Xmn if you want the scavenges to be spaced out)

...
...
...

Start Terminals
  started terminals for Warehouse 1

Benchmark SPECjbb 2.0m: warehouse 1 terminal 1

Terminal Rampup began Thu Feb 13 17:12:19 PST 2003 for 0.5 minutes
20.660: [GC 129060K->123900K(182016K), 0.0242160 secs] (scavenge #7)
21.318: [GC 130556K->26476K(182016K), 0.0230780 secs] (scavenge #8)
31.815: [GC 134508K->130228K(185408K), 0.0262060 secs]
32.272: [GC 134772K->26708K(185408K), 0.0256040 secs]
Timing Measurement began Thu Feb 13 17:12:49 PST 2003 for 2 minutes
43.259: [GC 141524K->138180K(187840K), 0.0313580 secs]
43.647: [GC 141892K->27036K(187840K), 0.0307460 secs]
55.264: [GC 146716K->143476K(189760K), 0.0331250 secs]
55.630: [GC 146868K->27204K(189760K), 0.0381670 secs]
67.567: [GC 150724K->147588K(191488K), 0.0363700 secs]
67.928: [GC 150980K->27492K(191488K), 0.0363130 secs]
80.359: [GC 154468K->151268K(193024K), 0.0417530 secs]
80.730: [GC 154660K->27668K(193024K), 0.0378780 secs]
...
...
...


Upon examining scavenge #7 (see above) closely using -XX:+PrintHeapAtGC, I see the following:


{Heap before GC invocations=7:
Heap
 PSYoungGen total 128832K, used 104064K [0x44740000, 0x4dd40000, 0x4dd40000)
  eden space 104064K, 100% used [0x44740000,0x4ace0000,0x4ace0000)
  from space 24768K, 0% used [0x4c510000,0x4c510000,0x4dd40000)
  to space 24768K, 0% used [0x4ace0000,0x4ace0000,0x4c510000)
 PSOldGen total 51200K, used 25004K [0x4dd40000, 0x50f40000, 0x50f40000)
  object space 51200K, 48% used [0x4dd40000,0x4f5ab060,0x50f40000)
 PSPermGen total 4864K, used 2677K [0x50f40000, 0x51400000, 0x54f40000)
  object space 4864K, 55% used [0x50f40000,0x511dd600,0x51400000)
20.425: [GC 129068K->124036K(182080K), 0.0258680 secs]


 Heap after GC invocations=7:
Heap
 PSYoungGen total 130880K, used 99032K [0x44740000, 0x4dd40000, 0x4dd40000) eden space 6656K, 0% used [0x44740000,0x44740000,0x44dc0000)
  from space 124224K, 79% used [0x44dc0000,0x4ae76010,0x4c710000)
  to space 22720K, 0% used [0x4c710000,0x4c710000,0x4dd40000)
 PSOldGen total 51200K, used 25004K [0x4dd40000, 0x50f40000, 0x50f40000)
  object space 51200K, 48% used [0x4dd40000,0x4f5ab060,0x50f40000)
 PSPermGen total 4864K, used 2677K [0x50f40000, 0x51400000, 0x54f40000)
  object space 4864K, 55% used [0x50f40000,0x511dd600,0x51400000)
}


Notice that after scavenge #7, the eden size reduces to a tiny 6656K from 104604K. This is very strange considering that From space goes up to
124224K. This causes the eden to get filled up soon after leading to the consecutive scavenge (#8 for above ex.). The behaviour is repeated till benchmark finishes.

I suspect this is a bug.
(Review ID: 181287)
======================================================================