This discussion is archived
0 Replies Latest reply: Aug 8, 2012 1:11 AM by 954520 RSS

Java 7 update 5 GC

954520 Newbie
Currently Being Moderated
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 update 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?

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points