Recherche d'une fuite de mémoire ou d'un problème de collecte de déchets en Java.

Question

C'est un problème que j'essaie de résoudre depuis quelques mois maintenant. J'ai une application Java qui traite les flux xml et stocke le résultat dans une base de données. Cela a donné lieu à des problèmes de ressources intermittents qui sont très difficiles à localiser.

Le contexte : Sur la boîte de production (où le problème est le plus visible), je n'ai pas un accès particulièrement bon à la boîte, et j'ai été incapable de faire fonctionner Jprofile. Cette boîte est une machine 64bit quad-core, 8gb exécutant centos 5.2, tomcat6, et java 1.6.0.11. Elle démarre avec les options java suivantes

JAVA_OPTS="-server -Xmx5g -Xms4g -Xss256k -XX:MaxPermSize=256m -XX:+PrintGCDetails -
XX:+PrintGCTimeStamps -XX:+UseConcMarkSweepGC -XX:+PrintTenuringDistribution -XX:+UseParNewGC"

La pile technologique est la suivante :

• Centos 64 bits 5.2
• Java 6u11
• Tomcat 6
• Spring/WebMVC 2.5
• Hibernate 3
• Quartz 1.6.1
• DBCP 1.2.1
• Mysql 5.0.45
• Ehcache 1.5.0
• (et bien sûr une foule d'autres dépendances, notamment les bibliothèques jakarta-commons)

Le plus proche que je puisse faire pour reproduire le problème est une machine 32 bits avec des exigences de mémoire plus faibles. J'ai le contrôle là-dessus. Je l'ai sondé à mort avec JProfiler et j'ai corrigé de nombreux problèmes de performance (problèmes de synchronisation, précompilation/mise en cache des requêtes xpath, réduction du threadpool, suppression des pré-recherches hibernate inutiles et réchauffement excessif du cache pendant le traitement).

Dans chaque cas, le profileur a montré qu'ils consommaient d'énormes quantités de ressources pour une raison ou une autre, et qu'ils n'étaient plus les principaux consommateurs de ressources une fois les changements effectués.

Le problème : La JVM semble ignorer complètement les paramètres d'utilisation de la mémoire, remplit toute la mémoire et ne répond plus. C'est un problème pour le client, qui s'attend à un sondage régulier (5 minutes et 1 minute de relance), ainsi que pour nos équipes d'exploitation, qui sont constamment informées qu'une boîte ne répond plus et doivent la redémarrer. Il n'y a rien d'autre d'important qui fonctionne sur cette boîte.

Le problème apparaît pour être la collecte des ordures. Nous utilisons le collecteur ConcurrentMarkSweep (comme indiqué ci-dessus) parce que le collecteur STW d'origine provoquait des timeouts JDBC et devenait de plus en plus lent. Les journaux montrent qu'au fur et à mesure que l'utilisation de la mémoire augmente, le collecteur commence à générer des échecs cms et revient au collecteur original Stop-the-World, qui semble alors ne pas collecter correctement.

Cependant, lorsque j'utilise jprofiler, le bouton "Run GC" semble bien nettoyer la mémoire au lieu de montrer une empreinte croissante, mais comme je ne peux pas connecter jprofiler directement à la machine de production et que la résolution des points chauds ne semble pas fonctionner, il me reste à régler la Garbage Collection à l'aveugle.

Ce que j'ai essayé :

• Profiler et fixer les points chauds.
• Utilisation des collecteurs de déchets STW, Parallel et CMS.
• Exécution avec des tailles de tas min/max à 1/2, 2/4, 4/5, 6/6 incréments.
• Fonctionne avec de l'espace permgen par incréments de 256M jusqu'à 1Gb.
• De nombreuses combinaisons de ce qui précède.
• J'ai également consulté la JVM [tuning reference] (http://java.sun.com/javase/technologies/hotspot/gc/gc\_tuning\_6.html), mais je n'ai pas trouvé d'explication à ce comportement ni d'exemples de paramètres de réglage à utiliser dans une telle situation.
• J'ai également (sans succès) essayé jprofiler en mode hors ligne, en me connectant avec jconsole, visualvm, mais je n'arrive pas à trouver quelque chose qui permette d'intercepter les données de mon journal gc.

Malheureusement, le problème apparaît également de manière sporadique, il semble être imprévisible, il peut fonctionner pendant des jours ou même une semaine sans avoir de problèmes, ou il peut échouer 40 fois en une journée, et la seule chose que je peux attraper de manière constante est que la collecte des déchets est en train de se produire.

Quelqu'un peut-il donner des conseils sur :
a) Pourquoi une JVM utilise-t-elle 8 gigaoctets physiques et 2 gigaoctets d'espace de pagination alors qu'elle est configurée pour en utiliser moins de 6.
b) Une référence à l'accord GC qui explique réellement ou donne des exemples raisonnables de quand et avec quel type de réglage utiliser les collections avancées.
c) Une référence aux fuites de mémoire java les plus courantes (je comprends les références non réclamées, mais je veux dire au niveau de la bibliothèque/du cadre, ou quelque chose de plus inhérent aux structures de données, comme les hashmaps).

Merci pour toutes les informations que vous pourrez nous fournir.

EDIT
Emil H :
1) Oui, mon cluster de développement est un miroir des données de production, jusqu'au serveur média. La principale différence est le 32/64bit et la quantité de RAM disponible, que je ne peux pas reproduire très facilement, mais le code, les requêtes et les paramètres sont identiques.

2) Il y a un certain code hérité qui repose sur JaxB, mais en réorganisant les tâches pour essayer d'éviter les conflits de programmation, j'ai éliminé cette exécution en général puisqu'elle est exécutée une fois par jour. L'analyseur primaire utilise des requêtes XPath qui font appel au paquet java.xml.xpath. C'était la source de quelques problèmes, d'une part les requêtes n'étaient pas pré-compilées, et d'autre part les références à celles-ci étaient dans des chaînes codées en dur. J'ai créé un cache threadsafe (hashmap) et fait en sorte que les références aux requêtes xpath soient des chaînes statiques finales, ce qui a considérablement réduit la consommation de ressources. Les requêtes représentent toujours une grande partie du traitement, mais c'est normal car c'est la principale responsabilité de l'application.

3) Une note supplémentaire, l'autre consommateur principal est les opérations d'image de JAI (retraitement des images à partir d'un flux). Je ne suis pas familier avec les bibliothèques graphiques de Java, mais d'après ce que j'ai trouvé, elles ne sont pas particulièrement perméables.

(merci pour les réponses jusqu'à présent, les gens !)

UPDATE :
J'ai pu me connecter à l'instance de production avec VisualVM, mais il avait désactivé l'option de visualisation / exécution du GC (bien que je puisse le visualiser localement). La chose intéressante : l'allocation du tas de la VM obéit aux JAVA_OPTS, et le tas réellement alloué est confortablement installé à 1-1,5 giga, et ne semble pas fuir, mais la surveillance au niveau de la boîte montre toujours un modèle de fuite, mais il n'est pas reflété dans la surveillance de la VM. Il n'y a rien d'autre qui tourne sur cette boîte, donc je suis perplexe.

Answer 1

Eh bien, j'ai finalement trouvé le problème qui causait cela, et je poste une réponse détaillée au cas où quelqu'un d'autre aurait ces problèmes.

J'ai essayé jmap pendant que le processus se comportait mal, mais cela provoquait généralement un blocage supplémentaire de la jvm, et je devais l'exécuter avec --force. Il en résultait des vidages de tas qui semblaient manquer beaucoup de données, ou du moins manquer les références entre elles. Pour l'analyse, j'ai essayé jhat, qui présente beaucoup de données mais pas grand chose sur la manière de les interpréter. Ensuite, j'ai essayé l'outil d'analyse de la mémoire basé sur eclipse ( http://www.eclipse.org/mat/ ), qui a montré que le tas était principalement constitué de classes liées à tomcat.

Le problème était que jmap ne rapportait pas l'état réel de l'application, et ne capturait que les classes à l'arrêt, qui étaient principalement des classes tomcat.

J'ai essayé quelques fois de plus, et j'ai remarqué qu'il y avait un nombre très élevé d'objets modèles (en fait 2-3x plus que ce qui était marqué public dans la base de données).

Grâce à cela, j'ai analysé les journaux de requêtes lentes, et quelques problèmes de performance sans rapport. J'ai essayé le chargement extra-lazy ( http://docs.jboss.org/hibernate/core/3.3/reference/en/html/performance.html ), ainsi que le remplacement de quelques opérations hibernate par des requêtes jdbc directes (principalement lorsqu'il s'agissait de charger et d'opérer sur de grandes collections -- les remplacements jdbc ont juste travaillé directement sur les tables de jonction), et ont remplacé quelques autres requêtes inefficaces que mysql enregistrait.

Ces mesures ont permis d'améliorer les performances de l'interface, mais elles n'ont pas permis de résoudre le problème de la fuite : l'application était toujours instable et se comportait de manière imprévisible.

Finalement, j'ai trouvé l'option : -XX:+HeapDumpOnOutOfMemoryError . Cela a finalement produit un très gros (~6.5GB) fichier hprof qui montrait précisément l'état de l'application. Ironiquement, le fichier était si gros que jhat ne pouvait pas l'analyser, même sur une machine avec 16 Go de RAM. Heureusement, MAT a pu produire de jolis graphiques et montrer de meilleures données.

Cette fois-ci, ce qui m'a frappé, c'est qu'un seul fil quartz occupe 4,5 Go des 6 Go du tas, dont la majeure partie est constituée d'un StatefulPersistenceContext d'hibernation ( https://www.hibernate.org/hib%5Fdocs/v3/api/org/hibernate/engine/StatefulPersistenceContext.html ). Cette classe est utilisée par Hibernate en interne comme cache primaire (j'ai désactivé les caches de second niveau et de requête soutenus par EHCache).

Cette classe est utilisée pour activer la plupart des fonctionnalités d'Hibernate, elle ne peut donc pas être désactivée directement (vous pouvez la contourner directement, mais Spring ne supporte pas les sessions sans état), et je serais très surpris qu'elle ait une fuite de mémoire aussi importante dans un produit mature. Alors pourquoi y a-t-il une fuite maintenant ?

Eh bien, c'était une combinaison de choses : Le pool de threads de quartz s'instancie avec certaines choses étant threadLocal, spring injectait une session factory, qui créait une session au début du cycle de vie des threads de quartz, qui était ensuite réutilisée pour exécuter les différents jobs de quartz qui utilisaient la session hibernate. Hibernate mettait alors en cache la session, ce qui est son comportement attendu.

Le problème est que le pool de threads ne libère jamais la session, et qu'Hibernate reste résident et maintient le cache pendant le cycle de vie de la session. Puisque nous utilisions le support des modèles hibernate de Spring, il n'y avait pas d'utilisation explicite des sessions (nous utilisons une hiérarchie dao -> manager -> driver -> quartz-job, le dao est injecté avec les configurations hibernate par Spring, donc les opérations sont faites directement sur les modèles).

Ainsi, la session n'était jamais fermée, Hibernate maintenait des références aux objets du cache, de sorte qu'ils n'étaient jamais ramassés, et chaque fois qu'un nouveau travail s'exécutait, il continuait à remplir le cache local du thread, de sorte qu'il n'y avait même pas de partage entre les différents travaux. De plus, comme il s'agit d'un travail à forte intensité d'écriture (très peu de lecture), le cache était principalement gaspillé, de sorte que les objets continuaient à être créés.

La solution : créer une méthode dao qui appelle explicitement session.flush() et session.clear(), et invoquer cette méthode au début de chaque tâche.

L'application fonctionne depuis quelques jours maintenant sans problème de surveillance, d'erreurs de mémoire ou de redémarrage.

Merci pour l'aide de tout le monde sur ce sujet, c'était un bug assez délicat à traquer, car tout faisait exactement ce qu'il était censé faire, mais à la fin une méthode en 3 lignes a réussi à résoudre tous les problèmes.

Answer 2

Pouvez-vous exécuter la boîte de production avec JMX activé ?

-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.port=<port>
...

Surveillance et gestion à l'aide de JMX

Et ensuite attacher avec JConsole, VisualVM ?

Est-il possible de faire un vidage de tas avec jmap ?

Si oui, vous pouvez alors analyser le vidage du tas à la recherche de fuites avec JProfiler (vous l'avez déjà fait), jhat VisualVM, Eclipse MAT . Comparez également les vidages de tas qui pourraient vous aider à trouver des fuites ou des modèles.

Et comme vous l'avez mentionné, jakarta-commons. Il y a un problème lors de l'utilisation de jakarta-commons-logging lié à la rétention du classloader. Pour une bonne lecture sur ce sujet, consultez

Une journée dans la vie d'un chasseur de fuites de mémoire ( release(Classloader) )

Answer 3

Il semble que la mémoire autre que le tas fuit, vous mentionnez que le tas reste stable. Un candidat classique est le permgen (génération permanente) qui consiste en 2 choses : les objets de classe chargés et les chaînes internées. Puisque vous avez déclaré vous être connecté à VisualVM, vous devriez être en mesure de voir la quantité de classes chargées, s'il y a une augmentation continue du nombre d'objets de classe. chargé classes (important, visualvm montre aussi le nombre total de classes chargées, il n'y a pas de problème si cela augmente mais le nombre de classes chargées doit se stabiliser après un certain temps).

S'il s'avère qu'il s'agit d'une fuite permgen, alors le débogage devient plus délicat car les outils d'analyse permgen sont plutôt absents par rapport au heap. Votre meilleure chance est de lancer un petit script sur le serveur qui invoque de manière répétée (toutes les heures ?) :

jmap -permstat <pid> > somefile<timestamp>.txt

jmap avec ce paramètre générera un aperçu des classes chargées avec une estimation de leur taille en octets, ce rapport peut vous aider à identifier si certaines classes ne sont pas déchargées. (note : avec je veux dire l'id du processus et devrait être un timestamp généré pour distinguer les fichiers)

Une fois que vous avez identifié certaines classes comme étant chargées et non déchargées, vous pouvez déterminer mentalement où elles peuvent être générées, sinon vous pouvez utiliser jhat pour analyser les dumps générés avec jmap -dump. Je garde cela pour une prochaine mise à jour si vous avez besoin de cette info.

Answer 4

Je chercherais un ByteBuffer directement alloué.

Extrait de la javadoc.

Un tampon d'octet direct peut être créé en invoquant la méthode d'usine allocateDirect de cette classe. Les tampons renvoyés par cette méthode ont généralement des coûts d'allocation et de désallocation un peu plus élevés que les tampons non directs. Le contenu des tampons directs peut résider en dehors du tas normal de déchets, et leur impact sur l'empreinte mémoire d'une application peut donc ne pas être évident. Il est donc recommandé d'allouer les tampons directs principalement pour les tampons volumineux et à longue durée de vie qui sont soumis aux opérations d'E/S natives du système sous-jacent. En général, il est préférable d'allouer des tampons directs uniquement lorsqu'ils apportent un gain mesurable en termes de performances du programme.

Il se peut que le code Tomcat l'utilise pour les E/S ; configurez Tomcat pour qu'il utilise un connecteur différent.

Sinon, vous pourriez avoir un thread qui exécute périodiquement System.gc(). "-XX:+ExplicitGCInvokesConcurrent" pourrait être une option intéressante à essayer.

Answer 5

Des JAXB ? Je trouve que JAXB permet de remplir l'espace en permanence.

Aussi, je trouve que visualgc qui est maintenant livré avec le JDK 6, est un excellent moyen de voir ce qui se passe en mémoire. Il montre les espaces eden, générationnel et perm, ainsi que le comportement transitoire du GC, de façon magnifique. Tout ce dont vous avez besoin est le PID du processus. Peut-être que cela vous aidera pendant que vous travaillez sur JProfile.

Et qu'en est-il des aspects de traçage/journalisation de Spring ? Vous pouvez peut-être écrire un aspect simple, l'appliquer de manière déclarative et créer ainsi un profileur du pauvre.