Incremental GC has delays upto 13 seconds under jdk1.2.2 / 1.3.1 / 1.4.0-b64

 after 6 or 7 minutes, and the ratio of real work to GC work
became very poor.
  
With JDk 1.2.2_08:
-----------------
I see a maximum delay of 4041ms during the intial phase,
and then delays quite often above 500ms during the garbage phase.

GarbageMaker.run() called
Monday May 14 13:32:31 EST 2001 No signficant incremental garbage collector activity - longest so far is 0
GC[1: 27 cars] in 721 ms: (500Mb, 19% free) -> (500Mb, 20% free) [application 54 ms requested 6 words]
Monday May 14 13:32:31 EST 2001 GC duration: 721 Longest GC: 721 at Monday May 14 13:32:31 EST 2001.
GC[1: 26 cars] in 665 ms: (500Mb, 19% free) -> (500Mb, 20% free) [application 161 ms requested 8 words]
Monday May 14 13:32:33 EST 2001 GC duration: 665 Longest GC: 721 at Monday May 14 13:32:31 EST 2001.
GC[1: 25 cars] in 517 ms: (500Mb, 19% free) -> (500Mb, 20% free) [application 26 ms requested 8 words]
Monday May 14 13:32:33 EST 2001 GC duration: 517 Longest GC: 721 at Monday May 14 13:32:31 EST 2001.
GC[1: 24 cars] in 606 ms: (500Mb, 19% free) -> (500Mb, 20% free) [application 79 ms requested 8 words]
Monday May 14 13:32:34 EST 2001 GC duration: 606 Longest GC: 721 at Monday May 14 13:32:31 EST 2001.
GC[1: 23 cars] in 624 ms: (500Mb, 19% free) -> (500Mb, 20% free) [application 28 ms requested 8 words]
Monday May 14 13:32:35 EST 2001 GC duration: 624 Longest GC: 721 at Monday May 14 13:32:31 EST 2001.
GC[1: 22 cars] in 575 ms: (500Mb, 19% free) -> (500Mb, 20% free) [application 28 ms requested 8 words]
Monday May 14 13:32:36 EST 2001 GC duration: 575 Longest GC: 721 at Monday May 14 13:32:31 EST 2001.
GC[1: 14 cars] in 552 ms: (500Mb, 19% free) -> (500Mb, 20% free) [application 27 ms requested 8 words]
Monday May 14 13:32:40 EST 2001 GC duration: 552 Longest GC: 721 at Monday May 14 13:32:31 EST 2001.
Mon May 14 13:33:31 EST 2001 Total Mem: 524288000 Used: 421209612 Percent full: 80% Total Growth:
1886024 Delta since last report: 1886024
  
Attached is the testcase which contains:

memstress.java
filter.pl
run.sh

Customer Problem Description:
------------------------------
The real problem I have is that the incremental garbage collector is taking
an unacceptably long time to run. Anything over 500ms is way too long
for my needs. Even the simple program you ran shows delays as high
as 5 seconds. I have seen delays of 13 seconds under jdk1.3.

On my project, our software holds a large number ( ~ 1 million ) of small
objects in memory which it allocates at startup, and then it's pretty tidy in regard to throwing garbage. I'm seeing very large GC delays. A refined version of the test program is attached which attempts to mimic the behaviour of my project. It allocates many objects, and then throws a configurable amount of garbage per second.

A perl program filters the verbose output from the garbage collector looking
for delays which are too long.

This page http://java.sun.com/products/hotspot/whitepaper.html
claims delays are typically less than 10ms, and that
    "in practice much larger pauses are extremely rare"
This is not what I'm seeing.

I've installed JDK1.3.1-rc2-b23 , and retested the example I sent you.

I'm seeing the incremental garbage collector run for over 5000 milliseconds during the
initial phase where it makes a lot of permanent objects, and then it runs for over
3800ms during the maintenance mode where it's creating garbage at the configured rate.
It runs for OK for 6 or 7 minutes, and then the garbage collector really starts to go crazy,
taking up almost all the CPU.

zwols00a: /usr/j2se/bin/javac *.java
zwols00a: /usr/j2se/bin/java -fullversion
java full version "1.3.1-rc2-b23"
zwols00a: /usr/j2se/bin/java -Xmx500m -Xms500m -verbose:gc -Xincgc -classpath . memstress 4000000 100000 |&
filter.pl
Before any allocations, Total Mem: 2228224 Used: 154960 Percent full: 6%
Making 4000000 permanent objects
Generating garbage at 100000 objects/second
GarbageMaker.makePermanent called with 4000000 objects to make
[GC 22462K->22803K(23744K), 0.5047509 secs]
During permanent object creation, incremental garbage collector ran for 0.5047509 seconds at Saturday May 12
13:50:16 EST 2001
[GC 33663K->33663K(34752K), 0.5065041 secs]
During permanent object creation, incremental garbage collector ran for 0.5065041 seconds at Saturday May 12
13:50:19 EST 2001
[GC 45202K->45146K(46656K), 1.1735302 secs]
During permanent object creation, incremental garbage collector ran for 1.1735302 seconds at Saturday May 12
13:50:23 EST 2001
[GC 64538K->64538K(66560K), 0.8337715 secs]
During permanent object creation, incremental garbage collector ran for 0.8337715 seconds at Saturday May 12
13:50:27 EST 2001
[GC 126747K->126747K(130688K), 1.6525491 secs]
During permanent object creation, incremental garbage collector ran for 1.6525491 seconds at Saturday May 12
13:50:44 EST 2001
[GC 221436K->221436K(229056K), 5.1433864 secs]
During permanent object creation, incremental garbage collector ran for 5.1433864 seconds at Saturday May 12
13:51:16 EST 2001
[GC 251195K->251195K(259008K), 3.4290611 secs]
During permanent object creation, incremental garbage collector ran for 3.4290611 seconds at Saturday May 12
13:51:18 EST 2001
GarbageMaker.run() called
[GC 389080K->388568K(401472K), 3.8561548 secs]
Saturday May 12 13:52:08 EST 2001 GC duration: 3.8561548 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
Sat May 12 13:52:30 EST 2001 Total Mem: 403767296 Used: 391959544 Percent full: 97% Total Growth: 67976
Delta since last report: 67976
Sat May 12 13:53:31 EST 2001 Total Mem: 403898368 Used: 391691384 Percent full: 96% Total Growth:
-6204552 Delta since last report: -6272528
Sat May 12 13:54:31 EST 2001 Total Mem: 389349376 Used: 379266520 Percent full: 97% Total Growth:
-18629416 Delta since last report: -12424864
Sat May 12 13:55:31 EST 2001 Total Mem: 389349376 Used: 379438096 Percent full: 97% Total Growth:
-18457840 Delta since last report: 171576
Sat May 12 13:56:31 EST 2001 Total Mem: 389349376 Used: 379085656 Percent full: 97% Total Growth:
-18810280 Delta since last report: -352440
Sat May 12 13:57:31 EST 2001 Total Mem: 389349376 Used: 379258104 Percent full: 97% Total Growth:
-18637832 Delta since last report: 172448
Sat May 12 13:58:31 EST 2001 Total Mem: 388890624 Used: 379430776 Percent full: 97% Total Growth:
-18465160 Delta since last report: 172672
[GC 370616K->370111K(376128K), 2.4626157 secs]
Saturday May 12 13:59:32 EST 2001 GC duration: 2.4626157 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
Sat May 12 13:59:32 EST 2001 Total Mem: 385155072 Used: 378995288 Percent full: 98% Total Growth:
-18900648 Delta since last report: -435488
[GC 370622K->370110K(376128K), 0.9505609 secs]
Saturday May 12 13:59:58 EST 2001 GC duration: 0.9505609 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 1.0004925 secs]
Saturday May 12 13:59:59 EST 2001 GC duration: 1.0004925 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 1.5593028 secs]
Saturday May 12 14:00:01 EST 2001 GC duration: 1.5593028 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 1.0284250 secs]
Saturday May 12 14:00:02 EST 2001 GC duration: 1.0284250 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.8217858 secs]
Saturday May 12 14:00:03 EST 2001 GC duration: 0.8217858 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.6786859 secs]
Saturday May 12 14:00:04 EST 2001 GC duration: 0.6786859 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9989170 secs]
Saturday May 12 14:00:05 EST 2001 GC duration: 0.9989170 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.8916059 secs]
Saturday May 12 14:00:06 EST 2001 GC duration: 0.8916059 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 1.2560502 secs]
Saturday May 12 14:00:07 EST 2001 GC duration: 1.2560502 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9630469 secs]
Saturday May 12 14:00:08 EST 2001 GC duration: 0.9630469 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9730126 secs]
Saturday May 12 14:00:09 EST 2001 GC duration: 0.9730126 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 1.5842647 secs]
Saturday May 12 14:00:11 EST 2001 GC duration: 1.5842647 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9931578 secs]
Saturday May 12 14:00:12 EST 2001 GC duration: 0.9931578 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.8177933 secs]
Saturday May 12 14:00:13 EST 2001 GC duration: 0.8177933 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.6596898 secs]
Saturday May 12 14:00:14 EST 2001 GC duration: 0.6596898 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9610811 secs]
Saturday May 12 14:00:15 EST 2001 GC duration: 0.9610811 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9051505 secs]
Saturday May 12 14:00:16 EST 2001 GC duration: 0.9051505 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 1.1762498 secs]
Saturday May 12 14:00:17 EST 2001 GC duration: 1.1762498 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9379373 secs]
Saturday May 12 14:00:18 EST 2001 GC duration: 0.9379373 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9306061 secs]
Saturday May 12 14:00:19 EST 2001 GC duration: 0.9306061 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 1.5496679 secs]
Saturday May 12 14:00:20 EST 2001 GC duration: 1.5496679 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.9888239 secs]
Saturday May 12 14:00:22 EST 2001 GC duration: 0.9888239 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.8246704 secs]
Saturday May 12 14:00:23 EST 2001 GC duration: 0.8246704 Longest GC: 3.8561548 at Saturday May 12 13:52:08 EST 2001.
[GC 370622K->370110K(376128K), 0.6229889 secs]
  

With JDk 1.4 Beta Build 64 (latest):
-------------------------------------
Starting filter
Before any allocations, Total Mem: 2228224 Used: 216328 Percent full: 9%
Making 4000000 permanent objects
Generating garbage at 100000 objects/second
GarbageMaker.makePermanent called with 4000000 objects to make
[GC 7920K->7955K(10240K), 0.5454071 secs]
During permanent object creation, incremental garbage collector ran for 0.5454071 seconds at Tue May 15 16:47:39 PDT 2001
[GC 12052K->12052K(14464K), 0.6783210 secs]
During permanent object creation, incremental garbage collector ran for 0.6783210 seconds at Tue May 15 16:47:40 PDT 2001
[GC 15636K->15637K(18176K), 0.5330404 secs]
During permanent object creation, incremental garbage collector ran for 0.5330404 seconds at Tue May 15 16:47:41 PDT 2001
[GC 19733K->19734K(22336K), 0.6380961 secs]
During permanent object creation, incremental garbage collector ran for 0.6380961 seconds at Tue May 15 16:47:42 PDT 2001
[GC 21782K->21782K(24448K), 2.3952519 secs]
During permanent object creation, incremental garbage collector ran for 2.3952519 seconds at Tue May 15 16:47:45 PDT 2001
[GC 23830K->24855K(26560K), 0.8688300 secs]
During permanent object creation, incremental garbage collector ran for 0.8688300 seconds at Tue May 15 16:47:45 PDT 2001
[GC 33218K->33218K(34880K), 1.2104973 secs]
During permanent object creation, incremental garbage collector ran for 1.2104973 seconds at Tue May 15 16:47:48 PDT 2001
[GC 49083K->49083K(52032K), 0.5928229 secs]
During permanent object creation, incremental garbage collector ran for 0.5928229 seconds at Tue May 15 16:47:54 PDT 2001
[GC 49595K->49560K(52608K), 0.6929600 secs]
During permanent object creation, incremental garbage collector ran for 0.6929600 seconds at Tue May 15 16:47:55 PDT 2001
[GC 63641K->63641K(67520K), 1.3403599 secs]
During permanent object creation, incremental garbage collector ran for 1.3403599 seconds at Tue May 15 16:47:59 PDT 2001
[GC 69274K->69274K(73664K), 0.5656572 secs]
During permanent object creation, incremental garbage collector ran for 0.5656572 seconds at Tue May 15 16:48:02 PDT 2001
[GC 80027K->80027K(85376K), 0.7841327 secs]
During permanent object creation, incremental garbage collector ran for 0.7841327 seconds at Tue May 15 16:48:06 PDT 2001
[GC 81563K->81563K(87040K), 0.5379253 secs]
During permanent object creation, incremental garbage collector ran for 0.5379253 seconds at Tue May 15 16:48:08 PDT 2001
[GC 82075K->82075K(87616K), 0.6509761 secs]
During permanent object creation, incremental garbage collector ran for 0.6509761 seconds at Tue May 15 16:48:08 PDT 2001
[GC 83099K->83099K(88704K), 0.5479509 secs]
During permanent object creation, incremental garbage collector ran for 0.5479509 seconds at Tue May 15 16:48:09 PDT 2001
[GC 83611K->83612K(89280K), 0.8858905 secs]
During permanent object creation, incremental garbage collector ran for 0.8858905 seconds at Tue May 15 16:48:10 PDT 2001
[GC 84124K->84124K(89856K), 0.5489988 secs]
During permanent object creation, incremental garbage collector ran for 0.5489988 seconds at Tue May 15 16:48:11 PDT 2001
[GC 85660K->85660K(91520K), 0.7476880 secs]
During permanent object creation, incremental garbage collector ran for 0.7476880 seconds at Tue May 15 16:48:12 PDT 2001
[GC 86172K->86172K(92032K), 0.5004234 secs]
During permanent object creation, incremental garbage collector ran for 0.5004234 seconds at Tue May 15 16:48:13 PDT 2001
[GC 108703K->108319K(116352K), 12.9414651 secs]
During permanent object creation, incremental garbage collector ran for 12.9414651 seconds at Tue May 15 16:48:33 PDT 2001
[GC 126239K->126239K(134720K), 3.4879746 secs]
During permanent object creation, incremental garbage collector ran for 3.4879746 seconds at Tue May 15 16:48:40 PDT 2001
[GC 141089K->141089K(150976K), 0.6529463 secs]
During permanent object creation, incremental garbage collector ran for 0.6529463 seconds at Tue May 15 16:48:46 PDT 2001
[GC 142626K->142626K(152640K), 0.5126402 secs]
During permanent object creation, incremental garbage collector ran for 0.5126402 seconds at Tue May 15 16:48:47 PDT 2001
[GC 143650K->143650K(153856K), 0.5099915 secs]
During permanent object creation, incremental garbage collector ran for 0.5099915 seconds at Tue May 15 16:48:48 PDT 2001
[GC 144674K->144674K(154880K), 0.9464722 secs]
During permanent object creation, incremental garbage collector ran for 0.9464722 seconds at Tue May 15 16:48:50 PDT 2001
[GC 145186K->145186K(155520K), 0.5382060 secs]
During permanent object creation, incremental garbage collector ran for 0.5382060 seconds at Tue May 15 16:48:50 PDT 2001
[GC 146722K->146722K(157184K), 0.6647143 secs]
During permanent object creation, incremental garbage collector ran for 0.6647143 seconds at Tue May 15 16:48:52 PDT 2001
[GC 153379K->153379K(164352K), 4.7150467 secs]
During permanent object creation, incremental garbage collector ran for 4.7150467 seconds at Tue May 15 16:48:59 PDT 2001
[GC 250669K->250669K(268224K), 6.7445342 secs]
During permanent object creation, incremental garbage collector ran for 6.7445342 seconds at Tue May 15 16:49:36 PDT 2001

The first line with the square brackets is coming directly from the JVM.
The second line is generated by the perl filter. The filter is looking
for GC times which are above a certain threshold ( 0.5 seconds ).
If the GC takes longer than this threshold, it prints the time of the offending
GC, and the phase in which the Java program is in (initial permanent object
creation, or "garbage mode")

The Java example also displays how much memory is in use, to show if/how
the garbage collector is keeping up with the garbage generated.
e.g.
Mon May 14 09:40:55 EST 2001 Total Mem: 410058752 Used: 398144792 Percent full: 97% Total Growth:
67952 Delta since last report: 67952
Mon May 14 09:41:56 EST 2001 Total Mem: 403898368 Used: 392132952 Percent full: 97% Total Growth:
-5761784 Delta since last report: -5829736

BTW, the example is configurable - just tell it how much garbage to generate per second on the command line to change the stress on the GC.
  
To elaborate, I meant that by looking at the program outputs you could see that
the GC was running for >=1 second, every 1 second or so. GC delays became
much more frequent