Java Runtime Performance Monitoring: GC and Safepoints

JVM internally takes care of many things for us, such as Garbage Collection and JIT Compilation. So JVM also needs its own time to sort out some stuff for itself, outside of the application. Some of the stuff that JVM can do might involve a safepoint (including GC). During a safepoint, all threads running Java code are suspended for JVM to do its work. The application goes to a halt for the time the JVM goes to a safepoint. 

There might be situations where the JVM could have been paused—not because of the GC but because of a safepoint. The -XX:+PrintGCApplicationStoppedTime option tells us the total time the application threads were paused by the JVM. It includes the pause time due to GC as well.

This article explains how to know whether GC was the cause of the pause or if the application was paused for some other reason as well. We will do this by combining the -XX:+PrintGCApplicationStoppedTime option with loggc option.

Consider a simple example. We will monitor Jenkins and see what we can infer. We can start Jenkins using the command below: 

java -XX:+PrintGCApplicationStoppedTime -Xloggc:testgc.log -jar jenkins.war

Now, we look at the testgc.log file and examine the contents: 

0.684: Total time for which application threads were stopped: 0.0303546 seconds
0.741: Total time for which application threads were stopped: 0.0001263 seconds
1.739: Total time for which application threads were stopped: 0.0001794 seconds
2.739: Total time for which application threads were stopped: 0.0001932 seconds
3.065: [GC 33280K->6009K(124928K), 0.0287263 secs]
3.094: Total time for which application threads were stopped: 0.0293479 seconds
3.471: [GC 39289K->4969K(124928K), 0.0157467 secs]
3.487: Total time for which application threads were stopped: 0.0161742 seconds
3.725: [GC 38249K->4417K(124928K), 0.0113980 secs]
3.737: Total time for which application threads were stopped: 0.0117724 seconds
3.944: [GC 37697K->4417K(158208K), 0.0118140 secs]
3.956: Total time for which application threads were stopped: 0.0121504 seconds
4.178: Total time for which application threads were stopped: 0.0004003 seconds
4.551: [GC 70977K->5083K(158208K), 0.0170096 secs]
4.569: Total time for which application threads were stopped: 0.0173157 seconds
4.569: Total time for which application threads were stopped: 0.0002169 seconds
4.569: Total time for which application threads were stopped: 0.0002606 seconds
4.570: Total time for which application threads were stopped: 0.0001754 seconds
4.570: Total time for which application threads were stopped: 0.0001602 seconds
4.570: Total time for which application threads were stopped: 0.0001691 seconds
4.570: Total time for which application threads were stopped: 0.0001383 seconds
4.571: Total time for which application threads were stopped: 0.0001098 seconds
4.571: Total time for which application threads were stopped: 0.0002347 seconds
4.571: Total time for which application threads were stopped: 0.0001441 seconds
4.571: Total time for which application threads were stopped: 0.0001598 seconds
4.572: Total time for which application threads were stopped: 0.0001209 seconds
4.572: Total time for which application threads were stopped: 0.0001218 seconds
4.572: Total time for which application threads were stopped: 0.0001531 seconds
4.572: Total time for which application threads were stopped: 0.0001410 seconds
4.573: Total time for which application threads were stopped: 0.0001531 seconds
4.573: Total time for which application threads were stopped: 0.0001441 seconds
4.573: Total time for which application threads were stopped: 0.0002240 seconds
4.574: Total time for which application threads were stopped: 0.0002022 seconds
4.574: Total time for which application threads were stopped: 0.0001490 seconds
4.574: Total time for which application threads were stopped: 0.0001473 seconds
4.574: Total time for which application threads were stopped: 0.0002129 seconds
4.575: Total time for which application threads were stopped: 0.0002312 seconds
4.575: Total time for which application threads were stopped: 0.0001937 seconds
4.575: Total time for which application threads were stopped: 0.0001705 seconds
4.576: Total time for which application threads were stopped: 0.0001513 seconds
4.576: Total time for which application threads were stopped: 0.0002463 seconds
4.576: Total time for which application threads were stopped: 0.0002093 seconds
4.577: Total time for which application threads were stopped: 0.0001883 seconds
4.577: Total time for which application threads were stopped: 0.0002084 seconds
4.577: Total time for which application threads were stopped: 0.0002320 seconds
4.577: Total time for which application threads were stopped: 0.0001999 seconds
4.578: Total time for which application threads were stopped: 0.0001397 seconds
4.578: Total time for which application threads were stopped: 0.0001040 seconds
4.578: Total time for which application threads were stopped: 0.0001098 seconds
4.578: Total time for which application threads were stopped: 0.0000754 seconds
4.578: Total time for which application threads were stopped: 0.0000692 seconds
4.578: Total time for which application threads were stopped: 0.0001044 seconds
4.579: Total time for which application threads were stopped: 0.0001258 seconds
4.579: Total time for which application threads were stopped: 0.0000768 seconds
4.579: Total time for which application threads were stopped: 0.0000763 seconds
5.407: Total time for which application threads were stopped: 0.0003485 seconds
5.409: Total time for which application threads were stopped: 0.0001977 seconds
5.436: Total time for which application threads were stopped: 0.0002080 seconds
5.717: Total time for which application threads were stopped: 0.0002472 seconds
5.759: Total time for which application threads were stopped: 0.0002267 seconds
6.238: Total time for which application threads were stopped: 0.0002499 seconds
6.492: Total time for which application threads were stopped: 0.0001794 seconds
6.492: Total time for which application threads were stopped: 0.0001910 seconds
6.493: Total time for which application threads were stopped: 0.0002878 seconds
6.493: Total time for which application threads were stopped: 0.0002834 seconds
6.493: Total time for which application threads were stopped: 0.0001847 seconds
6.494: Total time for which application threads were stopped: 0.0001490 seconds
6.494: Total time for which application threads were stopped: 0.0001669 seconds
6.494: Total time for which application threads were stopped: 0.0001602 seconds
6.495: Total time for which application threads were stopped: 0.0002030 seconds
6.495: Total time for which application threads were stopped: 0.0001888 seconds
6.495: Total time for which application threads were stopped: 0.0001923 seconds
6.496: Total time for which application threads were stopped: 0.0001794 seconds
6.496: Total time for which application threads were stopped: 0.0001870 seconds
6.496: Total time for which application threads were stopped: 0.0001830 seconds
6.496: Total time for which application threads were stopped: 0.0001812 seconds
6.497: Total time for which application threads were stopped: 0.0001740 seconds
6.497: Total time for which application threads were stopped: 0.0001669 seconds
6.497: Total time for which application threads were stopped: 0.0001807 seconds
6.497: Total time for which application threads were stopped: 0.0002062 seconds
6.498: Total time for which application threads were stopped: 0.0002405 seconds
6.498: Total time for which application threads were stopped: 0.0001843 seconds
6.499: Total time for which application threads were stopped: 0.0001629 seconds
6.499: Total time for which application threads were stopped: 0.0003396 seconds
6.499: Total time for which application threads were stopped: 0.0001522 seconds
6.501: Total time for which application threads were stopped: 0.0001004 seconds
6.501: Total time for which application threads were stopped: 0.0000705 seconds
6.501: Total time for which application threads were stopped: 0.0000678 seconds
6.501: Total time for which application threads were stopped: 0.0000629 seconds
6.501: Total time for which application threads were stopped: 0.0000968 seconds
6.502: Total time for which application threads were stopped: 0.0000884 seconds
6.502: Total time for which application threads were stopped: 0.0000968 seconds
6.502: Total time for which application threads were stopped: 0.0000678 seconds
6.502: Total time for which application threads were stopped: 0.0000638 seconds
6.502: Total time for which application threads were stopped: 0.0001348 seconds
6.502: Total time for which application threads were stopped: 0.0000647 seconds
6.502: Total time for which application threads were stopped: 0.0000491 seconds
6.503: Total time for which application threads were stopped: 0.0000473 seconds
6.503: Total time for which application threads were stopped: 0.0000477 seconds
6.503: Total time for which application threads were stopped: 0.0000464 seconds
6.503: Total time for which application threads were stopped: 0.0000460 seconds
6.503: Total time for which application threads were stopped: 0.0000455 seconds
6.503: Total time for which application threads were stopped: 0.0000469 seconds
6.503: Total time for which application threads were stopped: 0.0000464 seconds
6.503: Total time for which application threads were stopped: 0.0001272 seconds
6.527: Total time for which application threads were stopped: 0.0001303 seconds
6.527: Total time for which application threads were stopped: 0.0000714 seconds
6.527: Total time for which application threads were stopped: 0.0000732 seconds
6.527: Total time for which application threads were stopped: 0.0000785 seconds
6.550: Total time for which application threads were stopped: 0.0001218 seconds
6.550: Total time for which application threads were stopped: 0.0000683 seconds
6.550: Total time for which application threads were stopped: 0.0000705 seconds
6.550: Total time for which application threads were stopped: 0.0000754 seconds
6.559: Total time for which application threads were stopped: 0.0001821 seconds
6.559: Total time for which application threads were stopped: 0.0001316 seconds
6.559: Total time for which application threads were stopped: 0.0001598 seconds
6.560: Total time for which application threads were stopped: 0.0001464 seconds
6.584: Total time for which application threads were stopped: 0.0001263 seconds
6.584: Total time for which application threads were stopped: 0.0001254 seconds
6.584: Total time for which application threads were stopped: 0.0001080 seconds
6.585: Total time for which application threads were stopped: 0.0001044 seconds
6.623: Total time for which application threads were stopped: 0.0002544 seconds
6.632: Total time for which application threads were stopped: 0.0001254 seconds
6.633: Total time for which application threads were stopped: 0.0002240 seconds
6.633: Total time for which application threads were stopped: 0.0000951 seconds
6.635: Total time for which application threads were stopped: 0.0001419 seconds
6.657: Total time for which application threads were stopped: 0.0005721 seconds
6.657: Total time for which application threads were stopped: 0.0005154 seconds
6.672: Total time for which application threads were stopped: 0.0001232 seconds
6.677: Total time for which application threads were stopped: 0.0000768 seconds
6.677: Total time for which application threads were stopped: 0.0000571 seconds
6.715: Total time for which application threads were stopped: 0.0000736 seconds
6.716: Total time for which application threads were stopped: 0.0000567 seconds
6.716: Total time for which application threads were stopped: 0.0000594 seconds
6.716: Total time for which application threads were stopped: 0.0000397 seconds
6.717: Total time for which application threads were stopped: 0.0000366 seconds
6.720: Total time for which application threads were stopped: 0.0000585 seconds
6.720: Total time for which application threads were stopped: 0.0000527 seconds
6.721: Total time for which application threads were stopped: 0.0000571 seconds
6.721: Total time for which application threads were stopped: 0.0000567 seconds
6.722: Total time for which application threads were stopped: 0.0000567 seconds
6.722: Total time for which application threads were stopped: 0.0000571 seconds
6.730: Total time for which application threads were stopped: 0.0000607 seconds
6.730: Total time for which application threads were stopped: 0.0000531 seconds
6.730: Total time for which application threads were stopped: 0.0000567 seconds
6.731: Total time for which application threads were stopped: 0.0000732 seconds
6.767: Total time for which application threads were stopped: 0.0001589 seconds
6.771: Total time for which application threads were stopped: 0.0000718 seconds
6.771: Total time for which application threads were stopped: 0.0000379 seconds
6.771: Total time for which application threads were stopped: 0.0000437 seconds
6.771: Total time for which application threads were stopped: 0.0000513 seconds
6.786: Total time for which application threads were stopped: 0.0001129 seconds
6.804: Total time for which application threads were stopped: 0.0000759 seconds
6.834: Total time for which application threads were stopped: 0.0000772 seconds
6.844: Total time for which application threads were stopped: 0.0000705 seconds
6.845: Total time for which application threads were stopped: 0.0000567 seconds
6.845: Total time for which application threads were stopped: 0.0000602 seconds
6.845: Total time for which application threads were stopped: 0.0000589 seconds
6.884: Total time for which application threads were stopped: 0.0000768 seconds
6.923: Total time for which application threads were stopped: 0.0000790 seconds
6.932: Total time for which application threads were stopped: 0.0000701 seconds
6.946: Total time for which application threads were stopped: 0.0000754 seconds
6.947: Total time for which application threads were stopped: 0.0000589 seconds
6.947: Total time for which application threads were stopped: 0.0000594 seconds
6.948: Total time for which application threads were stopped: 0.0000683 seconds
6.976: Total time for which application threads were stopped: 0.0000754 seconds
6.976: Total time for which application threads were stopped: 0.0000576 seconds
6.976: Total time for which application threads were stopped: 0.0000598 seconds
6.977: Total time for which application threads were stopped: 0.0000594 seconds
6.982: Total time for which application threads were stopped: 0.0000665 seconds
6.984: Total time for which application threads were stopped: 0.0000585 seconds
6.984: Total time for which application threads were stopped: 0.0000540 seconds
6.984: Total time for which application threads were stopped: 0.0000580 seconds
6.985: Total time for which application threads were stopped: 0.0000580 seconds
6.987: Total time for which application threads were stopped: 0.0000580 seconds
6.987: Total time for which application threads were stopped: 0.0000535 seconds
6.987: Total time for which application threads were stopped: 0.0000580 seconds
6.988: Total time for which application threads were stopped: 0.0000585 seconds
6.995: Total time for which application threads were stopped: 0.0000594 seconds
6.995: Total time for which application threads were stopped: 0.0000531 seconds
6.995: Total time for which application threads were stopped: 0.0000571 seconds
6.996: Total time for which application threads were stopped: 0.0000585 seconds
7.009: Total time for which application threads were stopped: 0.0000620 seconds
7.009: Total time for which application threads were stopped: 0.0000540 seconds
7.009: Total time for which application threads were stopped: 0.0000580 seconds
7.010: Total time for which application threads were stopped: 0.0000576 seconds
7.028: [GC 71643K->11880K(222208K), 0.0437746 secs]
7.072: Total time for which application threads were stopped: 0.0441517 seconds
7.072: Total time for which application threads were stopped: 0.0001209 seconds
7.072: Total time for which application threads were stopped: 0.0001183 seconds
7.073: Total time for which application threads were stopped: 0.0001102 seconds
7.073: Total time for which application threads were stopped: 0.0001044 seconds
7.073: Total time for which application threads were stopped: 0.0000942 seconds

Take a look at the lines below from the log:

3.065: [GC 33280K->6009K(124928K), 0.0287263 secs]
3.094: Total time for which application threads were stopped: 0.0293479 seconds
3.471: [GC 39289K->4969K(124928K), 0.0157467 secs]
3.487: Total time for which application threads were stopped: 0.0161742 seconds
3.725: [GC 38249K->4417K(124928K), 0.0113980 secs]
3.737: Total time for which application threads were stopped: 0.0117724 seconds

All of the entries that say, “Total time for which application threads were stopped,” is caused by the -XX:+PrintGCApplicationStoppedTime option . The rest of the messages are due to the normal loggc option.

As you can see, the application was paused for 0.0293479 seconds. This matches almost with the GC time above. So it means that this application stopped due to the GC happening.

Now, take a look at what happens at approximately 4.5 seconds:

4.551: [GC 70977K->5083K(158208K), 0.0170096 secs]
4.569: Total time for which application threads were stopped: 0.0173157 seconds
4.569: Total time for which application threads were stopped: 0.0002169 seconds
4.569: Total time for which application threads were stopped: 0.0002606 seconds
4.570: Total time for which application threads were stopped: 0.0001754 seconds
4.570: Total time for which application threads were stopped: 0.0001602 seconds
4.570: Total time for which application threads were stopped: 0.0001691 seconds

You can see that there are lot of messages which say that threads were stopped. These are not attributed to the GC events. These are the events when a safepoint might have taken place and the JVM forces the threads to stop. We can see these messages go down till approx 7.010 seconds. Note that in this case, we’re seeing a lot of small pauses apart from GC because the application (in this case, Jenkins) was starting and JVM had to probably load the classes and compile them. So it is expected.

We can use the -XX:+PrintGCApplicationStoppedTime switch along with the GC options to correlate and understand how much time the JVM had stopped the application outside of the GC events.