0 Replies Latest reply: Aug 8, 2012 3:11 AM by 954520 RSS

    Java 7 update 5 GC

    954520
      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?