G1 est activé lorsque vous rajoutez l'option -XX:+UseG1GC. Pour tracer ce qu'il fait ajoutez également les options
- -XX:+PrintGC qui nous permettra d’activer les traces des opérations du GC et
- -XX:+PrintGCDetails qui permet d’avoir plus de détail
Ces options permettent de générer une trace similaire à celle-ci
[GC pause (young), 0.70874343 secs]
[Parallel Time: 101.2 ms]
[GC Worker Start (ms): 49786.9 49786.9
Avg: 49786.9, Min: 49786.9, Max: 49786.9, Diff: 0.0]
[Ext Root Scanning (ms): 6.9 7.4
Avg: 7.2, Min: 6.9, Max: 7.4, Diff: 0.5]
[Update RS (ms): 1.1 1.1
Avg: 1.1, Min: 1.1, Max: 1.1, Diff: 0.1]
[Processed Buffers : 7 5
Sum: 12, Avg: 6, Min: 5, Max: 7, Diff: 2]
[Scan RS (ms): 0.4 0.2
Avg: 0.3, Min: 0.2, Max: 0.4, Diff: 0.2]
[Object Copy (ms): 92.3 92.1
Avg: 92.2, Min: 92.1, Max: 92.3, Diff: 0.2]
[Termination (ms): 0.0 0.0
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]
[Termination Attempts : 1 1
Sum: 2, Avg: 1, Min: 1, Max: 1, Diff: 0]
[GC Worker End (ms): 49887.6 49887.6
Avg: 49887.6, Min: 49887.6, Max: 49887.6, Diff: 0.0]
[GC Worker (ms): 100.8 100.8
Avg: 100.8, Min: 100.8, Max: 100.8, Diff: 0.0]
[GC Worker Other (ms): 0.5 0.5
Avg: 0.5, Min: 0.5, Max: 0.5, Diff: 0.0]
[Clear CT: 5.6 ms]
[Other: 602.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 567.8 ms]
[Ref Enq: 8.0 ms]
[Free CSet: 6.1 ms]
[Eden: 179M(179M)->0B(33M) Survivors: 7168K->18M Heap: 204M(256M)->35M(256M)]
[Times: user=0.05 sys=0.13, real=0.72 secs]
Nous allons maintenant découper ligne par ligne cette log pour savoir quels enseignements nous pouvons en tirer. L’indentation permet de distinguer les différentes sous tâches qui sont lancées.
Collecte sur la young
[GC pause (young), 0.70874343 secs] indique que la tâche est une tâche stop-the-world (mot clé pause) sur la young space (zone Eden et Survivor) et qu’elle a pris 0.70874343 secs. Si le GC travaille à la fois sur la young et la old, la log commencerait par la ligne [GC pause (mixed), 0.70874343 secs].
G1 fonctionne ici en lançant plusieurs threads en parallèle. Vous avez le temps total passé dans ces traitements
[Parallel Time: 101.2 ms] [GC Worker Start (ms): 49786.9 49786.9 Avg: 49786.9, Min: 49786.9, Max: 49786.9, Diff: 0.0]
[GC Worker Start] indique l’instant de départ des différents threads. Par exemple dans notre exemple, nous savons que le thread0 et thread1 ont été lancés à 49786.9. La deuxième ligne va donné des statistiques sur ces lancements (Moyenne, min, max...). [Ext Root Scanning (ms): 6.9 7.4
Avg: 7.2, Min: 6.9, Max: 7.4, Diff: 0.5]
[Ext Root Scanning] permet de savoir combien de temps a été passé par les différents threads dans la sous tâche de scan des éléments de base (registres, thread stacks...) [Update RS (ms): 1.1 1.1
Avg: 1.1, Min: 1.1, Max: 1.1, Diff: 0.1]
[Processed Buffers : 7 5
Sum: 12, Avg: 6, Min: 5, Max: 7, Diff: 2]
[Scan RS (ms): 0.4 0.2
Avg: 0.3, Min: 0.2, Max: 0.4, Diff: 0.2]
Les différentes structures de données contenant les références vers les différents emplacements de la heap sont appelées les Remembered Sets (RS). Nous avons ici des indications sur les temps passés par chaque thread pour mettre à jour ces références (les temps de scans étant exposés dans
[Scan RS]). La copie des objets d’une zone à une autre fait que les références vers les zones occupées par ces objets ne font que bouger pendant le travail du GC. Tous ces changements sont stockés dans les buffers appelés "Update Buffers". La sous tâche Update RS met à jour ces références et le nombre de buffers pris en compte par chacun des workers est tracé dans [Processed Buffers]. [Object Copy (ms): 92.3 92.1
Avg: 92.2, Min: 92.1, Max: 92.3, Diff: 0.2]
Chaque thread est amené à copier les objets encore en vie vers une autre zone mémoire. Nous avons ici des informations sur les temps de copie.
[Termination (ms): 0.0 0.0
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]
[Termination Attempts : 1 1
Sum: 2, Avg: 1, Min: 1, Max: 1, Diff: 0]
Quand un thread en a terminé avec son ensemble particulier d'objets à copier et scanner, il pénètre dans sa phase de finalisation (termination). Il cherche à récupérer du travail supplémentaire auprès des autres threads avant de repasser en phase de finalisation. Les logs donnent le temps passé dans cet état
[Termination (ms)] ainsi que le nombre de fois où un thread passe dans cet état [Termination Attempts] [GC Worker End (ms): 49887.6 49887.6
Avg: 49887.6, Min: 49887.6, Max: 49887.6, Diff: 0.0]
[GC Worker (ms): 100.8 100.8
Avg: 100.8, Min: 100.8, Max: 100.8, Diff: 0.0]
[GC Worker Other (ms): 0.5 0.5
Avg: 0.5, Min: 0.5, Max: 0.5, Diff: 0.0]
La première ligne donne des informations sur l’heure à laquelle les différents workers ont été stoppés. La seconde donne la durée de chaque worker et la dernière indique le temps passé à faire d’autres choses qui n’ont pas été listées dans la liste des sous tâches déjà évoquées.
[Clear CT: 5.6 ms]
[Other: 602.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 567.8 ms]
[Ref Enq: 8.0 ms]
[Free CSet: 6.1 ms]
[Clear CT] donne le temps passé par les différents workers dans le nettoyage de la Card Table qui est une meta donnée des Remembered Set.
Le reste du travail effectué de manière séquentiel est tracé dans la partie
[Other:]. On retrouve[Choose CSet]: Le CSet est une collection qui contient toutes les données encore en vie détectées par un cycle de garbage. Les données correspondent au temps passé pour sélectionner les différentes régions à traiter.[Ref Proc]: temps passé dans le traitement des références vers les objets reportées par les phases précédentes du GC.[Ref Enq]: temps passé à placer les références dans la liste en attente.[Free CSet]: temps pour libéré cet ensemble
[Eden: 179M(179M)->0B(33M) Survivors: 7168K->18M Heap: 204M(256M)->35M(256M)]
Cette ligne donne des informations sur les changements de taille des différentes régions de la heap. Dans notre exemple nous pouvons interprété que
- la taille des différentes zones Eden est montée à 179M, avant la collecte la taille était de 179M et à la fin elle est de 0 (normal vu que les données sont déplacées dans le Survivor voir la Old generation). La valeur de 33M correspond à la valeur cible de l’Eden à partir de laquelle la prochaine collecte sera lancée.
- la taille des différentes zones Survivor était de 7168K et est montée à 18M.
- l’espace total de la heap était de 204M et est à la fin de 35M.
Comme je l’ai précisé dans la première partie, le marquage des objets dans la old generation se fait en mode concurrent (sans interrompre l’application). Cette opération se déclenche lorsque le taux d’occupation de la heap atteint un certain seuil (on parle de marking threshold). Ce seuil est par défaut définit à 45% mais vous pouvez le personnaliser via l’option -XX: InitiatingHeapOccupancyPercent.
Si nous regardons les logs nous trouvons des lignes de ce type :
Le marquage se fait en mode concurrent et permettra lors de la prochaine exécution d’un nettoyage de la young, de traiter un nombre déterminé de zone de la old generation (suppression et compactage des données restant en vie).
La tâche
Références principales
Voici les principales références qui m'ont permis d'écrire cette suite d'article http://www.fasterj.com/articles/G1.shtml https://blogs.oracle.com/poonam/entry/understanding_g1_gc_logs http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/G1GettingStarted/index.html http://www.infoq.com/articles/G1-One-Garbage-Collector-To-Rule-Them-All
[GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0149287] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.5043124 sec] [GC remark [GC ref-proc, 0.0015751 secs], 0.0164269 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] [GC cleanup 191M->191M(256M), 0.0014653 secs] [Times: user=0.00 sys=0.01, real=0.00 secs]
Le marquage se fait en mode concurrent et permettra lors de la prochaine exécution d’un nettoyage de la young, de traiter un nombre déterminé de zone de la old generation (suppression et compactage des données restant en vie).
La tâche
[GC remark] se fait en mode STW (stop the world) et complète le marquage précédent sur les objets qui n’ont pas pu être traités en mode concurrent.Références principales
Voici les principales références qui m'ont permis d'écrire cette suite d'article http://www.fasterj.com/articles/G1.shtml https://blogs.oracle.com/poonam/entry/understanding_g1_gc_logs http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/G1GettingStarted/index.html http://www.infoq.com/articles/G1-One-Garbage-Collector-To-Rule-Them-All
Aucun commentaire:
Enregistrer un commentaire
Remarque : Seul un membre de ce blog est autorisé à enregistrer un commentaire.