Posts Tagged ‘performance’
By:
Il était une fois les expressions régulières
Depuis bien longtemps je connais et pratique les expressions régulières, à la fois au moment de coder, mais également dans mes éditeurs de texte, parfois aussi dans le shell, lors d’un grep par exemple. Bref les expressions régulières sont pratiques dans la vie de tous les jours pour un ingénieur logiciel.
Seulement voilà je me suis aussi rendu compte que certains d’entre nous n’ont pas une connaissance approfondie des expressions régulières et de leurs arcanes. Effectivement il y a parfois certaines expressions qui sont assez absconses. Et aujourd’hui les moteurs des expressions régulières dépassent ce le cadre dans lequel ces expressions ont été conçue. Elle permettent certaines constructions qui sont peu connues.
Les expressions régulières hier et aujourd’hui
Sans remonter aux origines des expressions régulières -cette partie là est couverte par wikipedia- il est intéressant de noter que les expressions régulières et leur moteur ont bien évoluées en 60ans. En effet le mot régulier vient de l’état de fait que ces expressions permettaient de rechercher dans des langages formels et non-contextuel; aujourd’hui les recherches ont avancées et les moteurs permettent maintenant de dépasser le cadre du langage formel pour permettre de travailler dans l’espace du langage contextuel. Les racines des expressions régulières remontent bien avant l’avènement de l’informatique pour aller jusqu’aux raisonnements complexes de la logique mathématique.
Il y a une une grosse différence entre un langage non-contextuel et un lange contextuel, dans les faits cette évolution explique pourquoi il y a aujourd’hui des différences dans les moteurs qui sont intégrés dans les différents programmes (en fonction de la plateforme, des outils, du langages etc.) Aujourd’hui en Perl, en C#, et en Java nous avons la chance d’avoir des moteurs qui font partie des dernières générations. C’est sur cet héritage que je vais disserter, cela dit uniquement dans le cadre de Java et de sa fameuse classe Pattern. (Vous remarquerez d’ailleurs que le moteur est nommé Pattern plutôt que Regex ou quelque chose du genre, l’explication est simple : cette génération de moteur n’est plus simplement à propos d’expression régulière mais donc de pattern.) Je tiens aussi à préciser que cet article se concentre sur la création d’expressions régulières et non sur l’usage de la classe Pattern.
Les différentes constructions
Petit rappel
Je passe rapidement sur les bases, j’imagine que tout le monde connaît les constructions basiques d’une expression régulière :
- Les classes de caractère [ ] et les compléments [^ ]
- L’opérateur de Kleene *
- L’alternative | (le pipe)
- Les autres quantificateurs : +, ?, {}, ces quantificateurs ne sont vraiment que des raccourcis de ce qui est déjà exprimable avec les autres constructions, mais ils nous simplifient la vie.
- Les groupes ()
Globalement pas de surprises ici, avec ses constructions il assez facile d’écrire l’expression la plus simple jusqu’à l’expression un poil plus élaborée.
Par exemple pour valider un mail (sans rentrer dans les arcanes de la RFC) on peut avoir ça:
@Test
public void simpleEmailMatch() {
String regex = "[a-z]+(\.[a-z]+)*@[a-z]+\.[a-z]{2,6}";
assertTrue(Pattern.compile(regex).matcher("brice.dutheil@gmail.com").matches());
}
Ok, c’est déjà pas mal, mais si on veut extraire une section d’un texte ou valider précisément certaines sections d’un texte, il faut connaitre les constructions un peu plus pointues.
Les ancres
Les ancres sont rangées dans la javadoc de la classe Pattern sous la catégorie Boundary matchers. Une ancre identifie juste une position à laquelle elle matche, elle ne consomme pas de caractères dans la séquence traitée.
Le début et la fin d’une ligne
Généralement les personnes qui ont beaucoup travaillé avec le shell connaissent les deux principales ancres, à savoir le début d’une ligne ^ et la fin d’une ligne $. Mais il y a une astuce en Java, c’est que par défaut ^ et $ repèrent le début et la fin du CharSequence uniquement, pas de notion de saut de ligne!
Pour s’en convaincre on écrit un petit test simple qu’on enrichira d’assertions, la méthode regexFirstMatch extrait la première section du texte qui matche la regex :
@Test
public void startEndOfLineVsPermanentStartEndOfString() {
String text = "The account number is :n" +
"t123456789n" +
"the client phone number is :n" +
"t0-987-654-321n";
assertEquals("T", regexFirstMatch(text, "^.")); // Tout le temps le début de la séquence
assertEquals("1", regexFirstMatch(text, ".$")); // Tout le temps la fin de la séquence
}
private String regexFirstMatch(String text, String regex) {
Matcher matcher = Pattern.compile(regex).matcher(text);
return matcher.find() ? matcher.group(0) : "";
}
Et ouai, on ne s’attend pas à ça (matche T et 1) surtout quand la description de ces ancres utilise le mot ligne. En fait il faut activer l’option multiligne Pattern.MULTILINE dans le moteur, pour que celui-ci identifie les sauts de ligne.
Ainsi dans le contexte du bout de code du dessus, les lignes suivantes permettent de voire qu’il s’agit bien du caractère ‘:’ de la première ligne qui est trouvé.
Matcher matcher = Pattern.compile(".$", Pattern.MULTILINE).matcher(text);
matcher.find();
assertEquals(":", matcher.group(0));
Nice, mais il y a encore mieux, le moteur de regex de Java (comme certains autres) permet de donner les options à l’intérieur de la regex, la javadoc de Pattern donne cette info dans la catégorie Special constructs (non-capturing), celle qui nous intéresse est la construction sur les options pour toute l’expression.
- (?idmsux-idmsux) Nothing, but turns match flags on – off
Il faut le placer au début de l’expression régulière, ici (?m) :
assertEquals(":", regexFirstMatch(text, "(?m).$"));
On choppe alors bien le caractère à la fin de la première ligne.
Le début et la fin d’une séquence de caractères
Dans notre expression si on veut se caler dans tous les cas sur le début et la fin d’une séquence de caractères, il y a des ancres dédiées A et Z. Celles-ci ne sont bien entendu pas affectées par l’option multiligne.
assertEquals("T", regexFirstMatch(text, "\A.")); // Tout le temps le début de la séquence
assertEquals("1", regexFirstMatch(text, ".\Z")); // Tout le temps la fin de la séquence
assertEquals("1", regexFirstMatch(text, "(?m).\Z")); // Tout le temps la fin de la séquence
Notez quand même qu’en ce qui concerne le Z le dernier caractère de la séquence qui est un séparateur de ligne n’est pas retourné! Comme indiqué dans la javadoc, cette ancre repère la position avant le dernier caractère séparateur (écrit comme terminators dans la javadoc).
Il existe d’autres ancres, mais elles sont moins utiles, je vous laisse voir par vous même.
Les options
On a vu qu’on pouvait activer des options pour une expression régulière, effectivement c’est assez pratique.
Les options possibles utilisables à la construction ou dans le pattern sont dans la javadoc, mais les plus intéressantes sont :
| Option | Flag | Flag à la construction |
| Multi-ligne | m | Pattern.MULTILINE |
| Insensibilité à la casse | i | Pattern.CASE_INSENSITIVE |
| Matching de la casse relatif aux règles Unicode | u | Pattern.UNICODE_CASE |
| Matching des caractère en fonction de leur forme canonique | Pattern.CANON_EQ |
Certaines options comme vu dans le tableau n’ont pas d’équivalence dans la regex.
Bon c’est bien pratique ça, mais parfois on aimerait bien s’assurer que la casse est ou n’est pas vérifiée sur une portion de la regex. Il existe une construction qui permet d’activer/désactiver une option dans une section de l’expression régulière :
- (?idmsux-idmsux:X) X, as a non-capturing group with the given flags on – off
A peu près la même chose que pour les options avec une portée sur toute la regex, sauf que cette fois, la portion soumise à l’option changée est à l’intérieur d’un groupe. Et là vous remarquerez que la javadoc dit bien “non-capturing” ça veut dire que la regex ne gardera pas en mémoire le contenu de ce groupe, contrairement aux groupes qui, donc, capturent et sont identifiables par l’encadrement du groupe par des parenthèses (X).
Ainsi par exemple si on ne veut pas tenir compte de la casse dans une portion de la regex on écrirait:
assertFalse(Pattern.compile("(?-i)[a-z]+ [a-z]+ [a-z]+").matcher("jqsdfkjkd fdfhJGJKGFQSDKjb ckbvg").matches());
assertTrue(Pattern.compile("(?-i)[a-z]+ (?i:[a-z]+) [a-z]+").matcher("jqsdfkjkd fdfhJGJKGFQSDKjb ckbvg").matches());
Dans la première expression, qui ne marche pas, l’ensemble de l’expression est sensible à la casse c’est l’option (?-i) en début d’expression. Mais au milieu on voudrait quand même autoriser les majuscules. Pour ce faire on active l’insensibilité uniquement pour le groupe du milieu (?i:[a-z]+).
Les bornes de mot
Les bornes de mots sont des ancres de type particulier. Comme n’importe quelle ancre, ces bornes ne consomment aucun caractère. La borne b s’utilise avant ou après un mot pour marquer le début ou la fin d’un mot.
Par exemple en utilisant la classe de caractère w.
assertTrue("word".matches("\bword"));
assertTrue("word".matches("word\b"));
assertTrue("word".matches("\bword\b"));
assertTrue("word".matches("\b\w+\b"));
assertTrue("12dsk_".matches("\b\w+\b"));
assertTrue("12dsk; fdg987".matches("\w+\b.*\b\w+"));
assertFalse("12dsk; ;:!,:".matches("\w+\b.*\b\w+"));
assertTrue(Pattern.compile("\bes\b").matcher("Tu es encore dans ces histoires ").find());
assertFalse(Pattern.compile("\bes\b").matcher("Tu as encore des histoires ").find());
assertFalse("12dsk-".matches("\w+"));
assertFalse("12dsk-".matches("\w+-\b"));
assertTrue("12dsk-".matches("[0-9a-z-]+"));
assertFalse("12dsk-".matches("[0-9a-z-]+\b"));
assertFalse("12dsk. ".matches("\w+.\b."));
assertFalse("bobEtLéa".matches("bob\b\w+\bLéa"));
Bon c’est bien cool, mais si je veux matcher un texte en allemand, du grec ou simplement des lettres accentuées de notre bon français ? Là ça pèche un peu si on utilise le w.
assertFalse("Éole".matches("\b\w+"));
assertTrue("Éole".matches("\bÉole"));
assertTrue("Éole".matches("\b[Éa-z]+"));
assertTrue("Éole".matches("\b\p{L}+"));
En effet la classe w ne connait que les caractères ASCII et plus précisément; uniquement ceux de cette classe [a-zA-Z0-9_] tel que c’est mentionné dans la javadoc. Pour palier à cette limitation soit il faut ajouter le caractère accentué à une classe de caractère, soit on utilise une classe de caractère Unicode, c’est ce qui est fait dans la dernière assertion j’utilise p{L} ! Je reviendrais plus tard sur Unicode avec les expressions régulières.
Attention à l’encodage de vos codes source ! J’ai eu des erreurs d’encodage du fichier sur Eclipse, IntelliJ et NetBeans qui provenaient de plateformes différentes (MacOSX et Windows), du coup le caractère É n’était pas bien encodé (comprendre que l’IDE encodait ce caractère dans autre chose qu’une lettre), ce qui faisait évidement échouer l’expression.
Enfin le complément d’une borne b est représenté par la borne B, celle-ci matche tout ce que b ne matche pas. Dans les faits B marque la borne entre deux classes de caractères à l’exception d’une classe composée des caractères qu’on peut trouvé dans w.
assertTrue("12dsk-".matches("\w+-\B")); // B capture l'inverse b
assertTrue("12dsk.".matches("\w+\.\B"));
assertTrue(".!? nt".matches("[.!?]+\B\s+"));
assertTrue(".!?,,,;:".matches("[.!?]+\B[,;:]+"));
Fin de la partie 1
Voilà pour la première partie, la plus simple, sur les expressions régulières en Java. Pour la suite qui arrive très bientôt j’exposerai la manière de fonctionner de certaines constructions un peu particulières : les backreferences, les quantificateurs possessifs, les possibilités de lookahead / lookbehind.
Références
By:
Sujet intéressant, les problèmes en production sont quand même pour beaucoup des casse-têtes. Effectivement c’est bien vrai, les problèmes en production sont difficiles à résoudre. Il y a bien une partie technique souvent absconse, mais ce n’est pas un travail en solitaire, c’est un travail d’équipe. L’organisation dans la boite favorise ou freine cette opportunité de résoudre un problème à travers les différentes équipe impliquées. Dans ce billet je vous fait un petit retour d’expérience sur un problème de lenteur sur une application web genre “CRUD” sur une JVM IBM.
Le contexte
“The context is King” disait Andy Hunt dans son livre Pragmatic Learning and Thinking. Alors brève introduction au contexte du problème.
- Application assez simple qui permet de rechercher, consulter, créer, modifier des données différentes issues du domaine métier.
- L’application tourne sur un WebSphere.
- WebSphere tourne sur une JVM IBM. Ah là ça sent la pêche aux informations, n’ayant jamais travaillé sur cette JVM, et pas de bol non plus la JVM IBM sur Windows n’est pas accessible gratuitement depuis le site de IBM.
- L’ensemble tourne sur une machine AIX.
- L’entreprise utilise l’outils Introscope qui permet d’avoir plein de métriques.
Le problème
Les utilisateurs ressentent des lenteurs, voire des freezes. L’outil INSC identifie ces threads en Stalled, et permet de donner des métriques sur les temps d’attentes et de réponses de certains éléments du systèmes, les ingénieurs systèmes utilisent abondamment cet outils. Bref, les temps de réponses vont de quelques dizaines de secondes à plusieurs minutes.
Il y a définitivement un problème. Forcément quand on a un super outils comme INSC qui a plein de métriques, on se balade dedans pour essayer de trouver le problème. Malheureusement un seul thread dump pour voir ce qu’il se passe dans les threads ne suffit pas. Le thread dump révèle que la plupart des threads sont à l’état “Waiting On Condition“. Le super outils INSC indique un usage de la heap, il indique aussi que certaines requêtes SQL sont très très longues, il indique les sessions web ouvertes une petite trentaine, pas de quoi fouetter un chat. Et pourtant il y aurait du CPU assez fortement utilisé, vu depuis Introscope.
Mais voilà l’analyse tourne un peu autour du pot. Pourquoi ces threads sont-elles bloquées? Pourquoi les requêtes SQL sont-elles aussi longues?!
Le problème dans l’analyse
Récapitulons, dans cette situation les métriques de Introscope ont été regardées, et on a un seul thread dump.
Introscope malgré ces métriques ne dit pas ou est le problème, il ne dit même pas quel est le type de problème. Les métriques affichées sont pour certaines intéressantes, je pense à l’identification des threads figées, les temps de réponses de certains composants, la consommation mémoire, et l’utilisation du CPU.
Mais pourquoi cet outils n’a pas aidé à trouver le problème, parce qu’il ne mesure pas les bonnes choses. Et il faut en particulier comprendre que quand un système fonctionne mal il y a un effet de corrélation qui s’applique sur un ensemble de variable. Et ce n’est pas avec Introscope qu’on va pouvoir identifier la cause du ralentissement généralisé, ni trouver une relation de cause-à-effet.
Pour résoudre un problème, il faut s’équiper avec les bons outils! Il faut aussi regarder les bonnes données, au bon endroit, et au bon moment!
A la poursuite du vrai problème (partie 1)
Bon hop, déjà pour commencer j’écarte pour le moment Introscope. Et j’ai un thread dump … de la JVM de IBM, il va falloir essayer les outils IBM qui permettent de traiter ces informations. Je vais me satisfaire ça pour l’instant.
L’analyse du thread dump
Avec : IBM Thread and Monitor Dump Analyzer for Java
Évidement le format ne correspond pas à celui de Sun, heureusement IBM nous fournit des outils pour analyser ces informations. Direction http://www.alphaworks.ibm.com/tech/jca.
A l’ouverture un rapport apparait, il commence par ça en rouge :
***WARNING*** Java heap is almost exhausted : 0% free Java heap Please enable verbosegc trace and use IBM Pattern Modeling and Analysis Tool(http://www.alphaworks.ibm.com/tech/pmat) to analyze garbage collection activities. If heapdumps are generated at the same time, please use IBM HeapAnalyzer(http://www.alphaworks.ibm.com/tech/heapanalyzer) to analyze Java heap.
Ok, là c’est assez facile de savoir ou ça va! Mais allons plus loin!
Il y a également :
Number of Processors : 4
Java version : J2RE 5.0 IBM J9 2.3 AIX ppc64-64 build j9vmap6423-20090707Java Heap Information
Maximum Java heap size : 384m
Initial Java heap size : 384m
OK, j’en apprends un peu plus sur la JVM et la machine.
Free Java heap size: 0 bytes
Allocated Java heap size: 402 653 184 bytes
Ok évidement tout s’explique il ne reste plus rien pour allouer dans la Heap.
Tiens dans la ligne de commande je voit que Introscope est un agent de le JVM:
-Xshareclasses:name=webspherev61_%g,groupAccess,nonFatal -Dibm.websphere.internalClassAccessMode=allow -Dcom.wily.introscope.agentProfile=/opt/wily/wilyAgent/AvtAgent.profile -javaagent:/opt/wily/wilyAgent/Agent.jar
C’est intéressant, si la JVM est lente, ca peut vouloir dire que les mesures Introscope sont aussi soumises aux lenteurs de la JVM.
Le rapport est sympa, il donne la répartition de la mémoire de la JVM :
Memory Segment Analysis
Memory Type # of Segments Used Memory(bytes) Used Memory(%) Free Memory(bytes) Free Memory(%) Total Memory(bytes) Internal 13 1 191 740 88,4 156 452 11,6 1 348 192 Object (reversed) 1 402 653 184 100 0 0 402 653 184 Class 9 735 228 637 344 90,96 22 724 116 9,04 251 361 460 JIT Code Cache 5 41 943 040 100 0 0 41 943 040 JIT Data Cache 3 17 018 496 67,63 8 147 328 32,37 25 165 824 Overall 9 757 691 443 804 95,71 31 027 896 4,29 722 471 700
Ok, c’était un tableau intéressant, on voit clairement que dans une JVM il n’y a pas que de la Heap (pour ceux qui ne le savait pas), en effet on voit donc les sections suivantes (les passages surlignés viennent de moi, malheureusement l’outil d’IBM ne nous aide pas là dessus) :
- la mémoire interne de la JVM (les objets internes, les structure de thread, et autres objets natifs) : bonne utilisation
- les objets, en une seule section de mémoire, c’est la Heap, et là ben effectivement elle utilisée à 100%.
- les sections des classes, c’est la ou le byte code de vos classes est stocké par la JVM, mais ce n’est pas dans la Heap (chez la JVM de Sun ça correspondrait à la PermGen area), bref là aussi 90% d’utilisation c’est plutôt pas mal.
- JIT Code Cache et JIT Data Cache, c’est là ou la JVM va stocker le code natif qu’elle aura compilée depuis le bytecode, là aussi c’est rempli à100% mais c’est peut-être normal, après tout la taille totale est plus petite.
On voit aussi que la mémoire accessible dans la Heap est quand même supérieure a ce qui est indiqué dans la ligne de commande, à savoir les 384 MB. Ne connaissant pas la JVM IBM, je ne suis pas certains des raisons induisant ce phénomène.
Mais à 100% d’utilisation, ça sent le GC qui s’excite pour garder ses petits. Mais le rapport est long et n’est pas terminé, il reste des choses à lire.
Thread Status Analysis
Status Number of Threads : 170 Percentage Deadlock 0 0 % Runnable 12 7 % Waiting on Condition 158 93 % Waiting On Monitor 0 0 % Suspended 0 0 % Object.wait() 0 0 % Blocked 0 0 % Parked 0 0 %
Vous vous souvenez des threads vues en Wait on Condition au tout début, on les retrouve donc ici dans les stats du thread dump. Il y a environ 158 thread qui ne font rien et 12 threads qui travaillent. Alors petite parenthèse, qu’est ce que ça veut dire ce Waiting on Condition. Les raisons peuvent être les suivantes :
- Thread.sleep(), en gros on indique simplement à la thread de ne rien faire, mais c’est quand même la JVM qui gère ce sleep()
- Object.wait(), en gros quelque part dans le code un thread est en attente pour qu’une condition se réalise, voire le code en question pour en savoir plus sur la condition. Cette condition peut aussi être une condition interne à la JVM.
- La thread est en train de se synchroniser avec une autre, elle doit donc attendre que l’autre thread finisse son job, on verra probablement dans la stack un appel à un Thread.join().
- Unsafe.park, et autres support pour les lock
- La thread est blockée par des opérations d’I/O.
Déjà ce n’est pas forcément un problème pour toutes les threads, typiquement on peut s’attendre à voir des threads relatives aux systèmes de cache (ehcache et consorts) qui sont dans ces états. Ensuite il faut comprendre que ce mécanisme implique des conditions internes à la JVM. L’ordonnanceur (scheduler) de la JVM, qui en réalité fait appel au scheduler de l’OS, donne la main à d’autres traitements (java ou pas).
Le prochain tableau du rapport nous indique ou sont (toutes) nos threads, mais pas d’analyse par type de statut. On observe bien certaines des raisons citées plus haut.
Thread Method Analysis
Method Name Number of Threads : 170 Percentage java/lang/Object.wait(Native Method) 88 52 % java/lang/Thread.sleep(Native Method) 63 37% NO JAVA STACK 6 4 % java/net/PlainSocketImpl.socketAccept(Native Method) 5 3 % java/net/SocketInputStream.socketRead0(Native Method) 3 2 % com/ibm/misc/SignalDispatcher.waitForSignal(Native Method) 1 1 % d’autres ligne à 1%…
Pas mal de thread sont en attente, et beaucoup d’autres dorment. Quelques threads sans stack Java, ce sont des threads qui appartiennent à la JVM.
J’arrête là pour le moment sur le rapport de cet outils IBM, mais ce qu’il faut retenir c’est que le thread dump est utile pour étudier des threads, mais c’est utile sur un laps de temps, avec un seul cliché on ne se rends pas compte réellement du comportement. Et en plus ces données ne sont pas intéressantes pour savoir ce qu’il se passe coté gestion mémoire. Heureusement que J9 (la JVM de Mr IBM) fournit quelques infos, sinon je ne vois pas comment diagnostiquer le problème sans jeter un œil sur les données adéquates, c’est à dire le log du Garbage Collector.
L’analyse du log GC, enfin!
Après l’obtention du fameux log, il faut encore trouver un outil IBM pour analyser le fichier. Les choses deviennent intéressantes. Comme je l’ai déjà dit, les logs sont au format IBM, ça ressemble à du XML. Et pour analyser ces logs rien de mieux que les outils de IBM, non? Google me dit rapidement qu’il me faut donc ce truc Pattern Modeling and Analysis Tool for Java Garbage Collector, direction http://www.alphaworks.ibm.com/tech/pmat.
Avec : Pattern Modeling and Analysis Tool for Java Garbage Collector
Un petit graphique pour regarder ce qu’il se passe.
En rouge l’usage de la Heap, en bleu le marquage des objets à virer, et en vert les temps de compression de la mémoire. Effectivement le GC à l’air de bien s’amuser dans la mémoire, et d’être appelé assez souvent.
Bon celà dit je ne suis pas convaincu par l’outil IBM, il manque des informations que j’avais vu en texte dans le log GC ; un évènement GC à cette tête là :
<af type="tenured" id="388571" timestamp="Jun 21 03:01:11 2010" intervalms="228.858"></pre>
<minimum requested_bytes="168" />
<time exclusiveaccessms="0.489" />
<tenured freebytes="0" totalbytes="402653184" percent="0" >
<soa freebytes="0" totalbytes="402653184" percent="0" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<gc type="global" id="388576" totalid="388576" intervalms="230.720">
<refs_cleared soft="0" threshold="32" weak="76" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="408.282" sweep="5.061" compact="0.000" total="415.341" />
<tenured freebytes="209018360" totalbytes="402653184" percent="51" >
<soa freebytes="209018360" totalbytes="402653184" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="209013328" totalbytes="402653184" percent="51" >
<soa freebytes="209013328" totalbytes="402653184" percent="51" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="417.431" />
</af>
Vu l’allure du log, on a pas l’impression d’être sur un GC de type generationnel, mais je ne suis pas encore sûr, c’est une JVM IBM. Bon revenons à nos moutons:
- il y a eu 230 ms d’écoulées avant le dernier GC.
- la tenured indique directement qu’il n’y a plus de place dans la mémoire,
- on voit que le GC est de type global, ce qui veut dire que c’est toute la zone mémoire qui est affectée par le GC, c’est long
- la tenured libère environ 200 MB, soit 51%!
- le temps total mis par ce GC est de 420 ms, c’est long.
Et il y a plein d’entrées comme ça, ça fait beaucoup de GC globaux de 1 demi-secondes, tous les 5ème de secondes. Le GC prends du temps CPU pour nettoyer la mémoire un peu trop souvent. Et ce ci pourrait bien être la cause des ralentissements observés. En gros soit il n’y a simplement pas assez de mémoire, soit il y a une fuite mémoire.
Avec : IBM Support Assistant et Garbage Collection and Memory Visualizer
En me renseignant, je voulais jeter un œil aux outils IBM plus récents, tel que celui mentionné par Holly Cummins au ParisJug (le 8 Juin 2010). Pour commencer il faut un compte IBM et télécharger IBM Support Assistant, direction http://www-01.ibm.com/software/support/isa/.
Après une fois qu’on a l’outil, il faut à nouveau télécharger des plugins (nommé additif sur l’interface en français). Bon en fait le Health Center en me sert à rien puisqu’il il faut se connecter à une JVM IBM, ayant une JVM Sun sur mon poste je ne vais quand même pas aller taper sur la prod si tenté que ce soit possible. Finalement j’opte pour le plugin : Garbage Collection and Memory Visualizer.
Donc finalement j’essaye cet outils d’analyse, et j’ai un rapport bien plus sympa et complet avec plein de graphiques qui m’intéressent.
Déjà le rapport débute par :
Your application appears to be leaking memory. This is indicated by the used heap increasing at a greater rate than the application workload (measured by the amount of data freed). To investigate further see Guided debugging for Java
Ok, je m’en doutais déjà mais c’est quand même mieux que de dire que la mémoire est quasiment entièrement utilisée. Et on retrouve les alertes suivantes dans le rapport :
The application seems to be using some quite large objects. The largest request which triggered an allocation failure (and was recorded in the verbose gc log) was for 5242904 bytes.
5MB quand même! Cela dit ça n’arrive pas souvent, c’est peut-être un cache qui charge des données depuis le disque. Le graphe suivant (choisir Object Size dans les templates de graphique sur la droite) montre la taille des allocations demandées.
Mais la concomitance de ses demandes d’allocation avec l’utilisation de la heap fait sourciller.
On continue
Garbage collection is causing some large pauses. The largest pause was 7362 ms. This may affect application responsiveness. If responsiveness is a concern then a switch of policy or reduction in heap size may be helpful.
Effectivement le temps passé dans l’application et le temps passé dans le GC indique manifestement qu’il y a une suractivité anormale du GC.
En fait on voit même que le GC est en train de compacter la mémoire au moment de l’incident, c’est la courbe rouge clair (entre ~0.5s et 1s), ajouté à cela le temps de marquage des objets à virer (bon en fait dans le graphique que j’ai fait, le temps de pause est principalement du au temps de marquage), l’ensemble donnant un temps de pause pour laisser le GC travailler allant de 1 à 7s (par GC bien évidement).
Et là effectivement expliquer les ralentissements de l’application devient plus facile, merci à ces beaux graphiques explicites.
On peut regarder vraiment beaucoup de chose avec cet outils, même s’il y a des défauts manifestes dans l’interface utilisateur. C’est quand même plutôt pas mal.
Je termine sur un petit résumé des valeurs intéressantes que nous donne cet outils.
Allocation failure count 59971 Forced collection count 3 GC Mode optthruput Largest memory request (bytes) 5242904 Mean garbage collection pause (ms) 491 Mean heap unusable due to fragmentation (MB) 0.2 Mean interval between collections (minutes) 0.01 Number of collections 59974 Proportion of time spent in garbage collection pauses (%) 58.24 Proportion of time spent unpaused (%) 41.76 Rate of garbage collection (MB/minutes) 13250
Tiens le mode GC est optthruput, en fait c’est une des polices du comportement du GC, et probablement de la manière de segmenter la mémoire (Nursery (Young), Old (Tenured)).
En effet dans les logs GC, je n’ai pratiquement vu que des GC globaux et uniquement sur la section de la tenured, à priori pas de zone nursery, c’est probablement du à ce comportement du GC.
En me renseignant donc, il y a 4 polices de GC dans la JVM J9 de IBM :
- optthruput : Optimisé pour throughput (le débit), flat heap <= Bingo
- optavgpause : Optimisé pour les temps de pause (Stop-The-World), le CMS est configuré pour prendre le moins de temps, flat heap
- subpool : Un police optimisé pour les machine multi-processeur, flat heap
- gencon : C’est le GC générationnel, qui est divisé en zone
- nursery : qui permet la collection rapide et efficace des objets de vie courte, pas de pause
- tenured : zone des vieux objets, mais un GC dans cette zone est global et demande à pauser l’application
A la poursuite du vrai problème (partie 2)
La pèche aux informations
Après avoir passé le GC au mode générationnel, il y a toujours ces problèmes de lenteurs mais ce n’est plus généralisé à toute l’appli, pas de log GC pour vérifier mais Introscope indique une utilisation relativement correcte de la mémoire, bizarre. Back to basics!
Le thread dump de la JVM IBM me dit toujours que la Heap est utilisée à 100%, mais je vois quand même
Free Java heap size: 72 041 864 bytes
Allocated Java heap size: 402 653 184 bytes
Et plus loin :
Last Garbage Collection Detail
Nursery Area Free : 59 307 392 bytes Total : 60 397 568 bytes 98 % free
Tenured Area Free : 17 058 368 bytes Total : 335 544 320 bytes 5% free
Global Garbage Collector Counter : 148
La tenured est bien remplie et utilise un très grosse partie de la heap ; memory leak ou beaucoup d’objet à mettre en cache. Ou encore autre chose, sans mesures claires pour écarter les hypothèses ces dur.
Pour quoi ne pas activer dans tous les cas le log GC, la JVM IBM offre des option pour gérer la rotation des logs GC, comme ça l’argument de saturation du disque tombe à l’eau. Mais bon il faut lire la documentation; donc petit passage chez IBM grâce à Google, et hop :
-Xverbosegclog[:<file>[,<X>,<Y>]]
Et voilà : file étant le couple chemin + fichier, X le nombre de fichier maximum (ça tourne et écrase les fichiers), Y le nombre de cycle GC. Ce que ne dis pas par contre la doc IBM c’est la taille approximative d’un GC, donc 700 cycles de GC ≃ 1 MB. Il est même possible d’utiliser des tokens utilisés pour les dumps dans WAS 7 (voir ici).
Recoupement des informations
Le log du Garbage Collector ne venant pas, il faut chercher autrement. Je demande au moment ou le problème se reproduit , de faire plusieurs thread dump d’affilé séparé de quelques secondes (~20s) et de faire également un listing des sous-processus java.
En effet le thread dump est bien sympa, mais il ne donne pas la consommation CPU des threads.
Dans un environnement il faut entre dans le terminal (Dans Linux l’identifiant des thread est dans la colonne LWD.) :
ps -fLp <processid> -L
Evidement il s’agit d’un AIX et les commendes sont différents, pas de soucis un petit tour dans la doc IBM et il faut entrer la commande suivante, et là l’identifiant de la thread est dans la colonne TID :
ps -mp <processid> -o THREAD
On a alors un listing énorme, que j’ai tronqué ici.
USER PID PPID TID S CP PRI SC WCHAN F TT BND COMMAND wasadmin 393262 401580 - A 188 60 203 * 202001 - - /opt/was61/java/bin/java ... - - - 700535 S 0 82 1 f100070f1000ab40 8410400 - - - - - - 741581 S 0 82 1 f100070f1000b540 8410400 - - - - - - 802997 S 0 82 1 f100070f1000c440 8410400 - - - - - - 884895 S 0 82 1 f100070f1000d840 8410400 - - - - - - 1183791 Z 0 82 1 - c00001 - - - - - - 1667157 R 60 122 0 - 400000 - - - - - - 1708269 S 0 82 1 f100070f1001a140 8410400 - - - - - - 1736831 S 0 82 1 f100070f1001a840 8410400 - - -
La colonne CP me dit que manifestement la thread 1667157 utilise plutôt pas mal le CPU, qu’est-ce que donne cette thread du coté du thread dump ?! Au fait on repère 3 threads dans le même cas.
Il faut savoir que dans le thread dump il y a l’identifiant de la thread en Java, mais qu’il y a aussi et surtout de mentionné l’identifiant natif de la thread, par exemple NID.
Je google “1667157 in hex” ce qui me renvoie 0×197055. En utilisant l’outils IBM mentionné plus haut, on voit clairement que la thread en cause correspond à du code métier, développé ici.
Chacune des 3 threads passent dans le même bout de code. Autant au début j’ai des doutes, après toute la présomption d’innocence compte aussi pour le code, d’autant plus qu’il s’agit d’un code lent qui utilise beaucoup de reflection. Mais faut prendre en compte aussi le fait que la pile descend à chaque fois dans la couche Hibernate, ça vaut le coup d’aller voir. Les développeurs qui connaissent un peu mieux le code poussent dans cette direction.
Entre temps les DBA confirme que la base de données réponds très bien, mais qu’elle enregistre un très fort nombre d’un certain type de requête SQL.
Bingo, il y a une race condition dans une des boucles, et celle-ci part en boucle infinie. Ceci explique la très forte utilisation de la mémoire et les lenteurs remarquées.
Bilan
Un problème peut en cacher un autre, ou plus exactement un problème peut en provoquer d’autres. Il faut juste avoir des moyens de mesurer les changements qu’on apporte si on veut isoler / écarter des catégorie de problèmes.
L’outillage on l’a vu est essentiel, Introscope apporte des choses, mais il ne permet pas tout. Qui plus est, on ne sait pas précisément ce qu’il mesure et ou! Les temps de réponses SQL, n’étaient par exemple pas crédible, car Introscope mesurait également les GC.
Dans notre cas ici, j’aurais aussi bien aimé avoir une JVM IBM sur mon poste histoire de jouer plus facilement avec. C’est dommage que IBM ne fournisse pas gratuitement sa JVM au moins pour le développement.
Accessoirement ce serait bien un jour d’avoir des format de log normalisé entre les JVM, ainsi que certaines des options afférentes.
Finalement ce qui a pris le plus de temps était d’obtenir les bonnes données, pour prendre les meilleurs choix. L’impression de travailler les mains dans le noir n’était pas l’idéal pour résoudre le problème, mais c’est au moins formateur. Je peux dire que j’ai bien apprécié certains retours et recommandations des développeurs. L’équipe système étant surchargée n’a pas pu nous donné un support optimal, et cette carence s’est ressentie notamment pour avoir les données à temps. Mais leur vu du problème a permis d’orienter la recherche sur les parties qui pouvait poser problème.
Références & Documentation
- http://websphere.sys-con.com/node/921279?page=0,1
- http://sites.google.com/site/threaddumps/java-thread-dumps
- http://java.sun.com/developer/technicalArticles/Programming/Stacktrace/
- http://geekexplains.blogspot.com/2008/07/threadstate-in-java-blocked-vs-waiting.html
- http://www.ibm.com/developerworks/java/library/j-nativememory-aix/
- http://www.ibm.com/developerworks/ibm/library/i-garbage1/
- http://www-01.ibm.com/support/docview.wss?rs=180&context=SSEQTP&dc=DB560&dc=DB520&uid=swg21384096&loc=en_US&cs=UTF-8&lang=en&rss=ct180websphere
- http://publib.boulder.ibm.com/infocenter/javasdk/v6r0/index.jsp?topic=/com.ibm.java.doc.diagnostics.60/diag/appendixes/cmdline/cmdline_gc.htm
By:
Le contexte
L’histoire commence par un problème en production sur une version à priori stable et sans anomalie connue. Seulement voilà une fois en prod l’application devient de plus en plus lente. Pourquoi? Que se passe-t-il?
Avec l’activation des logs du GC dans les options de la JVM, l’équipe s’aperçoit donc très vite que l’application arrive à bout de la mémoire disponible, mais pas de OutOfMemoryError (pourtant classique lors d’une fuite mémoire).
-Xloggc:<logfile> -XX:+PrintGCDetails
Lors de l’analyse des GC on remarque immédiatement une famine de mémoire, la JVM est obligée de faire des Full GC très souvent, et un Full GC c’est lent!
Pour avoir une représentation un peu compréhensible, on analyse ces logs avec GCViewer. On a alors un graphe qui ressemble à ça :
On voit comment se passe le consommation de la mémoire dans l’application, on sait que l’application est lente, maintenant pourquoi la consommation mémoire monte autant sans être libéré. Effectivement les raisons peuvent varier surtout qu’il n’y avait pas de OutOfMemoryError!
- Possibilité 1 : Un problème de concurrence (deadlock, point de contention sur une ressource, …); c’est cette possibilité qui a été retenue pour l’investigation du problème. Les thread dump nous confortaient dans cette optique étant donné qu’on voyait régulièrement le même code revenir. Et les indicateurs sur le CPU montrait qu’il n’était pas énormément utilisé.
- Possibilité 2 : Une fuite mémoire, choix écarté parce qu’on ne voyait de OOME.
Et bien on avait tort, il s’agissait d’une fuite mémoire. Avec un collègue plus expérimenté nous avons fait du profiling, très vite il a mis le doigt sur le code en tort. Mais quelque chose me choquait, pourquoi pas d’erreur OOME alors qu’il s’agissait manifestement d’une fuite mémoire.
La bonne rencontre
J’ai eu la chance de pouvoir rencontré Heinz Kabutz lors d’une conférence chez Zenika, en discutant avec lui j’ai eu l’occasion d’aborder ce sujet. Il m’a immédiatement demandé si notre application utilisait beaucoup d’introspection. Il m’a dit qu’il soupçonnait que ce genre de cas pouvait se produire, et il m’a ensuite aiguillé sur la manière dont le JDK de Sun utilise des SoftReference pour stocker les éléments issus de la reflection.
Et là, les cases manquantes n’étaient plus, en effet les objets SoftReference sont des références qui sont réclamées par le GC lorsque la JVM a vraiment vraiment besoin de mémoire, juste avant de lever une OutOfMemoryError. En gros, ça se passe typiquement lors des Full GC.
Et donc comme l’application est toujours en état de marche, le code qui a besoin de reflection va recréer ces objets. Cette combinaison de Full GC et la recréation constante des références des éléments issus de l’introspection, va très fortement ralentir l’application sans lever cette fameuse OOME. Ou en tout cas en repoussant dans le temps cette OOME.
La preuve
Fort de cette nouvelle connaissance, j’ai été jeter un coup d’œil dans l’objet java.lang.Class pour effectivement y découvrir la mise en cache des éléments comme les méthodes et les champs dans une SoftReference. Ainsi en regardant le code source de OpenJDK:
/*
* Copyright 1994-2006 Sun Microsystems, Inc. All Rights Reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation. Sun designates this
* particular file as subject to the "Classpath" exception as provided
* by Sun in the LICENSE file that accompanied this code.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Sun Microsystems, Inc., 4150 Network Circle, Santa Clara,
* CA 95054 USA or visit www.sun.com if you need additional information or
* have any questions.
*/
...
// Returns an array of "root" methods. These Method objects must NOT
// be propagated to the outside world, but must instead be copied
// via ReflectionFactory.copyMethod.
private Method[] privateGetDeclaredMethods(boolean publicOnly) {
checkInitted();
Method[] res = null;
if (useCaches) {
clearCachesOnClassRedefinition();
if (publicOnly) {
if (declaredPublicMethods != null) {
res = (Method[]) declaredPublicMethods.get();
}
} else {
if (declaredMethods != null) {
res = (Method[]) declaredMethods.get();
}
}
if (res != null) return res;
}
// No cached value available; request value from VM
res = Reflection.filterMethods(this, getDeclaredMethods0(publicOnly));
if (useCaches) {
if (publicOnly) {
declaredPublicMethods = new SoftReference(res);
} else {
declaredMethods = new SoftReference(res);
}
}
return res;
}
Bon voilà pour la preuve de ce qui était avancé, mais pour aller plus loin je vais reproduire le scénario.
La preuve par l’exemple
L’idée de l’exemple est d’avoir du code qui va simuler une fuite mémoire et un autre code qui va utiliser plus ou moins intensément l’introspection. On le verra plus tard mais le débit d’allocation d’objet de la fuite mémoire ne doit pas être trop important sinon on verra effectivement très vite l’erreur OutOfMemoryError.
Le processus métier qui utilise de l’introspection
Comme je suis fainéant, je n’ai pas spécialement envie de créer 300 classes, donc je vais les générer en utilisant l’API Compiler du JDK 6. Je me suis un peu inspiré de qui disponible sur le net à ce sujet. En particulier de cette entrée. Je passe brièvement dessus pour simplement dire que c’est la méthode processBusinessLogic qui est intéressante, on charge des classes, et surtout on appelle une méthode par introspection.
package com.brice.memoryleakwithoutoome;
import javax.tools.*;
import java.io.*;
import java.lang.reflect.Method;
import java.net.URI;
import java.nio.charset.Charset;
import java.util.*;
public class BusinessLayerWithALotOfReflection {
private InMemoryClassLoader classLoader = new InMemoryClassLoader();
private List<String> classNames = new ArrayList();
public static void main(String... args) throws Exception {
BusinessLayerWithALotOfReflection businessLayer = new BusinessLayerWithALotOfReflection(3);
businessLayer.performBusinessLogic();
}
public BusinessLayerWithALotOfReflection(int toGenerate) throws Exception {
init(toGenerate);
}
public void performBusinessLogic() throws Exception {
for (String className : classNames) {
Object o = Class.forName(className, true, classLoader).newInstance();
Method method = o.getClass().getMethod("m1", null);
method.invoke(o, null);
}
}
private void init(int toGenerate) throws Exception {
generateSources(toGenerate);
}
private void generateSources(int toGenerate) throws Exception {
List<JavaObjectFromString> generatedSources = new ArrayList<JavaObjectFromString>();
for (int genId=0; genId < toGenerate; genId++) {
String className = "$Generated" + genId;
StringBuilder sb = new StringBuilder();
sb.append("package com.brice.memoryleakwithoutoome.generated; ");
sb.append("import java.util.Random;");
sb.append("public class ").append(className).append(" {");
sb.append("public void m1() { new Random().nextGaussian(); }");
sb.append("}");
classNames.add("com.brice.memoryleakwithoutoome.generated." + className);
generatedSources.add(new JavaObjectFromString(className, sb.toString()));
}
generateClasses(generatedSources);
}
private void generateClasses(Iterable<JavaObjectFromString> javaObjects) throws IOException {
JavaCompiler compiler = ToolProvider.getSystemJavaCompiler();
StandardJavaFileManager javaFileManager = compiler.getStandardFileManager(null, null, Charset.defaultCharset());
InMemoryJavaFileManager inMemoryJavaFileManager = new InMemoryJavaFileManager(javaFileManager, classLoader);
compiler.getTask(null, inMemoryJavaFileManager, null, null, null, javaObjects).call();
javaFileManager.close();
}
static class JavaObjectFromString extends SimpleJavaFileObject {
private String contents = null;
public JavaObjectFromString(String className, String contents) throws Exception {
super(URI.create("string:///" + className.replace('.', '/') + Kind.SOURCE.extension), Kind.SOURCE);
this.contents = contents;
}
public CharSequence getCharContent(boolean ignoreEncodingErrors) throws IOException {
return contents;
}
}
static class InMemoryJavaFileObject extends SimpleJavaFileObject {
InMemoryJavaFileObject(String name, Kind kind) {
super(URI.create(name), kind);
}
private ByteArrayOutputStream baos;
@Override
public CharSequence getCharContent(boolean ignoreEncodingErrors) throws IOException, IllegalStateException, UnsupportedOperationException {
throw new UnsupportedOperationException();
}
@Override
public InputStream openInputStream() throws IOException, IllegalStateException, UnsupportedOperationException {
return new ByteArrayInputStream(baos.toByteArray());
}
@Override
public OutputStream openOutputStream() throws IOException, IllegalStateException, UnsupportedOperationException {
return baos = new ByteArrayOutputStream();
}
public byte[] getClassDefinition() {
return baos.toByteArray();
}
}
static class InMemoryJavaFileManager extends ForwardingJavaFileManager<StandardJavaFileManager> {
private InMemoryClassLoader inMemoryClassLoader;
protected InMemoryJavaFileManager(StandardJavaFileManager fileManager, InMemoryClassLoader classLoader) {
super(fileManager);
this.inMemoryClassLoader = classLoader;
}
@Override
public JavaFileObject getJavaFileForOutput(Location location,
String name,
JavaFileObject.Kind kind,
FileObject sibling) throws IOException {
return inMemoryClassLoader.registerClassDefinition(new InMemoryJavaFileObject(name, kind));
}
}
static class InMemoryClassLoader extends ClassLoader {
private Map<String, InMemoryJavaFileObject> inMemoryClassObjects = new HashMap<String, InMemoryJavaFileObject>();
protected Class findClass(String name) throws ClassNotFoundException {
InMemoryJavaFileObject classObject = inMemoryClassObjects.get(name);
if (classObject != null) {
byte[] classDefinition = classObject.getClassDefinition();
return defineClass(name, classDefinition, 0, classDefinition.length);
}
return super.findClass(name);
}
public InMemoryJavaFileObject registerClassDefinition(InMemoryJavaFileObject object) {
inMemoryClassObjects.put(object.getName(), object);
return object;
}
}
}
Le code avec la fuite mémoire
Bon voilà pour le code qui simule du code métier avec de l’introspection, maintenant c’est au tour de simuler le service qui engendre une fuite mémoire. L’utilisation des thread est accessoire cela dit, mais ça permet de rappeler le fonctionnement d’une véritable application.
package com.brice.memoryleakwithoutoome;
import java.lang.management.ManagementFactory;
import java.util.Set;
import java.util.UUID;
import java.util.concurrent.ConcurrentSkipListSet;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.logging.Logger;
public class Service {
private static Set<UUID> sessions = new ConcurrentSkipListSet<UUID>();
private static ExecutorService executor = Executors.newCachedThreadPool();
private static BusinessLayerWithALotOfReflection businessLayer;
static {
try {
businessLayer = new BusinessLayerWithALotOfReflection(300);
} catch (Exception e) {
e.printStackTrace();
System.exit(1);
}
}
public static void main(String[] args) throws Throwable {
System.out.println(ManagementFactory.getRuntimeMXBean().getName());
try {
while (true) {
executor.submit(new LeakyThread(businessLayer));
Thread.sleep(1);
}
} catch (Throwable t) {
Logger.getAnonymousLogger().severe(t.toString());
throw t;
}
}
private static class LeakyThread extends Thread {
private BusinessLayerWithALotOfReflection businessLayer;
public LeakyThread(BusinessLayerWithALotOfReflection businessLayer) {
this.businessLayer = businessLayer;
}
@Override
public void run() {
// leak
sessions.add(UUID.randomUUID());
// non leaky business logic using a lot reflection
try {
businessLayer.performBusinessLogic();
} catch (Exception e) {
e.printStackTrace();
return;
}
}
}
}
C’est à la ligne de 30 du code que je contrôle le débit de la fuite mémoire. En effet si je retire ce Thread.sleep, il y a très vite une OOME. Pour la fuite mémoire, celle-ci consiste juste à alimenter un liste de String. On pourrait par exemple imaginer que dans une application réelle ce code stockerait des objets dans une Map pour chaque session.
Afin de ne pas attendre des heures avec juste quelques String, je vais limiter l’espace mémoire de mon application à 10MB:
-Xms10m -Xmx10m
Je vais également ajouter les paramètres à la JVM pour suivre le GC.
Et le résultat est là, l’application ne plante toujours pas après 6 minutes.
Effectivement les paramètres de la JVM donnent une allure différente d’une application en production, mais ici le but est de reproduire un scénario de fuite mémoire sans OutOfMemoryError. Le GC a donc l’allure suivante :
On voit un premier Full GC vers 1min30 ou les SoftReferences sont nettoyées, et puis vers 2min30 c’est la catastrophe, il n’y a que des Full GC, la JVM va constamment réclamer les références issues de l’introspection, le programme va constamment en recréer, avec la saturation de la mémoire la lenteur de tous les FullGC devient manifeste. Et comme dit plus haut les thread dump ne vont pas révéler de point de contention, ils vont juste montrer que l’application est lente. En particulier les thread dump vont surtout révéler les stacks des modules ou l’application est plus lente!
D’ailleurs sur la sortie standard, on voit au premier Full GC les traces suivantes, et elles arrivent plus régulièrement une fois que les GC s’enchainent :
... [Unloading class sun.reflect.GeneratedConstructorAccessor147] [Unloading class sun.reflect.GeneratedConstructorAccessor419] [Unloading class sun.reflect.GeneratedMethodAccessor104] [Unloading class sun.reflect.GeneratedMethodAccessor151] [Unloading class sun.reflect.GeneratedMethodAccessor57] [Unloading class sun.reflect.GeneratedMethodAccessor390] [Unloading class sun.reflect.GeneratedConstructorAccessor8] [Unloading class sun.reflect.GeneratedMethodAccessor207] [Unloading class sun.reflect.GeneratedMethodAccessor395] [Unloading class sun.reflect.GeneratedConstructorAccessor83] ...
Autre outil à utiliser, jVisualVM qui est disponible en standard avec le JDK6. On se retrouve avec onglet de monitoring sympa. A noter que les graphes d’activité du CPU ne sont pas disponible en standard sur jVisualVM avec la JDK6.
Ce que je ne voyais pas avec GCViewer c’est que le nombre de threads actives a dramatiquement baissé, ce qui confirme la lenteur exécution, les traitements mettent vraiment plus longtemps, et les autres threads sont alors mises en standby. Si on fait attention à la fenêtre temporelle, ça passe vers 14h48, à ce moment là, la mémoire heap n’est pas encore complètement saturée les GC tenaient jusque là. C’est ensuite que les Full GC prennent le relai pour réclamer de la mémoire, c’est donc à ce moment que les SoftReference sont collectées. Et comme dit plus haut, ces références sont recréées par les traitements métier. Et comme le Full GC s’exerce en permanence après ce moment, les références qui viennent d’être recréés sont collectées à nouveau. Et voilà la boucle est bouclée.
Conclusion
En conclusion, ce n’est pas parce qu’il n’y a pas de OutOfMemoryError qu’il n’y a pas de fuite mémoire. Plus généralement le réflexe c’est de se demander si notre application utilise beaucoup d’introspection ou plus simplement si l’application utilise beaucoup de références plus faibles comme les WeakReference, SoftReference.
Follow