Может кто-то разобраться с выводом сборщика мусора G1? - PullRequest
17 голосов
/ 16 сентября 2011

Я запускаю программу Java с сборщиком мусора G1, используя следующие параметры:

-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]

Кто-нибудь может понять, что происходит?

Ответы [ 3 ]

46 голосов
/ 29 сентября 2011

Отказ

Я не очень хорошо разбираюсь в сборщике мусора и мусоре. Вопрос вдохновил меня проверить это впервые. Есть шанс Я могу ошибаться с некоторыми из моих сведений.

Введение

Чтобы получить больше информации о сборщике мусора (G1GC), Сборщик мусора - первая сборка бумага ( здесь , здесь , здесь и здесь ) является бесценный ресурс. Вы можете найти введение в G1GC здесь . Глоссарий HotSpot пригодится понимать термины JVM. Следующие документы были также полезны в дальнейшем понимание сборки мусора:

  • Взгляд на сборку мусора в реальном времени : здесь и здесь
  • Неблокирующая сборка мусора для мультипроцессоров : здесь и здесь
  • Неблокирующее корневое сканирование для сбора мусора в реальном времени : здесь
  • Неблокирующая копия объекта для сборки мусора в реальном времени : здесь и здесь

С этими ресурсами и отладкой OpenJDK 7 сборка , вы можете начать понимать журнал G1GC.

Определения

Используя статьи и веб-страницы, упомянутые выше, вот несколько полезных определения терминов, которые встречаются чаще всего:

  • одновременная маркировка : и то, и другое обеспечивает коллекцию «полнотой» и идентифицирует регионы, готовые к рекультивации путем компактной эвакуации. Обеспечивает полнота коллектора без наложения какого-либо заказа на выбор региона для коллекционные наборы. Предоставляет информацию в реальном времени, которая позволяет регионам собраны в порядке «мусора в первую очередь».
  • heap : область памяти, используемая JVM для динамического выделения памяти.
  • область кучи : куча разбивается на набор кучи одинакового размера регионы. Куча «Мусор-Первый» разделена на равные по размеру области кучи непрерывный диапазон виртуальной памяти.
  • растровое изображение маркировки : содержит один бит для каждого адреса, который может быть началом объект.
  • запомненный набор : структура данных, указывающая расположение кучи вне регион, который может содержать указатели на объекты в регионе. Каждый регион имеет связанный запомненный набор, который указывает все местоположения, которые могут содержать указатели на (живые) объекты в регионе. Мусор - Первые запоминающиеся наборы запись указателей из всех регионов (за некоторыми исключениями). Текущий буфер или последовательность измененных карт. Структура данных, которая записывает указатели между поколений.
  • корневой набор : набор объектов, о которых известно, что они доступны напрямую. места, из которых доступны все живые объекты.

Исходный код

Чтобы лучше понять журнал 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
  • хоtspot / src / share / vm / utilities / taskqueue.hpp
  • hotspot / src / share / vm / runtime / timer.cpp
  • hotspot / src / share / vm / runtime / timer.hpp
  • точка доступа / src / share / vm / gc_implementation / g1 / vm_operations_g1.cpp
  • точка доступа / src / share / vm / gc_implementation / g1 / vm_operations_g1.hpp
1134 * Анализ журнала

Ниже приведена аннотированная копия рассматриваемого журнала 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.

Чтобы увидеть, какой тип информации G1GC предоставляется с помощью отладочной сборки OpenJDK 7, я использовал следующую тестовую программу:

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<Object> young = new ArrayList<Object>(1000);
    private final List<WeakReference<Object>> old =
            new ArrayList<WeakReference<Object>>(100000);

    private void clearOld() {
        int clearedCnt = 0;
        for (final Iterator<WeakReference<Object>> iter = old.iterator(); iter
                .hasNext();)
        {
            final WeakReference<Object> ref = iter.next();
            if (null == ref.get()) {
                iter.remove();
                clearedCnt++;
            }
        }
        if (0 < clearedCnt) {
            System.out.println("Cleared " + clearedCnt
                    + " weak references to old objects.");
        }
    }

    public void run() {
        if (0 == ++iterations % 10000) {
            System.out.println("iterations=" + iterations + ", young.size()="
                    + young.size() + ", old.size()=" + old.size());
            clearOld();
            try {
                Thread.sleep(100);
            } catch (final Throwable e) {
                // Do nothing!
            }
        }
        if (rnd.nextBoolean()) {
            young.add(new byte[1000]);
        }
        if (rnd.nextBoolean() && !young.isEmpty()) {
            final int nextInt = Math.abs(rnd.nextInt());
            final int idx = nextInt % young.size();
            final Object obj = young.remove(idx);
            old.add(new WeakReference<Object>(obj));
        }
    }

    public static void main(final String[] args) {
        final G1GCTest t = new G1GCTest();
        while (1000000 > t.iterations) {
            t.run();
        }
    }
}

И выполнил его, используя:

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.

4 голосов
/ 06 декабря 2013

Парень из Oracle написал сообщение в блоге , в котором объясняется каждая часть журнала GC. Я нахожу это очень полезным.

Вот цитата из блога.

0,522: [пауза GC (молодой), 0,15877971 с]

Это информация самого высокого уровня, говорящая нам, что это Эвакуационная пауза, начавшаяся через 0,522 с после начала процесс, в котором все регионы, которые будут эвакуированы, являются молодыми, т.е. и выжившие регионы. Эта коллекция заняла 0,15877971 сек, чтобы закончить.

Эвакуационные паузы также могут быть смешаны. В этом случае набор выбранные регионы включают в себя все молодые регионы, а также некоторые старые регионы.

1,730: [пауза GC (смешанная), 0,32714353 с]

Давайте посмотрим на все подзадачи, выполняемые в этой эвакуации. Пауза.

[Параллельное время: 157,1 мс]

Параллельное время - это общее время, затраченное всеми параллельными GC. рабочие темы. Следующие строки соответствуют параллельным задачам выполняется этими рабочими потоками в это общее параллельное время, которое в этом случае 157,1 мсек.

[GC Worker Start (мс): 522,1 522,2 522,2 522,2 Avg: 522,2, мин: 522,1, Макс .: 522,2, разница: 0,1]

Первая строка сообщает нам время начала каждого рабочего потока в миллисекунды. Время начала упорядочено по отношению к работнику идентификаторы потока - поток 0 начался в 522.1ms и поток 1 начался в 522,2 мс с начала процесса. Вторая строка сообщает средним, минимальным, максимальным и разным временам начала всех рабочих потоков.

0 голосов
/ 28 сентября 2011

У меня есть инструмент (предварительная версия, но еще не OSS), который может пролить свет здесь.

Если вам интересно, напишите мне, и мы поговорим о том, как получитьлоги мне.

К комментариям к посту - я использовал G1 в нагрузках типа prod и видел хорошие цифры (не такие хорошие, как те, которые вы видите, но лучше, чем CMS для некоторыхнагрузки).

Не было сбоев в бета-версиях Java 7 (но некоторые встречались со сборками Java 6).

...