44

Is it possible to do a rolling of garbage collector logs in Sun JVM?

Currently I generate logs using:

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -verbose:gc -Xloggc:gc.log

But I have to manually rotate them using fifo queues and rotatelogs to create a new log for each day. I hope that there is a better solution for this.

Maybe there is a way to access this log entries from inside java so I could redirect them to log4j?

Edit: the solution with fifo queue is not good enough because if the process that reads from this queue (e.g. rotatelogs) reads to slow it will slow down the entire jvm (apparently Sun/Oracle does gc logging synchronously)

Krzysztof Krasoń
  • 26,515
  • 16
  • 89
  • 115
  • Your solution sounds pretty good to me; what don't you like about it? You have colocation: the rotating happens near your Java invocation (which configures the logging) instead of in the application code (which should be oblivious to the logging). – Mark Peters Sep 29 '10 at 13:49
  • Also my gut would say no, it's not possible or if it is possible it'd be through a private, restricted API that you probably don't want to force into your application. – Mark Peters Sep 29 '10 at 13:52
  • -XX:+PrintGCDateStamps is not applied to java5? – rafa.ferreira Feb 23 '11 at 21:54

6 Answers6

89

Built-in support for GC log rotation has been added to the HotSpot JVM. It is described in the RFE 6941923 and is available in:

There are three new JVM flags that can be used to enable and configure it:

  • -XX:+UseGCLogFileRotation
    must be used with -Xloggc:<filename>;
  • -XX:NumberOfGCLogFiles=<number of files>
    must be >=1, default is one;
  • -XX:GCLogFileSize=<number>M (or K)
    default will be set to 512K.
Johan Kaving
  • 4,870
  • 1
  • 27
  • 21
  • 5
    -XX:NumberOfGClogFiles should have a capital L (-XX:NumberOfGCLogFiles) – Szymon Jednac Mar 22 '13 at 13:17
  • 2
    It's a pity that this is not per day, I don't see a point in size rolling, I usually wan to see logs from given day, not the 123MB :) – Krzysztof Krasoń Jul 04 '16 at 19:51
  • 4
    The point in size rolling is that the total size of log files is constrained (to NumberOfGCLogFiles * GCLogFileSize), which avoids no-space-left-on-device errors and outweighs the inconvenience of finding the logs of a given day. – vboerchers Aug 04 '16 at 13:04
  • @krzyk a workaround may be logging to a named file with the date stamp in it and restart the logging mechanism daily. – Thorbjørn Ravn Andersen Sep 01 '16 at 12:28
  • @ThorbjørnRavnAndersen how to "restart the logging mechanism daily" without restarting the JVM? – hidralisk Jul 06 '18 at 18:43
7

If you can't upgrade your java version to use the new flags for rotating the gc log then you could specify a different gc file each time the application starts:

JAVA_OPTS="-Xms1024m -Xmx1024m -XX:MaxPermSize=256m -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/path/to/log/dir/gc.log-"`date +%Y-%m-%d-%H-%M`

When the setenv is referenced, usually at startup or shutdown, it will reference a different log file. In unix this can be used as a method for 'rotating' the log.

Underverse
  • 1,271
  • 21
  • 32
  • A better method would be to append the verbose output to a file and rotate this file with logrotate or similar. You get longer logs and not broken up into a mess of different files. – Stian Lund Sep 27 '13 at 23:36
  • 2
    @Pathduck This answer is for older java versions. It means that you cannot append to Xlogcc. My experiments also show that you cannot cause the running java to close and reopen the log. You also cannot cause it to seek(EOF), java remembers the file position inside Xloggc. Major PITA. – kubanczyk Apr 01 '15 at 14:10
  • @Pathduck Not all systems have logrotate unfortunately. This solution posted for admins who have to do without. Appending date in this fashion is also useful for rotating catalina.out :-) – Underverse Apr 11 '15 at 09:16
  • The problem with appending date to the name is that after six months and a bunch of server restarts, you end up with a lot of messy logs, and unless you have logrotate set to clean these up, they will just stay there. Not a problem with one or two servers, but with hundreds this might be a problem, or not, depending on how OCD you are about messy log dirs :) Also see: http://stackoverflow.com/questions/8353401/garbage-collector-log-loggc-file-rotation-with-logrotate-does-not-work-properl/10499244#10499244 – Stian Lund Apr 12 '15 at 11:15
  • 1
    I concur. Hence: `find /opt/app/data/gc -type f -mtime +69 -exec rm -rf {} \;` – Underverse Apr 14 '15 at 05:18
  • @Underverse Thanks for the timestamp idea. I use already the new rolling GC log parameters, but my "problem" is another one: the rolling GC logs do not append, they overwrite the previous GC logs! So after a application/process/system restart, the "evidence" is gone... Timestamps do the magic. :-) – t0r0X Jan 25 '16 at 21:27
  • @t0r0X Even with the new options I found that the time stamped rolling logs to be more useful due to that the older logs can be moved or copied to another location for analysis. The only problem is that if the application runs for a few weeks the GC log file can get over 300mb. For viewing the log I added a tail and a bit of cleanup to more easily see recent FullGC events `cat \`ls -Et /data/gc/* | awk '$5 >800' | awk '{print $9}' | head -n 1\` | grep ": " | sed 's/./ /11' | sed 's/+1000: / /g' | sed 's/: / /g' | tail -200` – Underverse Jan 27 '16 at 02:07
4

Have you tried this new options?

I tried jdk7u7, jdk7u6 and jdk6u35 like this:

java -Xloggc:gc.log -XX:+PrintGCDetails -XX:+UseGCLogRotation -XX:NumberOfGClogFiles=3 -XX:GCLogFileSize=10M

but with every version I'm seeing this error:

Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.

Bugfix #6941923 for 7u2 is referenced here: http://www.oracle.com/technetwork/java/javase/2col/7u2bugfixes-1394661.html

Blazej
  • 51
  • 4
  • 1
    Your flag is wrong - it's "-XX:+UseGCLogFileRotation" (you are missing the "File" in the flag) – Ryan May 13 '13 at 15:55
  • 1
    And the capital "L" is missing in "-XX:NumberOfGClogFiles" (as it was originally in my answer) – Johan Kaving May 30 '13 at 08:31
  • It's not Blazej's fault, the typos are in the bug documentation he referenced (http://bugs.java.com/bugdatabase/view_bug.do?bug_id=6941923). – t0r0X Jan 25 '16 at 20:06
1

An interesting approach would be to redirect gc.log to a named pipe -Xloggc:/my/named/pipe How to write GC log to named pipe

then read that pipe form the application itself: How to open a Windows named pipe from Java?

and log to an arbitrary (e.g. async rolling) logback logger from the code.

Tried that on a Windows machine. Unfortunately, it is trickier to setup on Windows than on Linux.

On Windows it works basically with help of an additional Powershell script (can be a dedicated application as well). This sample project also contains a demo application that can be used right away to test the GC logs redirection to Logback via SLF4J.

Community
  • 1
  • 1
Sergey Shcherbakov
  • 4,534
  • 4
  • 40
  • 65
  • To my understanding you must have a consumer listening to the named pipe or it will eventually block. – Thorbjørn Ravn Andersen Sep 01 '16 at 12:30
  • Yes, that's what the script project is. It also contains a "valve" for the case nothing receives the messages and a couple of comments that describe that. – Sergey Shcherbakov Sep 01 '16 at 19:26
  • Even though it is intriguing it means that your application is now dependent on this external component to function properly. This would most likely mean for us that we could not use it in production :-/ – Thorbjørn Ravn Andersen Sep 02 '16 at 08:12
  • That component is colocated and is running alongside the main JVM, it can be scripted to start together. Your code is also dependent on the JVM process where it runs in and on some OS processes, and often on other application services, etc. But yes, these examples are rather experimental than ready for production use. Mostly because I didn't spend time on load testing, tuning performance, threading model, don't know how stable PowerShell is. In Linux there should be a nicer way to implement such log output loop. – Sergey Shcherbakov Sep 02 '16 at 08:20
  • It is not the colocation and running along the JVM that is the issue, but the fact that if it for _any_ reason breaks, the application hangs indefinitely. – Thorbjørn Ravn Andersen Sep 02 '16 at 08:41
  • Same situation as if some other apps takes all memory or crashes in any other way the JVM were your application is running, e.g. in an application server. This situation with a separate script is arguably even better, since you have full control and can start a dedicated instance and even fence both processes in a cgroup for better resource protection. – Sergey Shcherbakov Sep 02 '16 at 17:42
  • Lots of ways to fail. What are your experiences with running this in production? – Thorbjørn Ravn Andersen Sep 04 '16 at 12:40
  • None. As I mentioned, I don't recommend using scripts as is in production. They simply demo the approach. For production I would probably prepare an app written in C/Go instead of PowerShell. – Sergey Shcherbakov Sep 04 '16 at 15:06
  • 1
    Whenever you actually get experiences with this it would be very interesting to hear them (probably worthy of a blogpost or two). – Thorbjørn Ravn Andersen Sep 04 '16 at 16:00
0

I ended up solving this problem by spawning a new thread in my application and sending jcmd log-rotate command periodically (based on a cron expression).

This is an unconventional approach as you will be using Oracle's Attach API, although the approach served our use case of rotating GC logs hourly.

ajay
  • 31
  • 5
0

Using -XX:+UseGCLogFileRotation will cause some serious long safepoint issue with the solaris and JDK versions 1.7.0_80 - 1.7.0_97 and 1.8.0_20 - 1.8.0_77

Dharan
  • 1
  • 2