java garbage-collection g1gc

java - ¿Alguien puede dar sentido a la salida del recolector de basura G1?



garbage-collection g1gc (3)

Renuncia

De ninguna manera estoy bien versado en Garbage-First Garbage Collector y esta pregunta me inspiró a echarle un vistazo por primera vez. Existe la posibilidad de que me equivoque con parte de mi información.

Introducción

Para obtener más información sobre el recolector de basura de Garbage-First (G1GC), el papel de recolección de basura de Garbage-First ( here , here , here y here ) es un recurso invaluable. Puedes encontrar una introducción al G1GC here . El Glosario de HotSpot es útil para comprender los términos de JVM. Los siguientes documentos también fueron útiles para comprender mejor la recolección de basura:

  • Una mirada dura a la recolección de basura dura en tiempo real : here y here
  • Recolección de basura sin bloqueo para multiprocesadores : here y here
  • Exploración de raíz sin bloqueo para la recolección de basura en tiempo real : here
  • Copia de objetos sin bloqueo para la recolección de basura en tiempo real : here y here

Con estos recursos y una build debug OpenJDK 7, puede comenzar a entender el registro G1GC.

Definiciones

Usando los documentos y las páginas web mencionadas anteriormente, aquí hay algunas definiciones útiles de los términos que surgieron con mayor frecuencia:

  • marcado concurrente : Ambos proporcionan la "integridad" de la colección e identifican las regiones que están listas para la recuperación mediante la evacuación por compactación. Proporciona información completa sobre el colector sin imponer ningún orden en la elección de región para los conjuntos de colecciones. Proporciona la información de datos en vivo que permite que las regiones se recopilen en el orden de "basura en primer lugar".
  • montón : el área de memoria utilizada por la JVM para la asignación de memoria dinámica.
  • región de pila : la pila se divide en un conjunto de regiones de pila de igual tamaño. La pila de Garbage-First se divide en regiones de pila de igual tamaño, cada una de ellas un rango contiguo de memoria virtual.
  • Marcar mapa de bits : contiene un bit para cada dirección que puede ser el inicio de un objeto.
  • conjunto recordado : una estructura de datos que indica ubicaciones de montón fuera de la región que pueden contener punteros a objetos en la región. Cada región tiene un conjunto recordado asociado, que indica todas las ubicaciones que pueden contener punteros a objetos (vivos) dentro de la región. Garbage-First Recordary establece punteros de registro de todas las regiones (con algunas excepciones). Un buffer actual o secuencia de cartas modificadas. Una estructura de datos que registra los punteros entre generaciones.
  • conjunto raíz : un conjunto de objetos que se sabe que son accesibles directamente. Las ubicaciones desde donde todos los objetos vivos son accesibles.

Código fuente

Para comprender mejor el registro de G1GC, usé los siguientes archivos de source de OpenJDK 7:

  • punto de acceso / src / share / vm / gc_implementation / g1 / concurrentMarkThread.cpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / concurrentMark.cpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / concurrentMark.hpp
  • hotspot / src / share / vm / gc_implementation / g1 / g1_specialized_oop_closures.hpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / g1CollectedHeap.cpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / g1CollectedHeap.hpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / g1CollectorPolicy.cpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / g1CollectorPolicy.hpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / g1OopClosures.hpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / g1OopClosures.inline.hpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / g1RemSet.cpp
  • punto de acceso / src / share / vm / memory / sharedHeap.cpp
  • punto de acceso / src / share / vm / memory / sharedHeap.hpp
  • hotspot / src / share / vm / utilities / taskqueue.hpp
  • hotspot / src / share / vm / runtime / timer.cpp
  • hotspot / src / share / vm / runtime / timer.hpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / vm_operations_g1.cpp
  • punto de acceso / src / share / vm / gc_implementation / g1 / vm_operations_g1.hpp

Análisis de registro

A continuación se muestra una copia anotada del registro G1GC en cuestión.

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

Si puede crear una debug de debug de OpenJDK 7, tendrá algunas opciones de JVM más disponibles que le brindarán aún más información sobre G1GC. Use el siguiente comando para obtener una lista de todas las opciones de JVM:

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

La salida muestra las siguientes opciones de G1GC disponibles; Esta no es una lista exhaustiva, solo algunas que pensé que se estaban intercalando.

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.

Para ver qué tipo de información G1GC se proporciona utilizando la compilación de depuración OpenJDK 7, usé el siguiente programa de prueba:

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(); } } }

Y lo ejecutamos usando:

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

El resultado fue muy detallado, pero proporciona una gran cantidad de información que podría resultar útil si está realizando un ajuste de GC.

Estoy ejecutando un programa Java con el recolector de basura G1 usando las siguientes opciones:

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

La salida se ve así ...

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]

¿Alguien puede dar sentido a lo que está pasando?

Tengo una herramienta (versión preliminar, aún no OSS) que puede arrojar algo de luz aquí.

Si está interesado, envíeme un correo electrónico y podremos hablar sobre cómo obtener los registros para mí.

A los comentarios en la publicación: he utilizado G1 en cargas tipo prodigio y he visto algunos números buenos (no tan buenos como los que está viendo, pero mejores que CMS para algunas cargas).

No he visto ningún bloqueo de las 7 betas de Java (pero sí algunas con compilaciones de Java 6).

Un tipo de Oracle escribió una publicación de blog que explica cada parte del registro de GC. Lo encontré muy útil.

Aquí hay una cita del blog.

0.522: [Pausa GC (joven), 0.15877971 segundos]

Esta es la información de más alto nivel que nos indica que se trata de una Pausa de Evacuación que comenzó a los 0.522 segundos desde el inicio del proceso, en la que todas las regiones que están siendo evacuadas son Young, es decir, Eden y Survivor. Esta colección tomó 0.15877971 segundos para terminar.

Las pausas de evacuación también se pueden mezclar. En cuyo caso, el conjunto de regiones seleccionadas incluye todas las regiones jóvenes, así como algunas regiones antiguas.

1.730: [Pausa GC (mixta), 0.32714353 seg.]

Echemos un vistazo a todas las sub-tareas realizadas en esta pausa de evacuación.

[Tiempo paralelo: 157.1 ms]

Tiempo paralelo es el tiempo total transcurrido que pasan todos los subprocesos de trabajo de GC en paralelo. Las siguientes líneas corresponden a las tareas paralelas realizadas por estos subprocesos de trabajo en este tiempo paralelo total, que en este caso es 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]

La primera línea nos dice la hora de inicio de cada uno de los subprocesos de trabajo en milisegundos. Los tiempos de inicio se ordenan con respecto a los ID de subproceso de trabajo: el subproceso 0 comenzó a 522.1ms y el subproceso 1 comenzó a 522.2ms desde el inicio del proceso. La segunda línea le indica a Avg, Min, Max y Diff los tiempos de inicio de todos los subprocesos de trabajo.