Hitachi

Hitachi Application Server V10 Definition Reference Guide (For UNIX® Systems)


7.6.2 -XX:[+|-]HitachiVerboseGC

-XX:[+|-]HitachiVerboseGC outputs the extended verbosegc information to the Java VM log file when GC occurs.

Description

-XX:[+|-]HitachiVerboseGC specifies whether the extended verbosegc information is to be output when GC occurs.

Output format (for SerialGC)
[id] <date> (Skip Full:full_count, Copy:copy_count) 
[gc_kind gc_info, gc_time secs][Eden: eden_info][Survivor: survivor_info]
[Tenured: tenured_info][Metaspace: Metaspace_info]
[class space: class_space_info] [cause:cause_info] [User: user_cpu secs]
[Sys:  system_cpu secs][IM: jvm_alloc_size, mmap_total_size, malloc_total_size]
[TC: thread_count][DOE: doe_alloc_size, called_count]
[CCI: cc_used_sizeK, cc_max_sizeK, cc_infoK]

The following provides details about the output.

Output item

Output content

id

VGC (Java VM log file identifier)

date

Start date and time of GC

This information is not output if the -XX:-HitachiVerboseGCPrintDate option is specified.

full_count

Number of times output of the full GC information was skipped.

This information is output if the -XX:HitachiVerboseGCIntervalTime option is specified.

copy_count

Number of times output of the CopyGC information was skipped.

This information is output if the -XX:HitachiVerboseGCIntervalTime option is specified.

gc_kind

GC type. Either FullGC or GC is output.

gc_info

GC information. This information is output in the following format:

area_length_before_GC -> area_length_after_GC (area_size)

gc_time

Elapsed GC time.

Eden

Eden type. DefNew::Eden is output.

eden_info

Eden information. This information is output in the following format:

area_length_before_GC -> area_length_after_GC (area_size)

Survivor

Survivor type. DefNew::Survivor is output.

survivor_info

Survivor information. This information is output in the following format:

area_length_before_GC -> area_length_after_GC (area_size)

Tenured

Tenured type. Tenured is output.

tenured_info

Tenured information. This information is output in the following format:

area_length_before_GC -> area_length_after_GC (area_size)

Metaspace_info

Memory information of the Metaspace area. This information is output in the following format:

size_of_used_Metaspace_area_before_GCK(capacity_size_of_Metaspace_area_before_GCK, commit_size_of_Metaspace_area_before_GCK)->size_of_used_Metaspace_area_after_GCK(capacity_size_of_Metaspace_area_after_GCK, commit_size_of_Metaspace_area_after_GCK)

classspace_info

Memory information of the Compressed Class Space. This information is output in the following format:

size_of_used_Compressed_Class_Space_before_GCK(capacity_size_of_Compressed_Class_Space_before_GCK, commit_size_of_Compressed_Class_Space_before_GCK)->size_of_used_Compressed_Class_Space_after_GCK(capacity_size_of_Compressed_Class_Space_after_GCK, commit_size_of_Compressed_Class_Space_after_GCK)

This information is not output if the functionality for the compressed object pointer is not used.

cause_info

Details on the cause of GC.

This information is not output if the -XX:-HitachiVerboseGCPrintCause option is specified.

user_cpu

Amount of CPU time that the GC thread spent in user mode. This information is output in units of seconds.

If acquisition of the CPU time fails, unknown is displayed, as in [User:unknown].

This information is not output if the -XX:-HitachiVerboseGCCpuTime option is specified.

system_cpu

Amount of CPU time that the GC thread spent in kernel mode. This information is output in units of seconds.

If acquisition of the CPU time fails, unknown is displayed, as in [Sys:unknown].

This information is not output if the -XX:-HitachiVerboseGCCpuTime option is specified.

jvm_alloc_size

Of the total size of the areas managed in Java VM (the sum of mmap_total_size and malloc_total_size), the size of the area that is currently in use

This information is not output if the -XX:-HitachiVerboseGCPrintJVMInternalMemory option is specified.

mmap_total_size

Of the areas managed in Java VM, the total C heap size allocated by mmap

This information is not output if the -XX:-HitachiVerboseGCPrintJVMInternalMemory option is specified.

malloc_total_size

Of the areas managed in Java VM, the total C heap size allocated by malloc

This information is not output if the -XX:-HitachiVerboseGCPrintJVMInternalMemory option is specified.

thread_count

Number of Java threads

This information is not output if the -XX:-HitachiVerboseGCPrintThreadCount option is specified.

doe_alloc_size

Cumulative size of the heap that was allocated when java.io.File.deleteOnExit() was called

This information is not output if the -XX:-HitachiVerboseGCPrintDeleteOnExit option is specified.

called_count

Number of times java.io.File.deleteOnExit() was called.

This information is not output if the -XX:-HitachiVerboseGCPrintDeleteOnExit option is specified.

cc_used_size

Size of the used code cache area when GC occurred. This information is output in units of kilobytes.

This information is not output if the -XX:-PrintCodeCacheInfo option is specified.

cc_max_size

Maximum size of the code cache area. This information is output in units of kilobytes.

This information is not output if the -XX:-PrintCodeCacheInfo option is specified.

cc_info

Maintenance information

This information is not output if the -XX:-PrintCodeCacheInfo option is specified.

Format of output (for G1GC)

Log entries related to GC and log entries related to Concurrent Marking are output to the Java VM log file. The log entry for one instance of Concurrent Marking is output into two or more lines, because Concurrent Marking is executed in parallel with other applications.

Format of output for the log entries related to GC
[id]<date>[gc_kind gc_info, gc_time secs][Status:gc_status]
[G1GC::Eden: eden_info][G1GC::Survivor: survivor_info]
[G1GC::Tenured: tenured_info][G1GC::Humongous: humongous_info]
[G1GC::Free: free_info][Metaspace: Metaspace_info]
[class space: class_space_info][cause:cause_info][RegionSize: region_sizeK]
[Target: target_time secs][Predicted: predicted_time secs]
[TargetTenured: target_sizeK][Reclaimable: reclaimable_info]
[User: user_cpu secs][Sys: system_cpu secs]
[IM: jvm_alloc_sizeK, mmap_total_sizeK, malloc_total_sizeK][TC: thread_count]
[DOE: doe_alloc_sizeK, called_count][CCI: cc_used_sizeK, cc_max_sizeK, cc_infoK]
Output format of the log entries related to Concurrent Marking
[id]<date>[cm_event][User:  user_cpu secs][Sys:  sys_cpu secs]

The following provides details about the output.

Classification

Output item

Output content

Log entry related to GC

id

VG1 (Java VM log file identifier).

date

Start data and time of GC or Concurrent Marking.

This information is not output if the -XX:-HitachiVerboseGCPrintDate option is specified.

gc_kind

Type of GC or Concurrent Marking. One of the following is output: FullGC, Mixed GC, Young GC, Young GC(initial-mark), CM Remark, or CM Cleanup.

gc_info

Memory information of the JavaHeap area. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_JavaHeap_area_before_GCK/size_of_used_JavaHeap_area_before_GC#K(size_of_JavaHeap_area_before_GC#K)->size_of_used_JavaHeap_area_after_GCK/size_of_used_JavaHeap_area_after_GC#K(size_of_JavaHeap_area_after_GC#K)

gc_time

Amount of time for which the application stopped due to GC. This information is output in units of seconds.

gc_status

GC status.

  • When a To space overflow occurs, to exhausted is output.

  • In cases other than the above, - is output.

For each type of GC, the GC status is output as follows.

  • When gc_kind is Young GC, Young GC(initial-mark), or Mixed GC:

    - or to exhausted is output.

  • When gc_kind is a type other than the above:

    - is output.

eden_info

Memory information of the Eden area. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_Eden_area_before_GC#K(maximum_size_that_can_be_acquired_by_Eden_area_before_GC#K)->size_of_used_Eden_area_after_GC#K(maximum_size_that_can_be_acquired_by_Eden_area_after_GC#K)

The maximum size that can be acquired by the Eden area refers to size_of_New_area - size_of_used_Survivor_area.

survivor_info

Memory information of the Survivor area. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_Survivor_area_before_GC#K->size_of_used_Survivor_area_after_GC#K

tenured_info

Memory information of the Tenured area. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_Tenured_area_before_GC#K->size_of_used_Tenured_area_after_GC#K

humongous_info

Memory information of the Humongous area. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_Humongous_area_before_GC#K->size_of_used_Humongous_area_after_GC#K

free_info

Memory information of the Free area. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_Free_area_before_GC#K->size_of_used_Free_area_after_GC#K

Metaspace_info

Memory information of the Metaspace area. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_Metaspace_area_before_GCK(capacity_size_of_Metaspace_area_before_GCK, commit_size_of_Metaspace_area_before_GCK)->size_of_used_Metaspace_area_after_GCK(capacity_size_of_Metaspace_area_after_GCK, commit_size_of_Metaspace_area_after_GCK)

classspace_info

Memory information of the Compressed Class Space. This information is output in the following format, where values are given in units of kilobytes:

size_of_used_Compressed_Class_Space_before_GCK(capacity_size_of_Compressed_Class_Space_before_GCK, commit_size_of_Compressed_Class_Space_before_GCK)->size_of_used_Compressed_Class_Space_after_GCK(capacity_size_of_Compressed_Class_Space_after_GCK, commit_size_of_Compressed_Class_Space_after_GCK)

This information is not output if the functionality for the compressed object pointer is not used.

cause_info

Details on the cause of GC

This information is not output if the -XX:-HitachiVerboseGCPrintCause option is specified.

region_size

Size of a single region. This information is output in units of kilobytes.

target_time

Target amount of time for which applications are stopped due to GC. This information is output in units of seconds.

You can specify the target time by using the -XX:+MaxGCPauseMillis option.

predicted_time

Amount of time for which applications will be stopped due to GC, as predicted by Java VM. This information is output in units of seconds.

If the type of GC or Concurrent Marking is Full GC, CM Remark, or CM Cleanup, Java VM does not predict the stop time, and 0 is output.

target_size

Size of the Tenured area that is subject to Mixed GC. This information is output in units of kilobytes.

If the type of GC or Concurrent Marking is not Mixed GC, 0 is output.

reclaimable_info

Information about the predicted collection size. This information is output in the following format:

predicted_collection_size K(predicted_collection_rate %)

The predicted collection size is output in units of kilobytes. The predicted collection rate is output as a value with two decimal places.

Note that the information about the predicted collection size is output only for Young GC or Mixed GC immediately after Concurrent Marking. In other cases, Java VM does not predict the collection size, and 0 is output.

user_cpu

Total CPU time that all GC threads spent in user mode. This information is output in units of seconds.

If acquisition of the CPU time fails, unknown is displayed, as in [User:unknown].

This information is not output if the -XX:-HitachiVerboseGCCpuTime option is specified.

system_cpu

Total CPU time that all GC threads spent in kernel mode. This information is output in units of seconds.

If acquisition of the CPU time fails, unknown is displayed, as in [Sys:unknown].

This information is not output if the -XX:-HitachiVerboseGCCpuTime option is specified.

jvm_alloc_size

Of the total size of the areas managed in Java VM (the sum of mmap_total_size and malloc_total_size), the size of the area that is currently in use

This information is not output if the -XX:-HitachiVerboseGCPrintJVMInternalMemory option is specified.

mmap_total_size

Of the areas managed in Java VM, the total C heap size allocated by mmap

This information is not output if the -XX:-HitachiVerboseGCPrintJVMInternalMemory option is specified.

malloc_total_size

Of the areas managed in Java VM, the total C heap size allocated by malloc

This information is not output if the -XX:-HitachiVerboseGCPrintJVMInternalMemory option is specified.

thread_count

Number of Java threads

This information is not output if the -XX:-HitachiVerboseGCPrintThreadCount option is specified.

doe_alloc_size

Cumulative size of the heap that was allocated when java.io.File.deleteOnExit() was called

This information is not output if the -XX:-HitachiVerboseGCPrintDeleteOnExit option is specified.

called_count

Number of times java.io.File.deleteOnExit() was called

This information is not output if the -XX:-HitachiVerboseGCPrintDeleteOnExit option is specified.

cc_used_size

Size of the used code cache area when GC occurred. This information is output in units of kilobytes.

This information is not output if the -XX:-PrintCodeCacheInfo option is specified.

cc_max_size

Maximum size of the code cache area. This information is output in units of kilobytes.

This information is not output if the -XX:-PrintCodeCacheInfo option is specified.

cc_info

Maintenance information

This information is not output if the -XX:-PrintCodeCacheInfo option is specified.

Log entry related to Concurrent Marking

id

VCM (Java VM log file identifier).

date

Start data and time of Concurrent Marking.

This information is not output if the -XX:-HitachiVerboseGCPrintDate option is specified.

cm_event

Status of Concurrent Marking.

  • Concurrent Root Region Scan Start

    The Concurrent Root Region Scan has started.

  • Concurrent Root Region Scan End

    The Concurrent Root Region Scan has ended.

  • Concurrent Mark Start

    The Concurrent Mark has started.

  • Concurrent Mark End

    The Concurrent Mark has ended.

  • Concurrent Mark Stop

    The Concurrent Mark has stopped.

  • Concurrent Cleanup Start

    The Concurrent Cleanup has started.

  • Concurrent Cleanup End

    The Concurrent Cleanup has ended.

user_cpu

Total CPU time that all GC threads spent in user mode. This information is output in units of seconds.

If acquisition of the CPU time fails, unknown is displayed, as in [User:unknown].

This information is not output if the -XX:-HitachiVerboseGCCpuTime option is specified.

If the status of Concurrent Marking is Concurrent Mark Start, 0 is output.

sys_cpu

Total CPU time that all GC threads spent in kernel mode. This information is output in units of seconds.

If acquisition of the CPU time fails, unknown is displayed, as in [Sys:unknown].

This information is not output if the -XX:-HitachiVerboseGCCpuTime option is specified.

If the status of Concurrent Marking is Concurrent Mark Start, 0 is output.

#:

The size is estimated by rounding up the area size to the size of one region, and represented as a multiple of the size of one region.

The following provides details about the causes of GC that are output for cause_info.

Table 7‒4: List of GC causes

Cause number

Cause content

Description

GC type

Other than G1GC

G1GC

0

ObjAllocFail

GC occurred because the object area could not be allocated.

Y

Y

1

System.gc

GC occurred because the java.lang.System.gc method was called.

Y

Y

3

DelayedGC

GC that was suspended by JNI or JVMTI was started.

Y

Y

4

JavaGCCommand

GC occurred due to the javagc command.

Y

Y

6

JHeapProfCommand

GC occurred due to the jheapprof command.

Y

N

8

EMReclaimFail

Because objects were moved to the Java heap due to explicit release of Explicit memory, the Java heap overflowed.

Y

N

9

EMMigrateFail

Because objects were moved to the Java heap due to automatic release of Explicit memory, the Java heap overflowed.

Y

N

10

JVMTIForceGC

GC occurred due to the JVMTI function ForceGarbageCollection().

Y

Y

11

PromotionFail

GC occurred due to a CopyGC promotion failure.

Y

N

12

EMJavaGCCommand

GC occurred because an Explicit memory block was released by the javagc command.

Y

Y

13

EHeapProfCommand

GC occurred due to the eheapprof command.

Y

Y

14

G1HumAllocFail

When G1GC was used, GC occurred because a Humongous area was allocated.

N

Y

15

G1EvacuationPause

An evacuation occurred when G1GC was used.

N

Y

16

Concurrent Marking

No GC occurred but the Concurrent Marking processing, which stops and executes applications, was logged.

N

Y

17

EvacuationFail

When G1GC was used, GC occurred due to an evacuation failure.

N

Y

18

MetaspaceAllocFail

GC occurred because the Metaspace area could not be allocated.

Y

Y

19

LastMetaspaceGC

The last GC occurred before a Metaspace OutOfMemory error occurred.

Y

Y

Legend:

Y: Output.

N: Not output.

Syntax

-XX:[+|-]HitachiVerboseGC

Specifiable values

Type: String

-XX:+HitachiVerboseGC

Outputs the extended verbosegc information to the Java VM log file when GC occurs.

The information about each of the GC internal area types (Eden, Survivor, Tenured, and Metaspace) is output as the extended verbosegc information.

-XX:-HitachiVerboseGC

Does not output the extended verbosegc information to the Java VM log file when a GC occurs.

Default value

If the definition item is omitted:

-XX:-HitachiVerboseGC

Examples

Example of output 1

When SerialGC is used and the -XX:HitachiVerboseGCIntervalTime option is specified

[VGC]<Thu Oct 02 10:38:53.658 2014>(Skip Full:1,Copy:0)
[Full GC 770K->682K(8064K), 0.0050003 secs][DefNew::Eden: 88K->0K(2304K)]
[DefNew::Survivor: 0K->0K(256K)][Tenured: 681K->682K(5504K)] 
[Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)]
[class space: 356K(388K, 388K)->356K(388K, 388K)] 
[cause:System.gc][User: 0.0000000 secs][Sys: 0.0000000 secs]
[IM: 11944K, 12448K, 0K][TC: 22][DOE: 0K, 0][CCI: 1173K, 245760K, 2496K]
Example of output 2

When G1GC is used

  • GC-related log

    [VG1]<Thu Oct 02 10:38:56.193 2014>
    [Full GC 753K/2048K(8192K)->678K/1024K(8192K), 0.0097901 secs][Status:-]
    [G1GC::Eden: 1024K(2048K)->0K(2048K)][G1GC::Survivor: 0K->0K]
    [G1GC::Tenured: 1024K->1024K][G1GC::Humongous: 0K->0K]
    [G1GC::Free: 6144K->7168K] [Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)]
    [class space: 356K(388K, 388K)->356K(388K, 388K)] [cause:System.gc]
    [RegionSize: 1024K][Target: 0.2000000 secs][Predicted: 0.0000000 secs]
    [TargetTenured: 0K][Reclaimable: 0K(0.00%)][User: 0.0000000 secs]
    [Sys: 0.0000000 secs][IM: 20459K, 21920K, 0K][TC: 35][DOE: 0K, 0]
    [CCI: 1172K, 245760K, 2496K]
  • Concurrent Marking related log

    [VCM]<Wed Jul 24 11:45:20 2013>[Concurrent Root Region Scan Start]
    [User: 0.0000000 secs][Sys: 0.0000000 secs]
    [VCM]<Wed Jul 24 11:45:20 2013>[Concurrent Root Region Scan End]
    [User: 0.0126134 secs][Sys: 0.0146961 secs]
    [VCM]<Wed Jul 24 11:45:20 2013>[Concurrent Mark Start][User: 0.0000000 secs]
    [Sys: 0.0000000 secs]
    [VCM]<Wed Jul 24 11:45:34 2013>[Concurrent Mark End][User: 0.0156250 secs]
    [Sys: 0.2495800 secs]