Enabling GC Logging

In How to conditionally enable/disable a Log4J2 appender we looked at some options for conditional activation of a given Log4J2 appender. Then in Spring Boot, Log4J2, and Tomcat logging we discussed how to enable access logging and verbose request logging in Tomcat.

It is also worthwhile to turn on GC logging, especially considering the fact that it has very low overhead.

Listing 1. Enabling GC logging using unified logging
-Xlog:gc:file=jvm.log::filecount=3,filesize=10M

For more details refer to [1].

If you run a logging agent such as Cloud Watch, Splunk, or Logstash a file count of 3 and file size of 10MB should leave plenty of time at the agent’s disposal to ingest all the logging records.

Always validate your assumptions!

This in particular is an invaluable tool for troubleshooting out of memory errors as well as responsiveness issues.

Listing 2. Sample GC logging output
[0.006s][info][gc] Using G1
[0.017s][info][gc] Periodic GC disabled
[0.307s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 24M->4M(64M) 8.345ms
[0.578s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 37M->8M(64M) 8.576ms
[0.799s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 40M->10M(64M) 4.528ms
[0.858s][info][gc] GC(3) Pause Young (Concurrent Start) (GCLocker Initiated GC) 25M->11M(64M) 2.759ms
[0.858s][info][gc] GC(4) Concurrent Cycle
[0.869s][info][gc] GC(4) Pause Remark 14M->14M(54M) 1.160ms
[0.873s][info][gc] GC(4) Pause Cleanup 15M->15M(54M) 0.131ms
[0.873s][info][gc] GC(4) Concurrent Cycle 15.456ms
[0.974s][info][gc] GC(5) Pause Young (Concurrent Start) (G1 Evacuation Pause) 40M->12M(54M) 5.634ms
[0.974s][info][gc] GC(6) Concurrent Cycle
[0.985s][info][gc] GC(6) Pause Remark 16M->16M(54M) 0.677ms
[0.989s][info][gc] GC(6) Pause Cleanup 17M->17M(54M) 0.020ms
[0.989s][info][gc] GC(6) Concurrent Cycle 14.552ms
[1.104s][info][gc] GC(7) Pause Young (Normal) (G1 Evacuation Pause) 37M->14M(54M) 3.798ms
[1.255s][info][gc] GC(8) Pause Young (Normal) (G1 Evacuation Pause) 38M->15M(54M) 4.229ms
[1.423s][info][gc] GC(9) Pause Young (Normal) (G1 Evacuation Pause) 38M->17M(54M) 6.107ms
[1.564s][info][gc] GC(10) Pause Young (Normal) (G1 Evacuation Pause) 40M->18M(54M) 6.257ms
[1.699s][info][gc] GC(11) Pause Young (Normal) (G1 Evacuation Pause) 40M->19M(54M) 6.015ms
[1.843s][info][gc] GC(12) Pause Young (Normal) (G1 Evacuation Pause) 40M->20M(54M) 3.459ms
[1.986s][info][gc] GC(13) Pause Young (Normal) (G1 Evacuation Pause) 40M->22M(54M) 2.437ms
[2.129s][info][gc] GC(14) Pause Young (Normal) (G1 Evacuation Pause) 41M->22M(54M) 4.812ms

In the next post, we setup a Cloud Watch agent on an AWS EC2 instance to publish our logs into Cloud Watch Log streams.