Tenured messgaes in GC logs after upgrading to jdk1.4.2_13
our application is BEA weblogic 8.1 sp4 on solaris box,initially we were getting OOM errors but after upgrading our JVM and resizing Heap settings we are done away with OOM errors.
But in GC logs we are getting Tenured messages.
My Heap settings :
="-XX:NewSize=512m -XX:MaxNewSize=512m -XX:SurvivorRatio=4 -XX:TargetSurvivorRatio=80 -XX:PermSize=256m -XX:MaxPermSize=256m -Xms1536m -Xmx1536m
excerpts from GC logs :
261498.953: [GC 261498.954: [DefNew: 374585K->25176K(436928K), 0.2820820 secs] 1038388K->689202K(1485504K), 0.2822686 secs]
261534.897: [GC 261534.897: [DefNew: 374744K->33018K(436928K), 0.3950738 secs] 1038770K->701819K(1485504K), 0.3952532 secs]
261555.189: [GC 261555.189: [DefNew: 382586K->382586K(436928K), 0.0000436 secs]261555.189: [Tenured: 668801K->538076K(1048576K), 11.3593778 secs] 1051387K->538076K(1485504K), 11.3597008 secs]
398866.226: [GC 398866.226: [DefNew: 349568K->349568K(436928K), 0.0000439 secs]398866.227: [Tenured: 703838K->707334K(1048576K), 11.8975502 secs] 1053406K->707334K(1485504K), 11.8978785 secs]
398981.491: [GC 398981.491: [DefNew: 349568K->349568K(436928K), 0.0000434 secs]398981.491: [Tenured: 707334K->710596K(1048576K), 11.8955832 secs] 1056902K->710596K(1485504K), 11.8959308 secs]
399039.192: [GC 399039.192: [DefNew: 349568K->349568K(436928K), 0.0000456 secs]399039.192: [Tenured: 710596K->712593K(1048576K), 11.9330747 secs] 1060164K->712593K(1485504K), 11.9335147 secs]
Is there anything that we can be used to tweak our heap settings ?
[1624 byte] By [
Sawan_ATMa] at [2007-10-3 11:57:30]
What do you want to accomplish by tweaking your heap settings?
just want to check that will it affect our server performance?
n can we done away with it..or any optimum settings for this...
If you check the log extract the young generation is not getting collected .. and the pauses are long ~11secs the collection.
can we reduce tht time ?
Can we have to change any size or ratio for this
Message was edited by:
Sawan_ATM
Well, you told the JVM to use
256m permspace: -XX:PermSize=256m -XX:MaxPermSize=256m
1536m total heap: -Xms1536m -Xmx1536m
(although the GC log says 1485504K)
of which
512m new space: -XX:NewSize=512m -XX:MaxNewSize=512m
the rest is tenured space: 1024m
(here the GC log agrees saying 1048576K).
Of the 512m new space, the two survivor spaces each take 1/6 of new space giving
85m: -XX:SurvivorRatio=4
the rest of new space is eden: 340m
However the GC log says
eden: 436928K
which leaves 88m to be split between the two survivor spaces
matching -XX:SurvivorRatio=10
It looks like the GC logs totals do not include the survivor spaces as part of the heap
(not a problem as long as you know this)
and new space occupancy after GC is being mis-reported.261555.189: [GC 261555.189: [DefNew: 382586K->382586K(436928K), 0.0000436 secs]261555.189: [Tenured: 668801K->538076K(1048576K), 11.3593778 secs] 1051387K->538076K(1485504K), 11.3597008 secs]
398866.226: [GC 398866.226: [DefNew: 349568K->349568K(436928K), 0.0000439 secs]398866.227: [Tenured: 703838K->707334K(1048576K), 11.8975502 secs] 1053406K->707334K(1485504K), 11.8978785 secs]
398981.491: [GC 398981.491: [DefNew: 349568K->349568K(436928K), 0.0000434 secs]398981.491: [Tenured: 707334K->710596K(1048576K), 11.8955832 secs] 1056902K->710596K(1485504K), 11.8959308 secs]
399039.192: [GC 399039.192: [DefNew: 349568K->349568K(436928K), 0.0000456 secs]399039.192: [Tenured: 710596K->712593K(1048576K), 11.9330747 secs] 1060164K->712593K(1485504K), 11.9335147 secs]
I can make sense of these numbers only if everything in new space gets promoted to tenured space on these GC runs.
Maybe you want to try running with -XX:SurvivorRatio=2
You could also try running with a smaller young generation. Try -XX:MaxNewSize=128m or
256m. You might be running into the "young generation guarantee" that is described in
http://java.sun.com/docs/hotspot/gc1.4.2/#3.2.1.%20Young%20Generation%20Guarantee|outline
If you have 4 or more cpus you could also try the parallel collector with
-XX:+UseParallelGC.
thanks tschodt with your explanation in reading the GC logs.
one of our designer suggested to change the survivor ratio value to 20 which i couldnt understand.
Even the change carried out didnt resulted in the performance getting any better it still looks the same.
After 2 days frm a restart the applications start throwing tenured messages in the GC logs and young generation starts to stay at a particular same size.
like it gets stuck on 476672K for the new generation
new logs:
527100.231: [GC 527100.231: [DefNew: 476672K->476672K(500480K), 0.0001068 secs]527100.231: [Tenured: 740936K->742630K(1048576K), 12.1883470 secs] 1217608K->742630K(1549056K), 12.1887250 secs]
527366.736: [GC 527366.736: [DefNew: 476672K->476672K(500480K), 0.0001033 secs]527366.736: [Tenured: 742630K->735986K(1048576K), 14.9098709 secs] 1219302K->735986K(1549056K), 14.9102569 secs]
527730.279: [GC 527730.279: [DefNew: 476672K->476672K(500480K), 0.0001002 secs]527730.279: [Tenured: 735986K->744200K(1048576K), 11.9031163 secs] 1212658K->744200K(1549056K), 11.9034866 secs]
527878.436: [GC 527878.436: [DefNew: 476672K->476672K(500480K), 0.0001018 secs]527878.436: [Tenured: 744200K->746309K(1048576K), 11.9978099 secs] 1220872K->746309K(1549056K), 11.9981936 secs]
And tenured size after collection is increasing.
can something be concluded from the above log snippets as to where are we going wrong.
You have 726MB of live data in your 1024MB old generation. You have 465MB of data (we don't know yet if it's all live or not) in the young generation. Since we can't guarantee that all that stuff from the young generation will fit in the old generation, the young generation collection ("DefNew" in your logs) bails out (in 0.0001068 secs) to a full collection. The full collection deals with a lot of the garbage, reducing the heap to 726MB of live data, all in the old generation ("Tenured" in your logs) if you follow the "after" size of the entire heap of one collection the "before" size of the old generation in the next collection. That leaves the young generation empty. Some time later (a couple of minutes) the young generation fills up again, again we can't meet the "full promotion guarantee" that Jon pointed at in a previous reply, and we run a full collection again.
You could probably run this way forever. But you'd be much happier if you shrink the size of your young generation so there's room for us to guarantee that it could all fit in the old generation (1024MB of old generation - 726MB of live data implies your young generation should be more like 256MB, or maybe even less), at which point we will be running young generation collections. A smaller young generation will need to be collected more frequently, but that might not be a issue (once a minute instead of once every couple of minutes?) and young generation collections will almost certainly be faster than the full collections you are doing now. (As an aside, since you are only doing full collections that empty the young generation, you aren't using the "survivor spaces" at all: that's just unused space (only about 23MB, but I hate wasted space.)
Try using a smaller young generation (e.g., -XX:MaxNewSize=256m) and report back what happens!
Would not the frequent collections lead to high CPU usage? and how does shrinking help [if you can explain a bit more]
With more frequent young generation collections you might have like 261498.953: [GC 261498.954: [DefNew: 374585K->25176K(436928K), 0.2820820 secs] 1038388K->689202K(1485504K), 0.2822686 secs]
261534.897: [GC 261534.897: [DefNew: 374744K->33018K(436928K), 0.3950738 secs] 1038770K->701819K(1485504K), 0.3952532 secs]
with collections <0.5 seconds, but at more frequent intervals. Even twice as often (and likely slightly shorter) would be better than 398981.491: [GC 398981.491: [DefNew: 349568K->349568K(436928K), 0.0000434 secs]398981.491: [Tenured: 707334K->710596K(1048576K), 11.8955832 secs] 1056902K->710596K(1485504K), 11.8959308 secs]
399039.192: [GC 399039.192: [DefNew: 349568K->349568K(436928K), 0.0000456 secs]399039.192: [Tenured: 710596K->712593K(1048576K), 11.9330747 secs] 1060164K->712593K(1485504K), 11.9335147 secs]
where at about the same frequency you have 12 second full collections. That's a good trade. And probably will result in lower CPU usage.
Shrinking the young generation helps because your live data will fit in the old generation while also leaving room for a young generation to complete normally without bailing out. Does that make sense?
On the other hand, it looks like your live data size is going up (707334K, 710596K, 712593K) over the course of 3 minutes, so it's also possible your application holding on to increasing amounts of data, and you just need a larger heap.
