Performance Test and System Interruptions

Java GC Tutorials - Herong's Tutorial Examples

∟Garbage Collection Performance Test Program

∟Performance Test and System Interruptions

This section provides a tutorial showing performance measurement impact of operating system interruptions on JVM.

After several runs of the GCPerformance.java program, I noticed that the throughput and latency measurements are not accurate because of system interruptions.

Since Windows is a multi-tasking system, it will interrupt the JVM to perform other tasks.

Those system interruptions will stop the JVM for some periods of time.

If system interruptions have very long durations, we can find it very easily by examining the output.

For example, if you start the JVM to run the application, wait for few seconds, then start Chrome on your computer while the JVM is running. You may get the following output running with JDK 8 on an older computer.

herong> \Progra~1\java\jdk1.8.0\bin\java GCPerformance 1024 32 32 0 0

Parameters: Size=1024KB, Base=32, Chunk=32, Wait=0ms, Warmup=0
Real:Exec  Lat.     Throughput      Total:Free  Proc.
Time:Time  ms/o  Ave:Min:Max:Chunk   Mem.:Mem.   Obj.
78:78  2439  410:410:410:410  136776:70251  32
172:172  2941  372:340:410:340  136776:37496  64
281:281  3412  341:293:410:293  156572:90789  96
344:344  3412  372:293:507:507  156572:57183  128
422:422  3412  379:293:507:410  156572:24409  160
...
4774:4774  3412  395:293:680:410  156572:24403  1888
4914:4914  4385  390:228:680:228  156572:89941  1920
5024:5024  4385  388:228:680:290  156572:57171  1952
5323:5323  9345  372:107:680:107  156572:89940  1984
                             ---
          System interruption -|
5464:5464  9345  368:107:680:226  156572:57172  2016
5586:5586  9345  366:107:680:262  156572:24403  2048
5756:5756  9345  361:107:680:188  156572:89941  2080
5878:5878  9345  359:107:680:262  156572:57171  2112
5990:5990  9345  357:107:680:285  156572:24403  2144
6147:6147  9345  353:107:680:203  156572:89941  2176
6231:6231  9345  354:107:680:380  156572:57172  2208
6357:6357  9345  352:107:680:253  156572:89941  2240
6440:6440  9345  352:107:680:385  156572:57171  2272
6510:6510  9345  353:107:680:457  156572:24403  2304
6617:6617  9345  353:107:680:299  156572:89941  2336
6702:6702  9345  353:107:680:376  156572:57172  2368
6813:6813  9345  352:107:680:288  156572:89941  2400
6879:6879  9345  353:107:680:484  156572:57172  2432
6944:6944  9345  354:107:680:492  156572:24403  2464
...

As you can see from the output, a long system interruption happened at 5323ms time. The reported throughput suddenly dropped from about 400 objects/second to about 100 objects/second.

Actually, starting Chrome while the JVM is running has interrupted the JVM multiple times from 4914ms to 6879ms.

Also note that the long system interruption has a huge impact on latency and a small impact on throughput. This is because latency is defined based on the worst execution, while throughput is defined based on the average execution time.

To minimize system interruption, you can:

Close all other running applications.
Stop background jobs and services as many as you can.
Do not touch your computer while you are running the JVM.
Run GCPerformance.java for a longer time. The throughput will be more accurate. But the latency will not change, since it is calculated as the worst case.