Le ramasse-miettes Java ConcurrentMarkSweep ne supprime pas toutes les ordures

Question

Forme courte :Le garbage collector du CMS semble échouer à collecter une quantité toujours croissante de déchets ;Finalement, notre JVM se remplit et l'application ne répond plus.Forcer un GC via un outil externe (JConsole ou jmap -histo:live) le nettoie une fois.

MISE À JOUR:Le problème semble être lié au plugin JTop pour JConsole ;si nous n'exécutons pas JConsole ou si nous l'exécutons sans le plugin JTop, le comportement disparaît.

(Notes techniques :nous exécutons Sun JDK 1.6.0_07, 32 bits, sur une machine Linux 2.6.9.La mise à niveau de la version JDK n'est pas vraiment une option, sauf en cas de raison majeure et inévitable.De plus, notre système n'est pas connecté à une machine accessible par Internet, donc les captures d'écran de JConsole, etc. ne sont pas une option.)

Nous exécutons actuellement notre JVM avec les indicateurs suivants :

-server -Xms3072m -Xmx3072m -XX:NewSize=512m -XX:MaxNewSize=512m 
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled 
-XX:CMSInitiatingOccupancyFraction=70 
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 
-XX:+DisableExplicitGC

En observant le graphique de la mémoire dans JConsole, il existe un GC complet qui s'exécute toutes les environ 15 minutes pendant les premières heures de la durée de vie de notre application ;après chaque GC complet, de plus en plus de mémoire est encore utilisée.Après quelques heures, le système atteint un état stable où il y a environ 2 Go de mémoire utilisée dans l'ancienne génération du CMS.

Ce qui ressemble à une fuite de mémoire classique, sauf que si nous utilisons un outil qui force un GC complet (en appuyant sur le bouton "collecter les déchets" dans JConsole ou en exécutant jmap -histo:live, etc.), l'ancienne génération tombe soudainement à environ 500 Mo utilisés, et notre application redevient réactive pendant les heures suivantes (pendant lesquelles le même schéma continue - après chaque GC complet, de plus en plus d'ancienne génération est pleine.)

Une chose à noter :dans JConsole, le nombre de GC ConcurrentMarkSweep signalé restera à 0 jusqu'à ce que nous forcions un GC avec jconsole/jmap/etc.

En utilisant jmap -histo et jmap -histo:live en séquence, je suis en mesure de déterminer que les objets apparemment non collectés sont constitués de :

• plusieurs millions HashMaps et tableaux de HashMap$Entry (dans un rapport 1:1)
• plusieurs millions Vectors et tableaux d'objets (rapport 1: 1, et à peu près le même que le nombre de HashMaps)
• plusieurs millions HashSet, Hashtable, et com.sun.jmx.remote.util.OrderClassLoaders, ainsi que des tableaux de Hashtable$Entry (environ le même nombre de chacun ;environ la moitié moins que les HashMaps et les vecteurs)

Vous trouverez ci-dessous quelques extraits des résultats du GC ;mon interprétation semble être que le GC CMS est abandonné sans basculer vers le GC stop-the-world.Est-ce que j'interprète mal cette sortie d'une manière ou d'une autre ?Y a-t-il quelque chose qui pourrait provoquer cela ?

Pendant l'exécution normale, les blocs de sortie du CMS GC ressemblent à ceci :

36301.827: [GC [1 CMS-initial-mark: 1856321K(2621330K)] 1879456K(3093312K), 1.7634200 secs] [Times: user=0.17 sys=0.00, real=0.18 secs]
36303.638: [CMS-concurrent-mark-start]
36314.903: [CMS-concurrent-mark: 7.804/11.264 secs] [Times: user=2.13 sys=0.06, real=1.13 secs]
36314.903: [CMS-concurrent-preclean-start]
36314.963: [CMS-concurrent-preclean: 0.037/0.060 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
36314.963: [CMS-concurrent-abortable-preclean-start]
36315.195: [GC 36315.195: [ParNew: 428092K->40832K(471872K), 1.1705760 secs] 2284414K->1897153K(3093312K), 1.1710560 secs] [Times: user=0.13 sys=0.02, real=0.12 secs]
CMS: abort preclean due to time 36320.059: [CMS-concurrent-abortable-preclean: 0.844/5.095 secs] [Times: user=0.74 sys=0.05, real=0.51 secs]
36320.062: [GC[YG occupancy: 146166 K (471872 K)]36320.062: [Rescan (parallel), 1.54078550 secs]36321.603: [weak refs processing, 0.0042640 secs] [1 CMS-remark: 1856321K(2621440K)] 2002488K(3093312K), 1.5456150 secs] [Times: user=0.18 sys=0.03, real=0.15 secs]
36321.608: [CMS-concurrent-sweep-start]
36324.650: [CMS-concurrent-sweep: 2.686/3.042 secs] [Times: uesr=0.66 sys=0.02, real=0.30 secs]
36324.651: [CMS-concurrent-reset-start]
36324.700: [CMS-concurrent-reset: 0.050/0.050 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

et c'est tout;la ligne suivante sera le prochain ParNew GC.

Lorsque nous forçons un GC en utilisant jmap -histo:live, nous obtenons à la place :

48004.088: [CMS-concurrent-mark: 8.012/8.647 secs] [Times: user=1.15 sys=0.02, real=0.87 secs]
(concurrent mode interrupted)

suivi de ~125 lignes du formulaire ci-dessous :(certains GeneratedMethodAccessor, certains GeneratedSerializationConstructorAccessor, certains GeneratedConstructorAccessor, etc.)

[Unloading class sun.reflect.GeneratedMethodAccessor3]

suivi de:

: 1911295K->562232K(2621440K), 15.6886180 secs] 2366440K->562232K(3093312K), [CMS Perm: 52729K->51864K(65536K)], 15.6892270 secs] [Times: user=1.55 sys=0.01, real=1.57 secs]

Merci d'avance!

Answer 1

com.sun.jmx.remote.util.OrderClassLoader est utilisé dans la couche distante pour JMX et un examen rapide du code suggère qu'ils sont créés dans le cadre du processus de démarshalling pour les requêtes distantes à l'intérieur de la JVM.La durée de vie de ces chargeurs de classe sera directement liée à la durée de vie de la chose qui n'a pas été organisée, de sorte qu'une fois qu'il n'y aura plus de référence à cette chose, le chargeur de classe pourra être publié.

Je ne serais pas surpris si, dans ce cas, la présence de ces instances était le résultat direct de votre utilisation de JConsole pour examiner ce qui se passe dans la JVM.Et il semble qu'ils seraient simplement nettoyés par GC dans le cadre d'un fonctionnement normal.

Je suppose qu'il est possible qu'il y ait un bogue dans l'implémentation de JMX (cela semble peu probable dans une JVM relativement à jour) ou peut-être avez-vous des MBeans personnalisés ou utilisez-vous des outils JMX personnalisés à l'origine du problème.Mais en fin de compte, je soupçonne que OrderClassLoader est probablement un faux-fuyant et que le problème réside ailleurs (GC cassé ou autre fuite).

Answer 2

  

Notes techniques: Nous sommes en cours d'exécution Sun JDK   1.6.0_07, 32 bits, sur une boîte Linux 2.6.9. Mise à niveau de la version JDK n'est pas   vraiment une option, à moins qu'il y est un   inévitable, principale raison.

Plusieurs versions plus récentes Java ont été mises à jour du garbage collector CMS. Notamment 6u12, 6u14 et 6u18.

Je ne suis pas un expert avec des trucs GC, mais je devine que les correctifs PRECLEAN dans 6u14 peut résoudre le problème que vous voyez. Bien sûr, je pourrais dire la même chose au sujet des bogues de déchargement de classe 6u18. Comme je l'ai dit, je ne suis pas un expert en substance GC.

Il existe des correctifs pour:

• 6u10: (affecte 6u4 +) CMS efface jamais quand -XX referents: + ParallelRefProcEnabled
• 6u12: CMS: codage incorrect des tableaux d'objets survolées au cours simultanée prélavage
• 6u12: CMS: manipulation de débordement incorrect lors de l'utilisation simultanée de marquage parallèle
• 6u14: CMS: échec d'assertion "== is_cms_thread Thread :: current () -> is_ConcurrentGC_thread ()"
• 6u14: CMS: Besoin CMSInitiatingPermOccupancyFraction pour perm, en instance de divorce de CMSInitiatingOccupancyFraction
• 6u14: CMS assert: _concurrent_iteration_safe_limit mise à jour manqué
• 6u14: CMS: manipulation incorrecte de débordement lors de prélavage des listes de référence
• 6u14: SIGSEGV ou (! Is_null (v), "valeur oop ne peut jamais être zéro") affirmation lors de l'exécution avec la CMS et COOP
• 6u14: CMS:. Livelock dans CompactibleFreeListSpace :: block_size ()
• 6u14: Faire du travail CMS compressé oops
• 6u18: CMS: core dump avec -XX: + UseCompressedOops
• 6u18: CMS: bugs liés à déchargement classe
• 6u18: CMS: ReduceInitialCardMarks non sécuritaire en présence de CMS prélavage
• 6u18: [régression] -XX: NewRatio avec -XX: + UseConcMarkSweepGC provoque une erreur fatale
• 6u20: marques de cartes peuvent être reportées trop long

En plus de tout ce qui précède, 6u14 a également introduit le G1 du garbage collector, bien qu'il soit encore en test. G1 est destiné à remplacer la CMS en Java 7.

G1 peut être utilisé dans Java 6u14 et plus récent avec la ligne de commande suivant commute:

-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC

Answer 3

Je voudrais commencer par quelque chose de beaucoup plus simple, comme:

-server -Xms3072m -Xmx3072m -XX:+UseParallelOldGC -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 

Et si cela répond à vos besoins.

Answer 4

On dirait que vous construisez des objets qui leur point de retour des propriétaires (A des points aux points B à A). Ce résultat dans les comptes de référence restant supérieur à zéro, de sorte que le garbage collector ne peut pas les nettoyer. Vous devez briser le cycle lorsque vous les relâchez. Réduire à néant la référence en A ou B résoudra le problème. Cela fonctionne même dans les regards de référence grands comme (A -> B -> C -> D -> A). Les vecteurs et les tableaux d'objets peuvent être utilisés par vos HashMaps.

Le presense des chargeurs à distance peut indiquer un défaut de nettoyage et de références à des objets proches chargés via JNDI ou toute autre méthode d'accès à distance.

EDIT: Je pris un second regard sur votre dernière ligne. Vous pouvez augmenter l'allocation permanente.