Performance Jumps Not Related to GC

Java GC Tutorials - Herong's Tutorial Examples

∟Garbage Collection Performance Test Program

∟Performance Jumps Not Related to GC

This section provides a tutorial showing that Performance jumps are not related garbage collections.

In the last tutorial, we learned that our test program GCPerformance.java has some strange performance jumps running on Windows systems. Those jumps reach as high as 2 times than normal performance with chunk size of 16 objects.

In this tutorial, let's run the test again with GC logging to see those jumps are resulted from garbage collections or not:

[0.029s][info][gc] Using G1
[0.046s][info][gc] Periodic GC disabled
[0.319s][info][gc] GC(0) Pause Young (Concurrent Start)
                        (G1 Humongous Allocation) 722M->80M(1600M) 5.998ms
[0.319s][info][gc] GC(1) Concurrent Cycle
[0.322s][info][gc] GC(1) Pause Remark 97M->97M(1600M) 1.007ms
[0.323s][info][gc] GC(1) Pause Cleanup 97M->97M(1600M) 0.141ms
[0.329s][info][gc] GC(1) Concurrent Cycle 10.294ms

Parameters: Size=1024KB, Base=32, Chunk=16, Wait=0ms, Warmup=32
Real:Exec  Lat.     Throughput      Total:Free  Proc.
Time:Time  ms/o  Ave:Min:Max:Chunk   Mem.:Mem.   Obj.
4:4  250  4000:4000:4000:4000  1638400:1145618  16
25:25  1314  1280:761:4000:761  1638400:1111824  32
30:30  1314  1600:761:4000:3200  1638400:1079056  48
35:35  1314  1828:761:4000:3200  1638400:1046288  64
40:40  1314  2000:761:4000:3200  1638400:1013520  80
44:44  1314  2181:761:4000:4000  1638400:980752  96
49:49  1314  2285:761:4000:3200  1638400:947984  112
54:54  1314  2370:761:4000:3200  1638400:915216  128

[0.425s][info][gc] GC(2) Pause Young (Concurrent Start)
                        (G1 Humongous Allocation) 722M->80M(1600M) 2.773ms
[0.425s][info][gc] GC(3) Concurrent Cycle
[0.428s][info][gc] GC(3) Pause Remark 91M->91M(1600M) 1.154ms
[0.429s][info][gc] GC(3) Pause Cleanup 93M->93M(1600M) 0.125ms
64:64  1314  2250:761:4000:1600  1638400:1538731  144
68:68  1314  2352:761:4000:4000  1638400:1505963  160
[0.435s][info][gc] GC(3) Concurrent Cycle 9.975ms

72:72  1314  2444:761:4000:4000  1638400:1473195  176
77:77  1314  2493:761:4000:3200  1638400:1440427  192
81:81  1314  2567:761:4000:4000  1638400:1407659  208
85:85  1314  2635:761:4000:4000  1638400:1374891  224
88:88  1314  2727:761:5333:5333  1638400:1342123  240
92:92  1314  2782:761:5333:4000  1638400:1309355  256
96:96  1314  2833:761:5333:4000  1638400:1276587  272
100:100  1314  2880:761:5333:4000  1638400:1243819  288
104:104  1314  2923:761:5333:4000  1638400:1211051  304
109:109  1314  2935:761:5333:3200  1638400:1178283  320
113:113  1314  2973:761:5333:4000  1638400:1145515  336
117:117  1314  3008:761:5333:4000  1638400:1112747  352
121:121  1314  3041:761:5333:4000  1638400:1079979  368
125:125  1314  3072:761:5333:4000  1638400:1047211  384
129:129  1314  3100:761:5333:4000  1638400:1013937  400
133:133  1314  3127:761:5333:4000  1638400:981169  416
137:137  1314  3153:761:5333:4000  1638400:948401  432
141:141  1314  3177:761:5333:4000  1638400:915633  448

[0.512s][info][gc] GC(4) Pause Young (Concurrent Start)
                        (G1 Humongous Allocation) 721M->80M(1600M) 2.590ms
[0.512s][info][gc] GC(5) Concurrent Cycle
[0.515s][info][gc] GC(5) Pause Remark 91M->91M(1600M) 1.072ms
[0.515s][info][gc] GC(5) Pause Cleanup 93M->93M(1600M) 0.137ms
150:150  1314  3093:761:5333:1777  1638400:1538714  464
[0.518s][info][gc] GC(5) Concurrent Cycle 5.758ms

155:155  1314  3096:761:5333:3200  1638400:1505946  480
159:159  1314  3119:761:5333:4000  1638400:1473178  496
163:163  1314  3141:761:5333:4000  1638400:1440410  512
167:167  1314  3161:761:5333:4000  1638400:1407642  528
171:171  1314  3181:761:5333:4000  1638400:1374874  544
175:175  1314  3200:761:5333:4000  1638400:1342106  560
178:178  1314  3235:761:5333:5333  1638400:1309338  576
182:182  1314  3252:761:5333:4000  1638400:1276570  592
186:186  1314  3268:761:5333:4000  1638400:1243802  608
189:189  1314  3301:761:5333:5333  1638400:1211034  624
                             ----
       Throughput jumped here - |
   And no GC process was running

194:194  1314  3298:761:5333:3200  1638400:1178266  640
198:198  1314  3313:761:5333:4000  1638400:1145498  656
203:203  1314  3310:761:5333:3200  1638400:1112730  672
208:208  1314  3307:761:5333:3200  1638400:1079962  688
211:211  1314  3336:761:5333:5333  1638400:1047194  704
216:216  1314  3333:761:5333:3200  1638400:1014426  720
219:219  1314  3360:761:5333:5333  1638400:981658  736
224:224  1314  3357:761:5333:3200  1638400:948890  752
228:228  1314  3368:761:5333:4000  1638400:916122  768
[0.599s][info][gc] GC(6) Pause Young (Concurrent Start)
                        (G1 Humongous Allocation) 721M->80M(1600M) 2.696ms
[0.599s][info][gc] GC(7) Concurrent Cycle
[0.601s][info][gc] GC(7) Pause Remark 91M->91M(1600M) 0.888ms
[0.602s][info][gc] GC(7) Pause Cleanup 93M->93M(1600M) 0.135ms
237:237  1314  3308:761:5333:1777  1638400:1538702  784
[0.605s][info][gc] GC(7) Concurrent Cycle 5.848ms

As you can see from the output, the performance jumps happened between two GC processes. There was no interference from the garbage collector. So those performance jumps are not related to garbage collections.

I saw the same behavior with JDK 8 on an older computer too:

herong> \Progra~1\java\jdk1.8.0\bin\java -Xms1600m -Xmx1600m
   -XX:+PrintGCDetails -XX:+PrintHeapAtGC
   -XX:+PrintTenuringDistribution -XX:+PrintReferenceGC
   -XX:+PrintGCApplicationStoppedTime
   -XX:+PrintGCApplicationConcurrentTime
   GCPerformance 1024 32 16 0 64

Parameters: Size=1024KB, Base=32, Chunk=16, Wait=0ms, Warmup=64
...
Real:Exec  Lat.     Throughput      Total:Free  Proc.
Time:Time  ms/o  Ave:Min:Max:Chunk   Mem.:Mem.   Obj.
31:31  1937  516:516:516:516  1126400:797556  16
62:62  1937  516:516:516:516  1126400:781171  32
93:93  1937  516:516:516:516  1126400:764787  48
124:124  1937  516:516:516:516  1126400:748403  64
156:156  2000  512:500:516:500  1126400:732019  80
187:187  2000  513:500:516:516  1126400:715634  96
218:218  2000  513:500:516:516  1126400:699250  112
249:249  2000  514:500:516:516  1126400:682866  128
Application time: 0.7555145 seconds
{Heap before GC invocations=2 (full 0):
 def new generation   total 819200K, used 447629K [...
  eden space 409600K,  99% used [...
  from space 409600K,   9% used [...
  to   space 409600K,   0% used [...
 tenured generation   total 307200K, used 0K [...
   the space 307200K,   0% used [...
 Metaspace used 1561K, capacity 2246K, committed 2368K, reserved 4480K
[GC (Allocation Failure) [DefNew
Desired survivor size 209715200 bytes, new threshold 15 (max 15)
- age   1:   37751136 bytes,   37751136 total
- age   3:     250144 bytes,   38001280 total
: 447629K->37110K(819200K), 0.0117398 secs]
   447629K->37110K(1126400K), 0.0117658 secs]
Heap after GC invocations=3 (full 0):
 def new generation   total 819200K, used 37110K [...
  eden space 409600K,   0% used [...
  from space 409600K,   9% used [...
  to   space 409600K,   0% used [...
 tenured generation   total 307200K, used 0K [...
   the space 307200K,   0% used [...
 Metaspace used 1561K, capacity 2246K, committed 2368K, reserved 4480K
}
Total time for which application threads were stopped: 0.0121600 seconds, ...
280:280  2000  514:500:516:516  1126400:1076055  144
312:312  2000  512:500:516:500  1126400:1059671  160
343:343  2000  513:500:516:516  1126400:1043286  176
374:374  2000  513:500:516:516  1126400:1026902  192
405:405  2000  513:500:516:516  1126400:1010518  208
436:436  2000  513:500:516:516  1126400:994134  224
468:468  2000  512:500:516:500  1126400:977749  240
499:499  2000  513:500:516:516  1126400:961365  256
530:530  2000  513:500:516:516  1126400:944981  272
561:561  2000  513:500:516:516  1126400:928597  288
592:592  2000  513:500:516:516  1126400:912212  304
624:624  2000  512:500:516:500  1126400:895828  320
655:655  2000  512:500:516:516  1126400:879444  336
686:686  2000  513:500:516:516  1126400:863060  352
717:717  2000  513:500:516:516  1126400:846675  368
748:748  2000  513:500:516:516  1126400:830291  384
780:780  2000  512:500:516:500  1126400:813907  400
811:811  2000  512:500:516:516  1126400:797523  416
826:826  2000  523:500:1066:1066  1126400:781138  432
                            ----
   Throughput jumped on here - |

858:858  2000  522:500:1066:500  1126400:764754  448
889:889  2000  521:500:1066:516  1126400:748370  464
920:920  2000  521:500:1066:516  1126400:731986  480
951:951  2000  521:500:1066:516  1126400:715601  496
982:982  2000  521:500:1066:516  1126400:699217  512
1014:1014  2000  520:500:1066:500  1126400:682833  528
Application time: 0.7576008 seconds
{Heap before GC invocations=3 (full 0):
 def new generation   total 819200K, used 446638K [...
  eden space 409600K,  99% used [...
  from space 409600K,   9% used [...
  to   space 409600K,   0% used [...
 tenured generation   total 307200K, used 0K [...
   the space 307200K,   0% used [...
 Metaspace used 1561K, capacity 2246K, committed 2368K, reserved 4480K
[GC (Allocation Failure) [DefNew
Desired survivor size 209715200 bytes, new threshold 15 (max 15)
- age   1:   36701584 bytes,   36701584 total
- age   2:        936 bytes,   36702520 total
- age   4:     250144 bytes,   36952664 total
: 446638K->36086K(819200K), 0.0101967 secs]
   446638K->36086K(1126400K), 0.0102218 secs]
Heap after GC invocations=4 (full 0):
 def new generation   total 819200K, used 36086K [...
  eden space 409600K,   0% used [...
  from space 409600K,   8% used [...
  to   space 409600K,   0% used [...
 tenured generation   total 307200K, used 0K [...
   the space 307200K,   0% used [...
 Metaspace used 1561K, capacity 2246K, committed 2368K, reserved 4480K
}
Total time for which application threads were stopped: 0.0106689 s
...

As you can see from the output, the first performance jump happened between two Minor GCs. During that period, the applications ran for 0.7576008 seconds, without any interference from the garbage collector.