有人能理解G1垃圾收集器输出吗？

我使用以下选项运行G1垃圾收集器的Java程序：

-XX:-UseBiasedLocking -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/var/tmp/gclog.out 

输出看起来像这样……

 44900.297: [GC pause (young)44900.386 (initial-mark), 0.08894851 secs] : [GC concurrent-mark-start] [Parallel Time: 83.7 ms] [GC Worker Start Time (ms): 44900297.6 44900297.6 44900297.6 44900297.6 44900297.6 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 Avg: 44900297.7, Min: 44900297.6, Max: 44900297.7, Diff: 0.1] [Update RS (ms): 23.5 24.3 25.0 25.0 23.9 24.4 25.2 24.1 25.7 24.7 24.8 24.4 24.7 Avg: 24.6, Min: 23.5, Max: 25.7, Diff: 2.1] [Processed Buffers : 16 19 19 23 20 24 18 18 18 17 20 16 19 Sum: 247, Avg: 19, Min: 16, Max: 24, Diff: 8] [Ext Root Scanning (ms): 2.2 2.7 2.2 2.6 3.0 3.1 2.2 1.1 2.3 3.0 2.2 2.4 2.9 Avg: 2.4, Min: 1.1, Max: 3.1, Diff: 2.0] [Mark Stack Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] [Scan RS (ms): 14.1 14.6 14.5 14.3 14.6 14.2 14.4 14.5 14.0 13.9 14.6 14.5 14.0 Avg: 14.3, Min: 13.9, Max: 14.6, Diff: 0.8] [Object Copy (ms): 41.4 39.5 39.4 39.0 39.6 39.5 39.1 41.4 39.0 39.3 39.3 39.8 39.5 Avg: 39.7, Min: 39.0, Max: 41.4, Diff: 2.4] [Termination (ms): 1.3 1.4 1.5 1.6 1.5 1.4 1.6 1.4 1.5 1.7 1.5 1.4 1.3 Avg: 1.5, Min: 1.3, Max: 1.7, Diff: 0.4] [Termination Attempts : 1185 1205 1219 1436 1171 1231 1471 1237 1461 1526 1353 1259 1170 Sum: 16924, Avg: 1301, Min: 1170, Max: 1526, Diff: 356] [GC Worker End Time (ms): 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 44900380.3 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 Avg: 44900380.2, Min: 44900380.2, Max: 44900380.3, Diff: 0.1] [GC Worker Times (ms): 82.6 82.6 82.6 82.6 82.6 82.6 82.5 82.6 82.5 82.5 82.5 82.5 82.5 Avg: 82.6, Min: 82.5, Max: 82.6, Diff: 0.1] [Other: 1.2 ms] [Clear CT: 0.5 ms] [Other: 4.8 ms] [Choose CSet: 0.0 ms] [ 1331M->830M(1840M)] [Times: user=1.07 sys=0.01, real=0.09 secs] 44901.205: [GC concurrent-mark-end, 0.8186002 sec] 44901.205: [GC remark, 0.0258621 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 44901.231: [GC concurrent-count-start] 44901.479: [GC concurrent-count-end, 0.2478477] 44901.479: [GC cleanup 940M->931M(1840M), 0.0073079 secs] 

谁能理解发生了什么？

Answer 1

放弃

我对垃圾第一垃圾收集器并不精通，这个问题激发了我第一次检查它。 我的一些信息可能有问题。

介绍

要获得有关垃圾优先垃圾收集器（G1GC）的更多信息， 垃圾优先垃圾收集文件（ 此处 ， 此处 ， 此处和此处 ）是非常宝贵的资源。 您可以在这里找到G1GC的介绍。 HotSpot Glossary可以方便地理解JVM术语。 以下文章也有助于进一步了解垃圾收集：

• 对硬实时垃圾收集的认真看法 ： 这里和这里
• 多处理器的非阻塞垃圾收集 ： 此处和此处
• 用于实时垃圾收集的非阻塞根扫描 ： 此处
• 用于实时垃圾收集的非阻塞对象复制 ： 此处和此处

使用这些资源和OpenJDK 7 调试 版本 ，您可以开始了解G1GC日志。

定义

使用上面引用的论文和网页，以下是最常出现的一些有用的术语定义：

• 并行标记 ：两者都提供集合“完整性”，并通过紧凑疏散识别成熟的填海区域。 提供收集器完整性，而不对集合集的区域选择强加任何顺序。 提供实时数据信息，允许以“垃圾优先”顺序收集区域。
• heap ：JVM用于动态内存分配的内存区域。
• 堆区域 ：堆被分区为一组大小相等的堆区域。 Garbage-First堆被分成相等大小的堆区域，每个区域都是连续的虚拟内存范围。
• 标记位图 ：每个地址包含一个位，可以作为对象的起始位置。
• 记住集 ：一种数据结构，指示区域外的堆位置，可能包含指向区域中对象的指针。 每个区域都有一个相关的记忆集，表示可能包含指向区域内（实时）对象的指针的所有位置。 Garbage-First记住了来自所有区域的记录指针（有一些例外）。 当前缓冲区或修改后的卡片序列。 记录代之间指针的数据结构。
• root set ：已知可直接访问的一组对象。 可以访问所有活动对象的位置。

源代码

为了更好地理解G1GC日志，我使用了以下OpenJDK 7 源文件：

• 热点/ src目录/股/ VM / gc_implementation / G1 / concurrentMarkThread.cpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / concurrentMark.cpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / concurrentMark.hpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1_specialized_oop_closures.hpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1CollectedHeap.cpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1CollectedHeap.hpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1CollectorPolicy.cpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1CollectorPolicy.hpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1OopClosures.hpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1OopClosures.inline.hpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / g1RemSet.cpp
• 热点/ SRC /共享/ VM /存储器/ sharedHeap.cpp
• 热点/ SRC /共享/ VM /存储器/ sharedHeap.hpp
• 热点/ src目录/股/ VM /公共事业/ taskqueue.hpp
• 热点/ src目录/股/ VM /运行/ timer.cpp
• 热点/ src目录/股/ VM /运行/ timer.hpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / vm_operations_g1.cpp
• 热点/ src目录/股/ VM / gc_implementation / G1 / vm_operations_g1.hpp

日志分析

以下是有问题的G1GC日志的注释副本。

 44900.297: [GC pause (young) (initial-mark), 0.08894851 secs] ^^^^^^^^^^^ Elapsed seconds from JVM start ^^^^^^^^^ Collection pause at safe-point ^^^^^^^^ In full young GC mode ^^^^^^^^^^^^^^^ Last pause included initial mark ^^^^^^^^^^^^^^^^^^ Elapsed seconds in method 44900.386: [GC concurrent-mark-start] ^^^^^^^^^^^ Elapsed seconds from JVM start ^^^^^^^^^^^^^^^^^^^^^^^^^^ Concurrent mark thread started [Parallel Time: 83.7 ms] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Elapsed milliseconds for all GC worker threads to finish [GC Worker Start Time (ms): 44900297.6 44900297.6 44900297.6 44900297.6 44900297.6 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 44900297.7 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed seconds from JVM start that GC worker threads were started Avg: 44900297.7, Min: 44900297.6, Max: 44900297.7, Diff: 0.1] ^^^^^^^^^^^^^^^^^^^^^^ Average GC worker thread start time (elapsed seconds from JVM start) ^^^^^^^^^^^^^^^^^ Minimum GC worker thread start time (elapsed seconds from JVM start) ^^^^^^^^^^^^^^^^^ Maximum GC worker thread start time (elapsed seconds from JVM start) ^^^^^^^^^^^^^^ Total seconds to start all GC worker threads [Update RS (ms): 23.5 24.3 25.0 25.0 23.9 24.4 25.2 24.1 25.7 24.7 24.8 24.4 24.7 ^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to update cards in remembered sets during an evacuation pause Avg: 24.6, Min: 23.5, Max: 25.7, Diff: 2.1] ^^^^^^^^^^^^^^^^^ Average GC worker thread milliseconds to update RS ^^^^^^^^^^^^ Minimum GC worker thread milliseconds to update RS ^^^^^^^^^^^^ Maximum GC worker thread milliseconds to update RS ^^^^^^^^^^^^^^ Minimum/maximum delta of GC worker thread milliseconds to update RS [Processed Buffers : 16 19 19 23 20 24 18 18 18 17 20 16 19 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Total remembered set buffers processed by each GC worker thread Sum: 247, Avg: 19, Min: 16, Max: 24, Diff: 8] ^^^^^^^^^^... Summary information for total remembered set buffers processed by all GC worker thread [Ext Root Scanning (ms): 2.2 2.7 2.2 2.6 3.0 3.1 2.2 1.1 2.3 3.0 2.2 2.4 2.9 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to process heap roots during an evacuation pause Avg: 2.4, Min: 1.1, Max: 3.1, Diff: 2.0] ^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to process heap roots during an evacuation pause [Mark Stack Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to scan strong roots in the mark stack during an evacuation pause Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] ^^^^^^^... Summary information for total milliseconds for all GC worker thread to scan strong roots in the mark stack during an evacuation pause [Scan RS (ms): 14.1 14.6 14.5 14.3 14.6 14.2 14.4 14.5 14.0 13.9 14.6 14.5 14.0 ^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to scan for dirty cards in a heap region to update the remembered set Avg: 14.3, Min: 13.9, Max: 14.6, Diff: 0.8] ^^^^^^^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to scan for dirty cards in a heap region to update the remembered set [Object Copy (ms): 41.4 39.5 39.4 39.0 39.6 39.5 39.1 41.4 39.0 39.3 39.3 39.8 39.5 ^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to scan root sets for pointers to include in this heap region's remembered set during an evacuation pause Avg: 39.7, Min: 39.0, Max: 41.4, Diff: 2.4] ^^^^^^^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to scan root sets for pointers to include in this heap region's remembered set during an evacuation pause [Termination (ms): 1.3 1.4 1.5 1.6 1.5 1.4 1.6 1.4 1.5 1.7 1.5 1.4 1.3 ^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered set during an evacuation pause Avg: 1.5, Min: 1.3, Max: 1.7, Diff: 0.4] ^^^^^^^^^^^^^^... Summary information for total elapsed milliseconds for all GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered set during an evacuation pause [Termination Attempts : 1185 1205 1219 1436 1171 1231 1471 1237 1461 1526 1353 1259 1170 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Total attempts for each GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered set during an evacuation pause Sum: 16924, Avg: 1301, Min: 1170, Max: 1526, Diff: 356] ^^^^^^^^^^^^^^^... Summary information for total attempts for all GC worker thread to terminate scanning root sets for pointers to include in this heap region's remembered set during an evacuation pause [GC Worker End Time (ms): 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 44900380.3 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 44900380.2 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed seconds from JVM start that GC worker threads ended Avg: 44900380.2, Min: 44900380.2, Max: 44900380.3, Diff: 0.1] ^^^^^^^^^^^^... Summary information for total elapsed seconds from JVM start that GC worker threads ended for all GC worker threads [GC Worker Times (ms): 82.6 82.6 82.6 82.6 82.6 82.6 82.5 82.6 82.5 82.5 82.5 82.5 82.5 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^... Elapsed milliseconds for each GC worker threads Avg: 82.6, Min: 82.5, Max: 82.6, Diff: 0.1] ^^^^^^^^^^^^^... Summary information for total elapsed milliseconds for all GC worker threads [Other: 1.2 ms] ^^^^^^^^^^^^^^^^^^^^^^^ Other milliseconds during GC parallel processing; basically, total milliseconds minus: update RS, ext root scanning, mark stack scanning, scan RS, object copy, termination [Clear CT: 0.5 ms] ^^^^^^^^^^^^^^^^^^^^^^^ Total milliseconds cleaning up the dirty card tables list [Other: 4.8 ms] ^^^^^^^^^^^^^^^^^^^^ Total milliseconds in this GC pause not spent in parallel and clear CT [Choose CSet: 0.0 ms] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ Total milliseconds to choose young heap regions to add to the collection set [ 1331M->830M(1840M)] ^^^^^ Heap size change for this garbage collector ^^^^^ Total heap size before this collection pause ^^^^ Total heap size after this collection pause ^^^^^ Total heap size capacity for this garbage collector [Times: user=1.07 sys=0.01, real=0.09 secs] ^^^^^^^^ Execution seconds (uses TraceCPUTime class; constructor initializes times to zero, destructor prints times) ^^^^^^^^^^ User execution seconds for all threads ^^^^^^^^^ System execution seconds ^^^^^^^^^^^ Real (wall clock) execution seconds 44901.205: [GC concurrent-mark-end, 0.8186002 sec] ^^^^^^^^^^^ Elapsed seconds from JVM start ^^^^^^^^^^^^^^^^^^^^^^^^ Concurrent mark thread ended ^^^^^^^^^^^^^ Total seconds executing concurrent mark thread 44901.205: [GC remark, 0.0258621 secs] ^^^^^^^^^^^ Elapsed seconds from JVM start ^^^^^^^^^^ Concurrent re-marking of all heap roots, final work [Times: user=0.02 sys=0.00, real=0.03 secs] ^^^^^^^^ Execution seconds (uses TraceCPUTime class; constructor initializes times to zero, destructor prints times) ^^^^^^^^^^ User execution seconds for all threads ^^^^^^^^^ System execution seconds ^^^^^^^^^^^ Real (wall clock) execution seconds 44901.231: [GC concurrent-count-start] ^^^^^^^^^^^ Elapsed seconds from JVM start ^^^^^^^^^^^^^^^^^^^^^^^^^^^ Start concurrent marking of live objects 44901.479: [GC concurrent-count-end, 0.2478477] ^^^^^^^^^^^ Elapsed seconds from JVM start ^^^^^^^^^^^^^^^^^^^^^^^^^^^ End concurrent marking of live objects ^^^^^^^^^^^^ Total seconds to do concurrent marking of live objects 44901.479: [GC cleanup 940M->931M(1840M), 0.0073079 secs] ^^^^^^^^^^^ Elapsed seconds from JVM start ^^^^^^^^^^^ Concurrent marking cleanup (world is stopped at this checkpoint) ^... Heap size change for this garbage collector ^^^^ Total heap size before this operation ^^^^ Total heap size after this operation ^^^^^ Total heap size capacity for this garbage collector ^^^^^^^^^^^^^^ Total seconds executing concurrent marking cleanup 

OpenJDK 7 G1GC

如果您可以构建OpenJDK 7的调试副本 ，那么您将可以使用更多JVM选项，它们将为您提供有关G1GC的更多信息。 使用以下命令获取所有JVM选项的列表：

 java -XX:+AggressiveOpts -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal -XX:+PrintFlagsWithComments -version 

输出显示以下G1GC选项; 这不是一个包罗万象的清单，只是我认为有些问题。

  intx G1CardCountCacheExpandThreshold = 16 Expand the card count cache if the number of collisions for a particular entry exceeds this value. uintx G1ConcMarkForceOverflow = 0 The number of times we'll force an overflow during concurrent marking double G1ConcMarkStepDurationMillis = 10.000000 {product} Target duration of individual concurrent marking steps in milliseconds. intx G1ConcRSHotCardLimit = 4 The threshold that defines (>=) a hot card. intx G1ConcRSLogCacheSize = 10 Log base 2 of the length of conc RS hot-card cache. bool G1ConcRegionFreeingVerbose = false Enables verboseness during concurrent region freeing intx G1ConfidencePercent = 50 {product} Confidence level for MMU/pause predictions bool G1DeferredRSUpdate = true If true, use deferred RS updates bool G1FixedEdenSize = false When set, G1 will not allocate unused survivor space regions uintx G1FixedSurvivorSpaceSize = 0 If non-0 is the size of the G1 survivor space, otherwise SurvivorRatio is used to determine the size bool G1FixedTenuringThreshold = false When set, G1 will not adjust the tenuring threshold bool G1Gen = true If true, it will enable the generational G1 uintx G1HeapRegionSize = 0 {product} Size of the G1 regions. intx G1InitYoungSurvRatio = 50 Expected Survival Rate for newly allocated bytes intx G1MarkRegionStackSize = 1048576 {product} Size of the region stack for concurrent marking. intx G1MarkingOverheadPercent = 0 Overhead of concurrent marking intx G1MarkingVerboseLevel = 0 Level (0-4) of verboseness of the marking code intx G1MaxHotCardCountSizePercent = 25 The maximum size of the hot card count cache as a percentage of the number of cards for the maximum heap. intx G1MaxVerifyFailures = -1 The maximum number of verification failrues to print. -1 means print all. intx G1PausesBtwnConcMark = -1 If positive, fixed number of pauses between conc markings intx G1PolicyVerbose = 0 The verbosity level on G1 policy decisions bool G1PrintCTFilterStats = false If true, print stats on RS filtering effectiveness bool G1PrintHeapRegions = false {diagnostic} If set G1 will print information on which regions are being allocated and which are reclaimed. bool G1PrintOopAppls = false When true, print applications of closures to external locs. bool G1PrintParCleanupStats = false When true, print extra stats about parallel cleanup. bool G1PrintReachableAtInitialMark = false Reachable object dump at the initial mark pause ccstr G1PrintReachableBaseFile = The base file name for the reachable object dumps bool G1PrintRegionLivenessInfo = false {product} Prints the liveness information for all regions in the heap at the end of a marking cycle. bool G1RSCountHisto = false If true, print a histogram of RS occupancies after each pause bool G1RSLogCheckCardTable = false If true, verify that no dirty cards remain after RS log processing. bool G1RSScrubVerbose = false When true, do RS scrubbing with verbose output. intx G1RSetRegionEntries = 0 {product} Max number of regions for which we keep bitmaps.Will be set ergonomically by default intx G1RSetRegionEntriesBase = 256 Max number of regions in a fine-grain table per MB. uintx G1RSetScanBlockSize = 64 {product} Size of a work unit of cards claimed by a worker threadduring RSet scanning. intx G1RSetSparseRegionEntries = 0 {product} Max number of entries per region in a sparse table.Will be set ergonomically by default. intx G1RSetSparseRegionEntriesBase = 4 Max number of entries per region in a sparse table per MB. intx G1RSetUpdatingPauseTimePercent = 10 {product} A target percentage of time that is allowed to be spend on process RS update buffers during the collection pause. bool G1RecordHRRSEvents = false When true, record recent calls to rem set operations. bool G1RecordHRRSOops = false When true, record recent calls to rem set operations. intx G1RefProcDrainInterval = 10 {product} The number of discovered reference objects to process before draining concurrent marking work queues. intx G1ReservePercent = 10 {product} It determines the minimum reserve we should have in the heap to minimize the probability of promotion failure. uintx G1SATBBufferEnqueueingThresholdPercent = 60 {product} Before enqueueing them, each mutator thread tries to do some filtering on the SATB buffers it generates. If post-filtering the percentage of retained entries is over this threshold the buffer will be enqueued for processing. A value of 0 specifies that mutator threads should not do such filtering. intx G1SATBBufferSize = 1024 {product} Number of entries in an SATB log buffer. bool G1SATBPrintStubs = false If true, print generated stubs for the SATB barrier intx G1SATBProcessCompletedThreshold = 20 Number of completed buffers that triggers log processing. bool G1ScrubRemSets = true When true, do RS scrubbing after cleanup. uintx G1SecondaryFreeListAppendLength = 5 The number of regions we will add to the secondary free list at every append operation bool G1StressConcRegionFreeing = false It stresses the concurrent region freeing operation uintx G1StressConcRegionFreeingDelayMillis = 0 Artificial delay during concurrent region freeing bool G1SummarizeConcMark = false {diagnostic} Summarize concurrent mark info bool G1SummarizeRSetStats = false {diagnostic} Summarize remembered set processing info intx G1SummarizeRSetStatsPeriod = 0 {diagnostic} The period (in number of GCs) at which we will generate update buffer processing info (0 means do not periodically generate this info); it also requires -XX:+G1SummarizeRSetStats bool G1TraceConcRefinement = false {diagnostic} Trace G1 concurrent refinement bool G1TraceMarkStackOverflow = false If true, extra debugging code for CM restart for ovflw. intx G1UpdateBufferSize = 256 {product} Size of an update buffer bool G1VerifyDuringGCPrintReachable = false If conc mark verification fails, dump reachable objects intx G1YoungSurvRateNumRegionsSummary = 0 the number of regions for which we'll print a surv rate summary. bool G1YoungSurvRateVerbose = false print out the survival rate of young regions according to age. 

要查看使用OpenJDK 7调试版本提供哪种G1GC信息，我使用了以下测试程序：

 import java.lang.ref.WeakReference; import java.util.ArrayList; import java.util.Iterator; import java.util.List; import java.util.Random; public class G1GCTest implements Runnable { private int iterations = 0; private final Random rnd = new Random(); private final List 

并使用以下方式执行：

 java -Xms8m -Xmx8m -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+G1SummarizeConcMark -XX:+G1SummarizeRSetStats -XX:+G1YoungSurvRateVerbose -XX:G1PolicyVerbose=2 -verbose:gc G1GCTest 

其输出非常冗长，但提供了大量信息，如果您正在进行一些GC调整，这些信息可能会很有用。

Answer 2

一个Oracle人写了一篇博文 ，解释了GC日志的每个部分。 我发现它非常有用。

以下是博客的引用。

0.522：[GC暂停（年轻），0.15877971秒]

这是最高级别的信息，告诉我们这是一个疏散暂停，从过程开始的0.522秒开始，其中所有撤离的区域都是Young，即Eden和Survivor区域。 这个系列花了0.15877971秒来完成。

疏散暂停也可以混合。 在这种情况下，所选择的区域集包括所有年轻区域以及一些旧区域。

1.730：[GC暂停（混合），0.32714353秒]

让我们来看看这个疏散暂停中执行的所有子任务。

[平行时间：157.1毫秒]

并行时间是所有并行GC工作线程花费的总耗用时间。 以下行对应于这些工作线程在此总并行时间内执行的并行任务，在这种情况下为157.1 ms。

[GC Worker Start（ms）：522.1 522.2 522.2 522.2 Avg：522.2，Min：522.1，Max：522.2，Diff：0.1]

第一行告诉我们每个工作线程的开始时间（以毫秒为单位）。 开始时间是根据工作线程ID排序的 – 线程0从522.1ms开始，线程1从过程开始522.2ms开始。 第二行告诉所有工作线程的开始时间的平均值，最小值，最大值和差值。

Answer 3

我有一个工具（预发布，而不是OSS），这可能会在这里阐明一些。

如果您有兴趣，请给我发电子邮件，我们可以谈谈如何获取日志给我。

对于post上的评论 – 我在类似prod的负载中使用了G1并且看到了一些好的数字（不如你看到的那些好，但在某些负载上比CMS好）。

没有看到任何来自Java 7 beta的崩溃（但确实看到了一些Java 6版本）。