Java 7 update 5 GC

Wed Aug 8 11:18:20 PDT 2012

Hi Ching,

I'm not sure what's going on here. Do you have the complete GC logs 
available? What was the behavior with jdk7u4? I wonder if you are 
running into some expensive mixed GCs (perhaps as a result of a marking 
cycle being initiated by a humongous object allocation).

Thanks,

JohnC

On 08/08/12 00:50, Ching Chen wrote:
> Dear Sirs/Madams who may concern:
>  
> My java application (high-volume, low-latency on-line transaction 
> betting system) needs to accomplish the least GC pause while to keep 
> acceptable throughput.  When I read java 7 G1GC and thought this is 
> what I really want (I also investigated Azul Zing but stop somewhere 
> in the middle of my study).
>  
> I got a strange result when I ran a test with java 7 update 5 and 
> compared it with java 7.0 of same test though.
>  
> The java commands associating to GC in my test is not complicate.  I 
> only specified several of them and let GC to determine the rest for 
> best performance. The GC options are:
> java -Xms12288m -Xmx12288m -verbose:gc -XX:+PrintGCDetails 
> -XX:+PrintGCApplicationStoppedTime -XX:+PrintCommandLineFlags 
> -XX:+UseG1GC -XX:MaxGCPauseMillis=100 \
>  
> The java 7.0 result as following:
>  
> /java version "1.7.0"
> Java(TM) SE Runtime Environment (build 1.7.0-b147)
> Java HotSpot(TM) 64-Bit Server VM (build 21.0-b17, mixed mode)
> [INFO] total GC times:199
> [INFO] C:/Users/Chris/Documents/My 
> Projects/citibet-2nd/support/matchspace/GC 
> performance/XX_UseG1GC_MaxGCPauseMillis100.txt average GC:0.067739 second
> [INFO] app stops:206, average seconds:0.065926
> [DEBUG] [0.006688, 0.007678, 0.008537, 0.014192, 0.021206, 0.023098, 
> 0.023628, 0.026924, 0.028749, 0.029012, 0.030648, 0.031663, 0.031704, 
> 0.031743, 0.033121,
> 0.035534, 0.036437, 0.037418, 0.038571, 0.039253, 0.040569, 0.041807, 
> 0.042169, 0.042459, 0.043335, 0.043797, 0.045504, 0.046178, 0.046337, 
> 0.050747, 0.051332,
> 0.052527, 0.052614, 0.052623, 0.054945, 0.055021, 0.05538, 0.055595, 
> 0.055836, 0.05586, 0.056101, 0.056134, 0.056167, 0.056181, 0.056243, 
> 0.056648, 0.056803,
> 0.057133, 0.057656, 0.057689, 0.058021, 0.058613, 0.058964, 0.059164, 
> 0.059424, 0.059438, 0.059456, 0.059853, 0.060354, 0.06064, 0.060972, 
> 0.060999, 0.061141,
> 0.061157, 0.061163, 0.061305, 0.061444, 0.061567, 0.061594, 0.061923, 
> 0.06215, 0.062252, 0.063147, 0.063149, 0.063159, 0.063563, 0.063885, 
> 0.064047, 0.064882,
> 0.064975, 0.065076, 0.065228, 0.065311, 0.066254, 0.066435, 0.066572, 
> 0.067084, 0.067206, 0.067543, 0.067919, 0.067973, 0.068015, 0.068042, 
> 0.068397, 0.068797,
> 0.0691, 0.069626, 0.069885, 0.070051, 0.070063, 0.070077, 0.070625, 
> 0.071117, 0.071127, 0.071257, 0.071372, 0.071453, 0.071647, 0.071703, 
> 0.072027, 0.072058,
> 0.072275, 0.072301, 0.07234, 0.072363, 0.072513, 0.072575, 0.072679, 
> 0.07305, 0.073061, 0.073326, 0.073482, 0.073607, 0.073888, 0.073949, 
> 0.074562, 0.074604,
> 0.074644, 0.075278, 0.075352, 0.07547, 0.075543, 0.075581, 0.076057, 
> 0.076445, 0.076514, 0.076599, 0.076967, 0.076991, 0.077079, 0.077112, 
> 0.077192, 0.077519,
> 0.077547, 0.077881, 0.078351, 0.078416, 0.078975, 0.079444, 0.079986, 
> 0.080327, 0.080342, 0.080568, 0.080884, 0.081912, 0.081916, 0.082134, 
> 0.082136, 0.082305,
> 0.082722, 0.082755, 0.082992, 0.083276, 0.083517, 0.083989, 0.084839, 
> 0.084884, 0.085197, 0.08552, 0.085662, 0.08599, 0.085999, 0.086837, 
> 0.087184, 0.087367,
> 0.08745, 0.087659, 0.087908, 0.088478, 0.089203, 0.089498, 0.090376, 
> 0.09044, 0.092862, 0.093084, 0.093279, 0.093361, 0.097381, 0.098379, 
> 0.100322, 0.100868,
> 0.10163, 0.103446, 0.104192, 0.105727, 0.108074, 0.108931, 0.113103, 
> 0.152951]
> [INFO] Minimum=11419, Maximum=121219, Total=5204830, Count=66, 
> Average=78861. (total elapsed nano:67824103252)/
> /[INFO] memory in usages after test 101 ends:4111938008, total 
> memory:12884901888, max memory:12884901888 with total 5280000 bets/
> // 
>  
> This test result meets G1GC specified (more GC times but smaller GC 
> pause).  While comparing to the test result of java 7 up/date 5/, the 
> result is quite surprised me/:/
> // 
> /java version "1.7.0_05"
> Java(TM) SE Runtime Environment (build 1.7.0_05-b06)
> Java HotSpot(TM) 64-Bit Server VM (build 23.1-b03, mixed mode)
> [INFO] total GC times:8
> [INFO] C:/Users/Chris/Documents/My 
> Projects/citibet-2nd/support/matchspace/GC 
> performance/XX_UseG1GC_MaxGCPauseMillis100_java7u5.txt average 
> GC:0.730325 second
> [INFO] app stops:18, average seconds:0.325045
> [DEBUG] [0.433048, 0.712155, 0.725535, 0.73903, 0.765341, 0.774686, 
> 0.833398, 0.859405]
> [INFO] Minimum=11504, Maximum=175425, Total=5220946, Count=40, 
> Average=130523. (total elapsed nano:43241336678)
> [INFO] memory in usages after test 101 ends:5626027848, total 
> memory:12884901888, max memory:12884901888 with total 5280000 bets
> /
>  
> The throughput does increase but the GC pause-time does not meet the 
> minimum requirement (< 100 millisecond) quite a big difference! 
>  
> Again, both runnings use same command GC options.  System shows to me 
> like:
> -XX:InitialHeapSize=12884901888 -XX:MaxGCPauseMillis=100 
> -XX:MaxHeapSize=12884901888 -XX:+PrintCommandLineFlags -XX:+PrintGC 
> -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDetails 
> -XX:+UseCompressedOops -XX:+UseG1GC
> Do I miss something secrets when using java 7 update 5 for GC specific 
> issues?
>  
>  
> Thanks,
> Ching Chen
> // 
>  
>
>
>  
> ------------------------------------------------------------------------
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>   

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120808/f206c333/attachment.html 