Question on IBM verbose GC output

[peter.doyle]

all,

i recently spotted a line in my verbose gc output for which i can find
no information - the output for the entire AF looks like this ...

1.<AF[421]: Allocation Failure. need 164872 bytes, 462 ms since last
AF>
2.<AF[421]: managing allocation failure, action=2
(243805808/536869376)>
3. <GC(421): mark stack overflow[118]>
4. <GC(421): GC cycle started Mon Jan 24 11:52:59 2005
5. <GC(421): freed 22188976 bytes, 49% free (265994784/536869376), in
544 ms>
6. <GC(421): mark: 480 ms, sweep: 64 ms, compact: 0 ms>
7. <GC(421): refs: soft 11 (age >= 32), weak 31, final 9, phantom 0>
8. <GC(421): stop threads time: 2, start threads time: 1183>
9.<AF[421]: completed in 1730 ms>

.... and the line i'm interested in is line number 8.

i understand what the line is telling me, but what i don't understand
is why only a handful of AF's report this line - my calculated guess
would be somthing like ... if the start/stop of threads takes only a
short amount of time there's no need to report it explicitly, but if
the time exceeds some threshold then report it

in the absence of any useful pointers, and if my theory is correct, can
anybody suggest why starting threads should take a second in some
cases, but milliseconds in others ?

thanks,

peter.

 

[Ann]

all,

i recently spotted a line in my verbose gc output for which i can find
no information - the output for the entire AF looks like this ...

1.<AF[421]: Allocation Failure. need 164872 bytes, 462 ms since last
AF>
2.<AF[421]: managing allocation failure, action=2
(243805808/536869376)>
3. <GC(421): mark stack overflow[118]>
4. <GC(421): GC cycle started Mon Jan 24 11:52:59 2005
5. <GC(421): freed 22188976 bytes, 49% free (265994784/536869376), in
544 ms>
6. <GC(421): mark: 480 ms, sweep: 64 ms, compact: 0 ms>
7. <GC(421): refs: soft 11 (age >= 32), weak 31, final 9, phantom 0>
8. <GC(421): stop threads time: 2, start threads time: 1183>
9.<AF[421]: completed in 1730 ms>

... and the line i'm interested in is line number 8.

i understand what the line is telling me, but what i don't understand
is why only a handful of AF's report this line - my calculated guess
would be somthing like ... if the start/stop of threads takes only a
short amount of time there's no need to report it explicitly, but if
the time exceeds some threshold then report it

in the absence of any useful pointers, and if my theory is correct, can
anybody suggest why starting threads should take a second in some
cases, but milliseconds in others ?

thanks,

peter.

google says it might not be AF:
http://www-106.ibm.com/developerworks/eserver/library/es-Javaperf4.html

 

[peter.doyle]

thanks ann,

but in my output you'll see that the GC lines are part of an AF, and
not therefore connected to periodic RMI collections - also they're not
at regular intervals

peter.

 

[Plinio F Mendes]

Hi All,

I has a similar problem.

Environment:
- x86
- Red Hat Linux ES release 4 / kernel 2.6.9-5
- J2RE 1.4.2 IBM
- IBM Websphere Appserver V. 6.0.2

The application runs normally during 1, 2 weeks. The log of GC is like this:

<AF[1203]: Allocation Failure. need 3072808 bytes, 736 ms since last AF>
<AF[1203]: managing allocation failure, action=2 (388570792/805304832)>
<GC(1203): GC cycle started Mon Mar 17 10:22:33 2008
<GC(1203): freed 326024200 bytes, 88% free (714594992/805304832), in 176 ms>
<GC(1203): mark: 158 ms, sweep: 18 ms, compact: 0 ms>
<GC(1203): refs: soft 5 (age >= 32), weak 0, final 46, phantom 0>
<AF[1203]: completed in 177 ms>


Although I have a frequency GC (low time since last AF), the user feels the application is working normally.

After almost 2 weeks, I have the following behavior:

<AF[16728]: Allocation Failure. need 2091608 bytes, 2959 ms since last AF>
<AF[16728]: managing allocation failure, action=2 (300793824/1015806464)>
<GC(16728): GC cycle started Fri Mar 28 08:11:38 2008
<GC(16728): freed 633485024 bytes, 91% free (934278848/1015806464), in 171 ms>
<GC(16728): mark: 154 ms, sweep: 17 ms, compact: 0 ms>
<GC(16728): refs: soft 0 (age >= 32), weak 0, final 107, phantom 0>
<AF[16728]: completed in 188 ms>


<AF[16729]: Allocation Failure. need 2166432 bytes, 3600 ms since last AF>
<AF[16729]: managing allocation failure, action=2 (304946280/1015806464)>
<GC(16729): GC cycle started Fri Mar 28 08:11:44 2008
<GC(16729): freed 629023576 bytes, 91% free (933969856/1015806464), in 172 ms>
<GC(16729): mark: 155 ms, sweep: 17 ms, compact: 0 ms>
<GC(16729): refs: soft 0 (age >= 32), weak 0, final 268, phantom 0>
<GC(16729): stop threads time: 0, start threads time: 2482>
<AF[16729]: completed in 2654 ms>


The frequency between GCs are the same, but now there are a time to start and stop threads and theses times is high. Now the user feels the application so slowly.

The only difference is this new information "stop threads time" and "start threads time". There are some occurrence in the past but not so frequently and take a short time.

What is the means of theses informations?

IBM Garbage Collection and Storage Allocation Techniques
http://download.boulder.ibm.com/ibmdl/pub/software/dw/jdk/diagnosis/GCandMemory-042005.pdf

Very good document but I didn't arrive the information that I need.

Plinio