Java 8 Garbage Collection Logging: Difference between revisions

From NovaOrdis Knowledge Base
Jump to navigation Jump to search
 
(17 intermediate revisions by the same user not shown)
Line 17: Line 17:
</syntaxhighlight>
</syntaxhighlight>


The output can be sent into a configured file, as shown here: [[#Sending_the_GC_Logging_Output_to_a_File|Sending the GC Logging Output to a File]].
The output can be sent into a configured file (including /dev/stdout), as shown here: [[#Sending_the_GC_Logging_Output_to_a_File|Sending the GC Logging Output to a File]].


The output format can be configured as shown here: [[#Output_Format_Configuration|Output Format Configuration]].
The output format can be configured as shown here: [[#Output_Format_Configuration|Output Format Configuration]].


=Sending the GC Logging Output to a File=
=<span id='-Xloggc:'></span>Sending the GC Logging Output to a File=


When <code>-verbose:gc</code> is used, the JVM sends the output to stdout. To configured it to send the output to a particular file, use:
When <code>-verbose:gc</code> is used, the JVM sends the output to stdout. To configured it to send the output to a particular file, use:
<syntaxhighlight lang='text'>
<syntaxhighlight lang='text'>
-Xloggc:<file-name>
-Xloggc:<file-path>
</syntaxhighlight>
</syntaxhighlight>
If <code>-Xloggc</code> option is used, the stdout output is not generated anymore, and the output is directed into the specified file. The file is created if does not exist, and if it exists, it is overwritten. Additionally to <code>-verbose:gc</code>, each entry is prefixed by the number of seconds and milliseconds since the JVM start:
If <code>-Xloggc</code> option is used, the stdout output is not generated anymore, and the output is directed into the specified file. The file is created if does not exist, and if it exists, it is overwritten. The file path can be absolute or relative. In case of a relative path, it is relative to the current directory. "/dev/stdout" can be used as file name, in which case the output will be directed to stdout.
 
The option automatically turns on the following: <code>[[#-XX:.2BPrintGC|-XX:+PrintGC]]</code>, <code>[[#-XX:.2BPrintGCTimeStamps|-XX:+PrintGCTimeStamps]]</code>, so unlike in the case of the output produced by <code>-verbose:gc</code>, each entry is prefixed by the number of seconds and milliseconds since the JVM start:
<syntaxhighlight lang='text'>
<syntaxhighlight lang='text'>
169.963: [GC (Allocation Failure)  410112K->410112K(1048064K), 0.0008570 secs]
169.963: [GC (Allocation Failure)  410112K->410112K(1048064K), 0.0008570 secs]
169.964: [Full GC (Allocation Failure)  410112K->512K(720896K), 0.0032239 secs]
169.964: [Full GC (Allocation Failure)  410112K->512K(720896K), 0.0032239 secs]
</syntaxhighlight>
</syntaxhighlight>
{{Note|Using <tt>-Xloggc</tt> makes the <tt>-verbose:gc</tt> option redundant.}}
<code>-Xloggc</code> also generates a few summary lines at the top of the file, including a JVM header line and the command line flags in effect:
 
<syntaxhighlight lang='text'>
=Output Format Configuration=
Java HotSpot(TM) 64-Bit Server VM (25.221-b11) for bsd-amd64 JRE (1.8.0_221-b11), built on Jul  4 2019 04:36:22 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 33554432k(1243808k free)


/proc/meminfo:


 
CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=1073741824 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
 
0.710: [GC (Allocation Failure)  414863K->410120K(852480K), 0.0014617 secs]
 
0.712: [GC (Allocation Failure)  410120K->410072K(852480K), 0.0054436 secs]
 
 
 
 
 
 
 
 
 
 
 
 
 
 
In Java 8, GC logging is enabled with the <tt>[[#-Xloggc:|-Xloggc:<file>]]</tt> (see below). The actual -XX values the JVM operates with are displayed at the top of the log file:
 
<pre>
...
...
CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
</syntaxhighlight>
...
{{Note|Using <tt>-Xloggc</tt> makes the <tt>-verbose:gc</tt> option redundant, but it can be left on command line, as it will not cause any harm.}}
</pre>
 


=Output Format Configuration=
The recommended GC logging configuration is:
The recommended GC logging configuration is:
 
<syntaxhighlight lang='text'>
<pre>
-Xloggc:<absolute-path> -XX:+PrintGCDateStamps -XX:+PrintGCDetails
-Xloggc:<absolute-path> -XX:+PrintGCDateStamps -XX:+PrintGCDetails
</pre>
</syntaxhighlight>


In case the space of the filesystem logs are written onto is limited, [[#GC_Log_File_Rotation|log rotation]] can be enabled.
==-XX:+PrintGC==


==Options==
<syntaxhighlight lang='text'>
 
===-Xloggc:===
 
Turns on GC logging and directs the output into the specified file. When used, <tt>[[#-verbose:gc|-verbose:gc]]</tt> becomes irrelevant.
 
<pre>
-Xloggc:<file>
</pre>
 
where <file> can be absolute or relative. In case of a relative path, it is relative to the current directory.
 
If used, the option automatically turns on the following: <tt>[[#-XX:.2BPrintGC|-XX:+PrintGC]]</tt>, <tt>[[#-XX:.2BPrintGCTimeStamps|-XX:+PrintGCTimeStamps]]</tt>.
 
===-XX:+PrintGC===
 
<pre>
-XX:+PrintGC
-XX:+PrintGC
</pre>
</syntaxhighlight>
Enables printing of messages at every GC. <code>[[#-Xloggc:|-Xloggc:<file>]]</code> turns this option on implicitly.


Enables printing of messages at every GC. By default, this option is disabled, but <tt>[[#-Xloggc:|-Xloggc:<file>]]</tt> turns it on implicitly.
==-XX:+PrintGCTimeStamps==


===-XX:+PrintGCTimeStamps===
<syntaxhighlight lang='text'>
 
<pre>
-XX:+PrintGCTimeStamps
-XX:+PrintGCTimeStamps
</pre>
</syntaxhighlight>


Enables printing of time stamps (time in seconds since the JVM started) at every GC. By default, this option is disabled. It is implicit turned on if <tt>[[#-Xloggc:|-Xloggc:<file>]]</tt> is used. Time stamps recorded this way provide a chronology relative to the time the JVM started, but additional calculation is needed to translate the timestamps to normal timestamps, and it is only possible if the JVM start time is also recorded. A better way to record timestamps is to use <tt>[[#-XX:.2BPrintGCDateStamps|-XX:+PrintGCDateStamps]]</tt>.
Enables printing of time stamps (time in seconds since the JVM started) at every GC. By default, this option is disabled. It is implicit turned on if <code>[[#-Xloggc:|-Xloggc:<file>]]</code> is used. Time stamps recorded this way provide a chronology relative to the time the JVM started, but additional calculation is needed to translate the timestamps to normal timestamps, and it is only possible if the JVM start time is also recorded. A better way to record timestamps is to use <code>[[#-XX:.2BPrintGCDateStamps|-XX:+PrintGCDateStamps]]</code>.


===-XX:+PrintGCDateStamps===
==-XX:+PrintGCDateStamps==


<pre>
<syntaxhighlight lang='text'>
-XX:+PrintGCDateStamps
-XX:+PrintGCDateStamps
</pre>
</syntaxhighlight>


Records the GC event timestamps in the following format:
Records the GC event timestamps in the following format:


<pre>
<syntaxhighlight lang='text'>
2017-02-12T19:26:03.328+0800:
2017-02-12T19:26:03.328+0800:
</pre>
</syntaxhighlight>


===-XX:+PrintGCDetails===
==-XX:+PrintGCDetails==


Enables printing of detailed messages at every GC:
Enables printing of detailed messages at every GC:


<pre>
<syntaxhighlight lang='text'>
-XX:+PrintGCDetails
-XX:+PrintGCDetails
</pre>
</syntaxhighlight>


When used, each GC event contains information of how the event affected various heap areas such as the young generation, old generation and the metaspace. The default behavior is to report how the entire heap was modified as the result of the GC event. The difference in output is the following:
When used, each GC event contains information of how the event affected various heap areas such as the young generation, old generation and the metaspace. The default behavior is to report how the entire heap was modified as the result of the GC event. The difference in output is the following:


<pre>
<syntaxhighlight lang='text'>
2017-02-12T19:26:03.378+0800: 0.144: [Full GC (Ergonomics)  126674K->126513K(413696K), 0.0181008 secs]
2017-02-12T19:26:03.378+0800: 0.144: [Full GC (Ergonomics)  126674K->126513K(413696K), 0.0181008 secs]
</pre>
</syntaxhighlight>


<pre>
<syntaxhighlight lang='text'>
2017-02-12T19:42:35.003+0800: 0.156: [Full GC (Ergonomics) [PSYoungGen: 10721K->0K(141824K)] [ParOldGen: 115952K->126513K(270848K)] 126674K->126513K(412672K), [Metaspace: 3447K->3447K(1056768K)], 0.0182535 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
2017-02-12T19:42:35.003+0800: 0.156: [Full GC (Ergonomics) [PSYoungGen: 10721K->0K(141824K)] [ParOldGen: 115952K->126513K(270848K)] 126674K->126513K(412672K), [Metaspace: 3447K->3447K(1056768K)], 0.0182535 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]
</pre>
</syntaxhighlight>
 
===-verbose:gc===
 
Displays GC log information at stdout. This option is rendered irrelevant by  <tt>[[#-Xloggc:|-Xloggc:<file>]]</tt>. When <tt>-Xloggc:<file></tt> is used, the GC log information is redirected into the specified file.
 
<pre>
-verbose:gc
</pre>
 
===GC Log File Rotation===
 
<pre>
-XX:+UseGCLogFileRotation
</pre>
 
<pre>
-XX:NumberOfGCLogFiles=5
</pre>
 
<pre>
-XX:GCLogFileSize=3M
</pre>


===-XX:+PrintGCApplicationConcurrentTime===
==-XX:+PrintGCApplicationConcurrentTime==


Enables printing of how much time elapsed since the last GC pause.
Enables printing of how much time elapsed since the last GC pause.


<pre>
<syntaxhighlight lang='text'>
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationConcurrentTime
</pre>
</syntaxhighlight>


Output Example:
Output Example:


<pre>
<syntaxhighlight lang='text'>
2017-02-12T19:54:39.920+0800: 0.484: Application time: 0.0261502 seconds
2017-02-12T19:54:39.920+0800: 0.484: Application time: 0.0261502 seconds
</pre>
</syntaxhighlight>


===-XX:+PrintGCApplicationStoppedTime===
==-XX:+PrintGCApplicationStoppedTime==


Enables printing of how much time the GC pause lasted.
Enables printing of how much time the GC pause lasted.


<pre>
<syntaxhighlight lang='text'>
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationStoppedTime
</pre>
</syntaxhighlight>


Output Example:
Output Example:


<pre>
<syntaxhighlight lang='text'>
2017-02-12T19:57:57.170+0800: 0.116: Total time for which application threads were stopped: 0.0218238 seconds
2017-02-12T19:57:57.170+0800: 0.116: Total time for which application threads were stopped: 0.0218238 seconds
</pre>
</syntaxhighlight>
 
=GC Log File Rotation=
 
In case the space of the filesystem logs are written onto is limited, log rotation can be enabled as follows:
 
<syntaxhighlight lang='text'>
-XX:+UseGCLogFileRotation
</syntaxhighlight>
 
<syntaxhighlight lang='text'>
-XX:NumberOfGCLogFiles=5
</syntaxhighlight>
 
<syntaxhighlight lang='text'>
-XX:GCLogFileSize=3M
</syntaxhighlight>

Latest revision as of 20:24, 28 December 2020

External

Internal

Overview

Garbage collection logging is turned on by: 

-verbose:gc

By default, the output is sent to stdout, and the format is somewhat limited: 

[GC (Allocation Failure)  410112K->410112K(1048064K), 0.0010012 secs]
[Full GC (Allocation Failure)  410112K->512K(546304K), 0.0108077 secs]

The output can be sent into a configured file (including /dev/stdout), as shown here: Sending the GC Logging Output to a File.

The output format can be configured as shown here: Output Format Configuration.

Sending the GC Logging Output to a File

When -verbose:gc is used, the JVM sends the output to stdout. To configured it to send the output to a particular file, use: 

-Xloggc:<file-path>

If -Xloggc option is used, the stdout output is not generated anymore, and the output is directed into the specified file. The file is created if does not exist, and if it exists, it is overwritten. The file path can be absolute or relative. In case of a relative path, it is relative to the current directory. "/dev/stdout" can be used as file name, in which case the output will be directed to stdout.

The option automatically turns on the following: -XX:+PrintGC, -XX:+PrintGCTimeStamps, so unlike in the case of the output produced by -verbose:gc, each entry is prefixed by the number of seconds and milliseconds since the JVM start: 

169.963: [GC (Allocation Failure)  410112K->410112K(1048064K), 0.0008570 secs]
169.964: [Full GC (Allocation Failure)  410112K->512K(720896K), 0.0032239 secs]

-Xloggc also generates a few summary lines at the top of the file, including a JVM header line and the command line flags in effect: 

Java HotSpot(TM) 64-Bit Server VM (25.221-b11) for bsd-amd64 JRE (1.8.0_221-b11), built on Jul  4 2019 04:36:22 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 33554432k(1243808k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=1073741824 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
0.710: [GC (Allocation Failure)  414863K->410120K(852480K), 0.0014617 secs]
0.712: [GC (Allocation Failure)  410120K->410072K(852480K), 0.0054436 secs]
...

Using -Xloggc makes the -verbose:gc option redundant, but it can be left on command line, as it will not cause any harm.

Output Format Configuration

The recommended GC logging configuration is: 

-Xloggc:<absolute-path> -XX:+PrintGCDateStamps -XX:+PrintGCDetails

-XX:+PrintGC

-XX:+PrintGC

Enables printing of messages at every GC. -Xloggc:<file> turns this option on implicitly.

-XX:+PrintGCTimeStamps

-XX:+PrintGCTimeStamps

Enables printing of time stamps (time in seconds since the JVM started) at every GC. By default, this option is disabled. It is implicit turned on if -Xloggc:<file> is used. Time stamps recorded this way provide a chronology relative to the time the JVM started, but additional calculation is needed to translate the timestamps to normal timestamps, and it is only possible if the JVM start time is also recorded. A better way to record timestamps is to use -XX:+PrintGCDateStamps.

-XX:+PrintGCDateStamps

-XX:+PrintGCDateStamps

Records the GC event timestamps in the following format: 

2017-02-12T19:26:03.328+0800:

-XX:+PrintGCDetails

Enables printing of detailed messages at every GC: 

-XX:+PrintGCDetails

When used, each GC event contains information of how the event affected various heap areas such as the young generation, old generation and the metaspace. The default behavior is to report how the entire heap was modified as the result of the GC event. The difference in output is the following: 

2017-02-12T19:26:03.378+0800: 0.144: [Full GC (Ergonomics)  126674K->126513K(413696K), 0.0181008 secs]

2017-02-12T19:42:35.003+0800: 0.156: [Full GC (Ergonomics) [PSYoungGen: 10721K->0K(141824K)] [ParOldGen: 115952K->126513K(270848K)] 126674K->126513K(412672K), [Metaspace: 3447K->3447K(1056768K)], 0.0182535 secs] [Times: user=0.10 sys=0.03, real=0.02 secs]

-XX:+PrintGCApplicationConcurrentTime

Enables printing of how much time elapsed since the last GC pause. 

-XX:+PrintGCApplicationConcurrentTime

Output Example: 

2017-02-12T19:54:39.920+0800: 0.484: Application time: 0.0261502 seconds

-XX:+PrintGCApplicationStoppedTime

Enables printing of how much time the GC pause lasted. 

-XX:+PrintGCApplicationStoppedTime

Output Example: 

2017-02-12T19:57:57.170+0800: 0.116: Total time for which application threads were stopped: 0.0218238 seconds

GC Log File Rotation

In case the space of the filesystem logs are written onto is limited, log rotation can be enabled as follows: 

-XX:+UseGCLogFileRotation

-XX:NumberOfGCLogFiles=5

-XX:GCLogFileSize=3M
Retrieved from "https://kb.novaordis.com/index.php?title=Java_8_Garbage_Collection_Logging&oldid=74321"