Performance Jumps Not Related to GC

Java 8 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:

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.