YGC time increasing suddenly

[Bernd Eckenfels]

Hello,

I would look at the finalizer queue first. And if that does not cut it,  
take a heapdump and inspect it for unexpected large dominators (maybe  
cached softreferences - not sure about RMI DGC havent seen problems with  
it, but it sure can be a problem if it only cleans up once an hour.).

How often do you see YGC at the beginning and then over time? It looks  
like every 2s? You might want to resize YGC by larger factors (but with  
the yg already at 4g I guess something else is a problem here).

You claim that most of the data only lives for 100ms, that does not match  
with the age-size distribution (not at the beginning not at the end).


Gruss
Bernd


Am 18.12.2013, 19:58 Uhr, schrieb Luciano Molinari <lucmolinari at gmail.com>:

> 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,


-- 
http://bernd.eckenfels.net