YGC time increasing suddenly

[Wolfgang Pedot]

Hi,

this is the first time I write an answer on this mailing-list so this 
could be totally useless but here goes:

Your survivor-space seems to be quite empty, is the usage that low on 
all collects during your test? If so you could increase your 
survivor-ratio to gain more eden-space and if not many objects die in 
survivor you could also reduce the tenuring threshold. Total survivor 
usage has grown 6-fold from first to last GC and survivor space needs to 
be copied on each young gc. I admit it should probably not take that 
long to copy 60MB though...

Here is a young-gc from one of my logs for comparison:

30230.123: [ParNew
Desired survivor size 524261784 bytes, new threshold 12 (max 15)
- age   1:  113917760 bytes,  113917760 total
- age   2:   86192768 bytes,  200110528 total
- age   3:   59060992 bytes,  259171520 total
- age   4:   59319272 bytes,  318490792 total
- age   5:   45307432 bytes,  363798224 total
- age   6:   29478464 bytes,  393276688 total
- age   7:   27440744 bytes,  420717432 total
- age   8:   27947680 bytes,  448665112 total
- age   9:   27294496 bytes,  475959608 total
- age  10:   32830144 bytes,  508789752 total
- age  11:    7490968 bytes,  516280720 total
- age  12:   10723104 bytes,  527003824 total
- age  13:    4549808 bytes,  531553632 total
: 4306611K->731392K(4388608K), 0.1433810 secs] 
10422356K->6878961K(14116608K)

This is with MaxNewSize 5500m and a Survivor-Ratio of 8. You can see 
that GC-time is higher than yours (6core 3.33GHz Xeon), survivor-usage 
is way higher though.

Hope I could help
Wolfgang


Am 18.12.2013 19:58, schrieb Luciano Molinari:
> Hi everybody,
>
> We have a standalone Java app that receives requests through RMI and
> almost all the objects created by it are short (< ~100ms) lived objects.
> This app is running on a 24 cores server with 16 GB RAM (Red Hat Linux).
> During our performance tests (10k requests/second) we started to face a
> problem where the throughput decreases suddenly just a few minutes
> after the app was started.
> So, I started to investigate GC behaviour and to make some adjustments
> (increase memory, use CMS...) and now we are able to run our app
> properly for about 35 minutes. At this point the time spent during young
> collections grows sharply although no Full GC is executed (old gen is
> only ~4% full).
>
> I've done tests with many different parameters, but currently I'm using
> the following ones:
> java -server -verbose:gc -XX:+PrintGCDetails
> -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps
> -XX:PrintFLSStatistics=1 -XX:SurvivorRatio=4
> -XX:ParallelGCThreads=8 -XX:PermSize=256m -XX:+UseParNewGC
> -XX:MaxPermSize=256m -Xms7g -Xmx7g -XX:NewSize=4608m -XX:MaxNewSize=4608m
> -XX:MaxTenuringThreshold=15 -Dsun.rmi.dgc.client.gcInterval=3600000
> -Dsun.rmi.dgc.server.gcInterval=3600000
>   -Djava.rmi.server.hostname=IP_ADDRESS
>
> If I use this same configuration (without CMS) the same problem occurs
> after 20minutes, so it doesn't seem to be related to CMS. Actually, as I
> mentioned above, CMS (Full GC) isn't executed during the tests.
>
> Some logs I've collected:
>
> 1992.748: [ParNew
> Desired survivor size 402653184 bytes, new threshold 15 (max 15)
> - age   1:    9308728 bytes,    9308728 total
> - age   2:       3448 bytes,    9312176 total
> - age   3:       1080 bytes,    9313256 total
> - age   4:         32 bytes,    9313288 total
> - age   5:      34768 bytes,    9348056 total
> - age   6:         32 bytes,    9348088 total
> - age  15:       2712 bytes,    9350800 total
> : 3154710K->10313K(3932160K), 0.0273150 secs] 3215786K->71392K(6553600K)
>
> //14 YGC happened during this window
>
> 2021.165: [ParNew
> Desired survivor size 402653184 bytes, new threshold 15 (max 15)
> - age   1:    9459544 bytes,    9459544 total
> - age   2:    3648200 bytes,   13107744 total
> - age   3:    3837976 bytes,   16945720 total
> - age   4:    3472448 bytes,   20418168 total
> - age   5:    3586896 bytes,   24005064 total
> - age   6:    3475560 bytes,   27480624 total
> - age   7:    3520952 bytes,   31001576 total
> - age   8:    3612088 bytes,   34613664 total
> - age   9:    3355160 bytes,   37968824 total
> - age  10:    3823032 bytes,   41791856 total
> - age  11:    3304576 bytes,   45096432 total
> - age  12:    3671288 bytes,   48767720 total
> - age  13:    3558696 bytes,   52326416 total
> - age  14:    3805744 bytes,   56132160 total
> - age  15:    3429672 bytes,   59561832 total
> : 3230658K->77508K(3932160K), 0.1143860 secs] 3291757K->142447K(6553600K)
>
> Besides the longer time to perform collection, I also realized that all
> 15 ages started to have larger values.
>
> I must say I'm a little confused about this scenario. Does anyone have
> some tip?
>
> Thanks in advance,
> --
> Luciano
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>