why this young gc is so slow?

[Igor Veresov]

Actually it's not only the amount of live data that matters (that's true, but only for the copying part) but also the number of edges in the object graph that have to be traversed. In your example it could be the case that the old gen contains a huge data structure (say an object array) that contains references to objects in the young gen. It could have references to the same object, doesn't matter, what would matter is their number. So, during a young GC we would have to scan all those references, which could take time.

You could run with -XX:+PrintGCTaskTimeStamps and it should basically show you where the time goes. 

igor

On Friday, August 19, 2011 at 1:57 AM, BlueDavy Lin wrote:

> hi!
> 
>  CPU: 16 core, Physical Memory: 24G JDK: 6u23 || 6u21
>  startup options: -Xmn1g -Xms4g -Xmx4g
> 
>  some gc log:
>  2011-08-19T16:55:27.759+0800: 92.888: [GC [PSYoungGen:
> 1022368K->22752K(1024320K)] 1073312K->79200K(4170048K), 0.2117400
> secs] [Times: user=2.80 sys=0.00, real=0.21 secs]
> 2011-08-19T16:55:29.377+0800: 94.507: [GC [PSYoungGen:
> 1022688K->22848K(1024192K)] 1079136K->82896K(4169920K), 0.1858340
> secs] [Times: user=2.37 sys=0.01, real=0.18 secs]
> 2011-08-19T16:55:30.999+0800: 96.128: [GC [PSYoungGen:
> 1022784K->22784K(1024448K)] 1082832K->84752K(4170176K), 0.1648320
> secs] [Times: user=1.98 sys=0.00, real=0.16 secs]
> 2011-08-19T16:55:32.576+0800: 97.706: [GC [PSYoungGen:
> 1023040K->22816K(1024384K)] 1085008K->89416K(4170112K), 0.1979820
> secs] [Times: user=2.56 sys=0.00, real=0.19 secs]
> 2011-08-19T16:55:34.194+0800: 99.323: [GC [PSYoungGen:
> 1023072K->22784K(1024640K)] 1089672K->92208K(4170368K), 0.1748660
> secs] [Times: user=2.18 sys=0.01, real=0.18 secs]
> 2011-08-19T16:55:35.779+0800: 100.909: [GC [PSYoungGen:
> 1023360K->22784K(1024512K)] 1092784K->97792K(4170240K), 0.2129800
> secs] [Times: user=2.81 sys=0.00, real=0.21 secs]
> 2011-08-19T16:55:37.437+0800: 102.567: [GC [PSYoungGen:
> 1023360K->22752K(1024768K)] 1098368K->101528K(4170496K), 0.1880140
> secs] [Times: user=2.40 sys=0.00, real=0.18 secs]
> 2011-08-19T16:55:39.040+0800: 104.169: [GC [PSYoungGen:
> 1023648K->22784K(1024704K)] 1102424K->103688K(4170432K), 0.1647610
> secs] [Times: user=2.01 sys=0.01, real=0.16 secs]
> 2011-08-19T16:55:40.605+0800: 105.735: [GC [PSYoungGen:
> 1023680K->22816K(1024896K)] 1104584K->108600K(4170624K), 0.2030000
> secs] [Times: user=2.65 sys=0.00, real=0.21 secs]
> 
>  I think for ps gc,the live objects is the key factor,but in
> this case,live objects are not so much,why gc time so slow? I think
> it should be below 20ms,can someone help me for this?
> 
> -- 
> =============================
> | BlueDavy |
> | http://www.bluedavy.com |
> =============================