Java 7 update 5 GC

[Ching Chen]

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.730325second
[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
**
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120808/5d11a5a5/attachment.html