Developers take advantage of the JVM argument -XX:+UseGCLogFileRotation to rotate GC log files.
Example:
"-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/home/GCEASY/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=20M"
As per above example, JVM will rotate GC log file whenever its size reaches 20MB. It will generate files up to 5 files, with extensions gc.log.0, gc.log.1, gc.log.2, gc.log.3, gc.log.4.
But this approach has few challenges:
# a. Losing old GC Logs
Suppose if you had configured -XX:NumberOfGCLogFiles=5 then, over a period of time, 5 GC log files will be created:
gc.log.0 ← oldest GC Log content
gc.log.1
gc.log.2
gc.log.3
gc.log.4 ← latest GC Log content
Most recent GC log contents will be written to ‘gc.log.4’ and old GC log content will be present in ‘gc.log.0’.
When the application starts to generate more GC logs than the configured ‘-XX:NumberOfGCLogFiles’ in this case 5, then old GC log contents in gc.log.0 will be deleted. New GC events will be written to gc.log.0. It means you will end up not having all the generated GC logs. You will loose the visibility of all events.
# b. Mixed-up GC Logs
Suppose application has created 5 gc log files i.e.
gc.log.0
gc.log.1
gc.log.2
gc.log.3
gc.log.4
then, let’s say you are restarting the application. Now new GC logs will be written to gc.log.0 file and old GC log content will be present in gc.log.1, gc.log.2, gc.log.3, gc.log.4 i.e.
gc.log.0 ← GC log file content after restart
gc.log.1 ← GC log file content before restart
gc.log.2 ← GC log file content before restart
gc.log.3 ← GC log file content before restart
gc.log.4 ← GC log file content before restart
So your new GC log contents get mixed up with old GC logs. Thus, to mitigate this problem you might have to move all the old GC logs to a different folder before you restart the application.
# c. Forwarding GC logs to central location
In this approach, current active file to which GC logs are written is marked with extension “.current”. Example, if GC events are currently written to file ‘gc.log.3’ it would be named as: ‘gc.log.3.current’.
If you want to forward GC logs from each server to a central location, then most DevOps engineers uses ‘rsyslog’. However this file naming convention poses a significant challenge to use ‘rsyslog’, as described in this blog.
# d. Tooling
Now to analyze the GC log file using the GC tools such as (gceasy.io, GCViewer….), you will have to upload multiple GC log files instead of just one single GC Log file.
Recommended Solution
We can suffix the GC log file with the time stamp at which the JVM was restarted then, GC Log file locations will become unique. Then new GC logs will not over-ride the old GC logs. It can be achieved by suffixing ‘%t’ to GC log file name as shown below:
"-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/home/GCEASY/gc-%t.log"
‘%t’ suffixes timestamp to the gc log file in the format: ‘YYYY-MM-DD_HH-MM-SS’. So generated GC log file name will start to look like: ‘gc-2019-01-29_20-41-47.log’
This simple solution addresses all the shortcomings of ‘-XX:+UseGCLogFileRotation’
February 28, 2019 at 1:30 am
Thanks !
So could you stop displaying the warning message “-XX:+UseGCLogFileRotation argument is not recommended to be passed. ….” if the setting “-XX:+UseGCLogFileRotation -Xloggc:/path/to/file-%t.log” is detected ?
March 4, 2019 at 6:59 pm
Excellent suggestion Tao. We will implement it.
February 13, 2019 at 12:54 pm
I didn’t understand the problem at first, but then I re-read and now it looks like log rotation is not working as it’s supposed to be. people working with Log4J’s model of rolling files would find this shocking as the files with suffix 0 (or no suffix) is the one with latest content
https://logging.apache.org/log4j/2.x/manual/appenders.html#DefaultRolloverStrategy
February 6, 2019 at 3:33 pm
for long-running JVMs this will create insanely huge gc-logs since the new log is only created on JVM-start. we combine both log-rotation and the %t macro to have a unique set of rotated logs per JVM restart, thus no logs lost except when a JVM has been running long enough to overwrite it’s .0 log (at which point that data is typically not useful anyway).
February 13, 2019 at 2:32 pm
I agree, -UseGCLogFileRotation , did not work as intented. Adding the %t along with the log-rotation will solve the issue