Identifier les allocations humongous avec BPF

January 23, 2020 10 minutes de lecture

Performances • G1GC • BPF

2020-02-16 Mise à jour, un nouvel article a été publié pour inclure les contributions de plusieurs personnes. Il permet de répondre à plusieurs points laissés en suspens dans cet article.

Le livre BPF Performance Tools de Brendan Gregg regorge d’outils pour diagnostiquer les problèmes les plus ardus. Aujourd’hui, on s’intéressera à funccount, trace, argdist et stackcount pour diagnostiquer d’où proviennent des allocations humongous dans une application Java.

L’application d’exemple

Comme dans le précédent article, on analysera une application web Java tout ce qu’il y a de plus standard (Spring PetClinic). Excepté que j’ai volontairement modifié cette application pour que des objets très volumineux (humongous) soient alloués. Avec les commandes funccount, trace, argdist et stackcount, on cherchera à détecter ces allocations.

Des objets "humongous" ?

Tout d’abord, faisons un petit rappel sur les objets humongous. Lorsque l’on utilise le G1GC, la heap est divisée en de multiples régions. Ces régions sont ensuite affectées tantôt à l’Eden, les Survivors ou la Old Generation. Mais que se passe-t-il lorsque l’application alloue un objet dont la taille dépasse celle une région?

Le contrat de fonctionnement du GC est que l’application ne doit pas se rendre compte de comment la mémoire est fournie. Mais ce cas de figure, on doit s’intéresser à ce "comment". G1 va fusionner des régions adjacentes jusqu’à obtenir un espace mémoire suffisant pour stocker l’objet alloué. Ces régions ne feront alors ni partie de la Young Generation, ni de la Old Generation. Elles seront traitées à part, lors des cycles de GC mixtes.

Pour être tout à fait précis, ce sont tous les objets dont la taille dépasse la moitié d’une région qui sont considérés "humongous".

Ce qu’il faut retenir, c’est que G1GC n’a pas été optimisé du tout pour ces objets. Ils sont un anti-pattern connu. Il est alors recommandé de modifier l’application pour que ces objets soient séparés en plusieurs objets plus petits.

Lorsque la modification d’une application n’est pas une option, il est toujours possible de changer la taille des régions de G1 avec -XX:G1HeapRegionSize=…. Mais ce paramètre vient avec son lot de problèmes. Notamment, son utilisation désactive la logique adaptative de G1GC. Pour faire simple, lorsque l’on utilise ce paramètre, on indique au GC que l’on sait ce que l’on fait. Et donc il nous laisse entièrement aux commandes.

Le protocole de test

Pour cet article, j’utiliserai:

Le JDK 13.0.1
Les outils BPF installés via les paquets bcc et bcc-tools sous Archlinux avec un noyeau en version 5.4.6
L’agent Java perf-map-agent pour obtenir des stacktraces lisibles

Les variables d’environnement suivantes seront définies:

LIBJVM pointant sur le fichier libjvm.so de mon JDK
PATH incluant les outils BPF
JAVA_OPTS avec des paramètres pour avoir des régions de 1 Mo et pour générer des stacktraces lisibles par les outils BPF

export LIBJVM=/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so
export PATH=/usr/share/bcc/tools/:$PATH
export JAVA_OPTS="-XX:+PreserveFramePointer -Xms3G -Xmx3G -XX:+UseG1GC -XX:G1HeapRegionSize=1048576 -verbose:gc"

Un test de charge léger sera exécuté en tâche de fond pour solliciter le code à problème. Notons que l’application ne sera analysée qu’après optimisation par la JVM (steady-state).

Vérification préalable

Exécutons l’application et son test de charge, avec les logs GC activés. On peut lire qu’à plusieurs reprises, un cycle GC a été initié pour cause d’allocation "humongous". À elle seule, cette information nous confirme que l’application a un problème.

[442.770s][info][gc] GC(227) Pause Young (Normal) (G1 Humongous Allocation) 3059M->3034M(3072M) 3.816ms
[442.779s][info][gc] GC(228) Pause Young (Normal) (G1 Humongous Allocation) 3055M->3054M(3072M) 3.749ms
[442.866s][info][gc] GC(229) Pause Full (G1 Humongous Allocation) 3054M->3048M(3072M) 86.581ms
[442.870s][info][gc] GC(230) Pause Young (Normal) (G1 Humongous Allocation) 3055M->3054M(3072M) 2.324ms
[442.935s][info][gc] GC(231) Pause Full (G1 Humongous Allocation) 3054M->3054M(3072M) 65.282ms

Funccount

Commençons par la commande funccount. Cette commande compte, comme son nom l’indique, le nombre de fois qu’une fonction particulière a été appelée. Elle va nous servir à établir un premier diagnostique.

On souhaite identifier où les objets humongous sont alloués. Il nous faut donc tout d’abord déterminer quelle est la fonction de la JVM en charge de ces allocations. Alors là, soit on demande sur Twitter, soit on va lire le code source de la JVM pour trouver la classe G1CollectedHeap. Et plus particulièrement sa méthode G1CollectedHeap::humongous_obj_allocate.

L’avantage de l’open-source, ce n’est pas l’aspect gratuit. C’est qu’on peut aller lire le code source.

On doit déterminer quel est le nom réel de cette fonction après compilation par gcc. Comme on sait que ce nom contient humongous, on peut d’ores et déjà exécuter funccount "$LIBJVM:*humongous*" et voir ce qu’on obtient.

[alarm@archlinux ~]$ sudo funccount "$LIBJVM:*humongous*"
Tracing 24 functions for "b'/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:*humongous*'"... Hit Ctrl-C to end.
^C
FUNC                                                                             COUNT
b'_ZN16G1ConcurrentMark34humongous_object_eagerly_reclaimedEP10HeapRegion'       218
b'_ZN15G1CollectedHeap33eagerly_reclaim_humongous_regionsEv'                     228
b'_ZN9metaspace35get_size_for_nonhumongous_chunktypeENS_10ChunkIndexEb'          746
b'_ZN22G1BlockOffsetTablePart24set_for_starts_humongousEPP12HeapWordImplm'       3357
b'_ZN10HeapRegion20set_starts_humongousEPP12HeapWordImplm'                       3357
b'_ZN15G1CollectedHeap41humongous_obj_allocate_initialize_regionsEjjm'           3357
b'_ZN10HeapRegion23set_continues_humongousEPS_'                                  3357
b'_ZN15G1CollectedHeap28attempt_allocation_humongousEm'                          3393
b'_ZN15G1CollectedHeap22humongous_obj_allocateEm'                                3849
b'_ZN15G1CollectedHeap29humongous_obj_size_in_regionsEm'                         4562
b'_ZN15G1CollectedHeap21free_humongous_regionEP10HeapRegionP14FreeRegionList'    5858
b'_ZN10HeapRegion15clear_humongousEv'                                            6361
b'_ZN22G1RemSetTrackingPolicy31update_humongous_before_rebuildEP10HeapRegionb'   8649
Detaching...

On retrouve donc notre fonction avec un nom décoré un peu moins lisible: _ZN15G1CollectedHeap22humongous_obj_allocateEm.

Faisons abstraction du reste et concentrons nous sur cette fonction uniquement. Notre commande funccount devient: funccount -p `pgrep java` "$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm".

[alarm@archlinux ~]$ sudo funccount -p `pgrep java` "$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm"
Tracing 1 functions for "b'/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm'"... Hit Ctrl-C to end.
^C
FUNC                                                  COUNT
b'_ZN15G1CollectedHeap22humongous_obj_allocateEm'     2571
Detaching...

2571 occurrences, soit autant d’objets humongous. Là on peut clairement confirmer que l’application a un problème. D’autant plus que je n’ai pas exécuté funccount pendant très longtemps.

Maintenant, pour avancer dans l’analyse, on va utiliser un autre outil: trace.

Trace

L’outil trace permet de détecter quel thread a appelé une fonction donnée. Il permet également de générer des stacktraces jusqu’à cette même fonction. On peut donc également l’utiliser avec _ZN15G1CollectedHeap22humongous_obj_allocateEm. Mais cette fois, on exécutera au préalable l’agent perf-map-agent pour que les stacktraces soient lisibles.

./perf-map-agent/bin/create-java-perf-map.sh `pgrep java`

Tout d’abord, exécutons simplement trace -p `pgrep java` "$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm".

[alarm@archlinux ~]$ sudo trace -p `pgrep java` "$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm"
PID     TID     COMM            FUNC
631     804     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
631     948     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
631     946     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
631     896     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
631     887     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
631     803     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
631     944     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
[...]

On peut se rendre compte que les allocations d’objets humongous sont effectuées par les threads HTTP différents, d’après leur identifiant (TID). Cette information peut nous aider dans le diagnostique, notamment si l’application en cause utilise des pools de threads dédiés à certaines tâches.

Allons plus loin et générons des stacktraces. La commande trace sera configurée pour n’en enregistrer que 10 (-M 10). Sans ce paramètre, on se retrouverait avec plusieurs milliers de stacktraces générées en continu dans le terminal.

Le listing ci-dessous n’en contiendra qu’une seule, pour garder un semblant de lisibilité.

[alarm@archlinux ~]$ sudo trace -Up `pgrep java` -M 10 "$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm"
[...]
PID     TID     COMM            FUNC
631     951     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
        b'G1CollectedHeap::humongous_obj_allocate(unsigned long)+0x0 [libjvm.so]'
        b'G1CollectedHeap::mem_allocate(unsigned long, bool*)+0x105 [libjvm.so]'
        b'MemAllocator::allocate() const+0x9a [libjvm.so]'
        b'TypeArrayKlass::allocate_common(int, bool, Thread*)+0xb8 [libjvm.so]'
        b'OptoRuntime::new_array_C(Klass*, int, JavaThread*)+0x33 [libjvm.so]'
        b'_new_array_Java+0x2a [perf-631.map]'
        b'Lorg/springframework/samples/petclinic/owner/OwnerController;::initFindForm+0x60 [perf-631.map]' (3)
        b'Interpreter+0x1500 [perf-631.map]'
        b'Lorg/springframework/web/method/support/InvocableHandlerMethod;::invokeForRequest+0x298 [perf-631.map]'
        b'Lorg/springframework/web/servlet/mvc/method/annotation/ServletInvocableHandlerMethod;::invokeAndHandle+0x58 [perf-631.map]'
        b'Lorg/springframework/web/servlet/DispatcherServlet;::doDispatch+0x32c0 [perf-631.map]'
        b'Lorg/springframework/web/servlet/FrameworkServlet;::service+0x1130 [perf-631.map]'
        b'Lorg/apache/catalina/core/ApplicationFilterChain;::internalDoFilter+0x1d4 [perf-631.map]'
        b'Lorg/apache/tomcat/websocket/server/WsFilter;::doFilter+0x68 [perf-631.map]'
        b'Lorg/apache/catalina/core/ApplicationFilterChain;::internalDoFilter+0x138 [perf-631.map]'
        b'Lorg/springframework/web/servlet/resource/ResourceUrlEncodingFilter;::doFilter+0x174 [perf-631.map]'
        b'Lorg/apache/catalina/core/ApplicationFilterChain;::internalDoFilter+0x138 [perf-631.map]'
        b'Lorg/springframework/web/filter/RequestContextFilter;::doFilterInternal+0x1538 [perf-631.map]'
        b'Lorg/springframework/web/filter/OncePerRequestFilter;::doFilter+0x464 [perf-631.map]'
        b'Lorg/apache/catalina/core/ApplicationFilterChain;::internalDoFilter+0x138 [perf-631.map]'
        b'Lorg/springframework/web/filter/FormContentFilter;::doFilterInternal+0x2f0 [perf-631.map]'
        b'Lorg/springframework/web/filter/OncePerRequestFilter;::doFilter+0x464 [perf-631.map]'
        b'Lorg/apache/catalina/core/ApplicationFilterChain;::internalDoFilter+0x138 [perf-631.map]'
        b'Lorg/springframework/boot/actuate/metrics/web/servlet/WebMvcMetricsFilter;::doFilterInternal+0x5dc [perf-631.map]'
        b'Lorg/springframework/web/filter/OncePerRequestFilter;::doFilter+0x464 [perf-631.map]'
        b'Lorg/apache/catalina/core/ApplicationFilterChain;::internalDoFilter+0x138 [perf-631.map]'
        b'Lorg/springframework/web/filter/CharacterEncodingFilter;::doFilterInternal+0x20c [perf-631.map]'
        b'Lorg/springframework/web/filter/OncePerRequestFilter;::doFilter+0x464 [perf-631.map]' (2)
        b'Lorg/apache/catalina/core/ApplicationFilterChain;::internalDoFilter+0x138 [perf-631.map]'
        b'Lorg/apache/catalina/core/StandardWrapperValve;::invoke+0x384 [perf-631.map]'
        b'Lorg/apache/catalina/authenticator/AuthenticatorBase;::invoke+0x538 [perf-631.map]'
        b'Lorg/apache/catalina/core/StandardHostValve;::invoke+0x4c0 [perf-631.map]'
        b'Lorg/apache/catalina/connector/CoyoteAdapter;::service+0x680 [perf-631.map]'
        b'Lorg/apache/coyote/http11/Http11Processor;::service+0x53c [perf-631.map]'
        b'Lorg/apache/coyote/AbstractProcessorLight;::process+0xac [perf-631.map]'
        b'Lorg/apache/coyote/AbstractProtocol$ConnectionHandler;::process+0x550 [perf-631.map]'
        b'Lorg/apache/tomcat/util/net/NioEndpoint$SocketProcessor;::doRun+0x1f8 [perf-631.map]'
        b'Lorg/apache/tomcat/util/net/SocketProcessorBase;::run+0xdc [perf-631.map]' (1)
        b'Ljava/util/concurrent/ThreadPoolExecutor;::runWorker+0x150 [perf-631.map]'
        b'Interpreter+0x17b3 [perf-631.map]'
        b'Interpreter+0x17f8 [perf-631.map]'
        b'Interpreter+0x17f8 [perf-631.map]'
        b'call_stub+0x8a [perf-631.map]'
        b'JavaCalls::call_helper(JavaValue*, methodHandle const&, JavaCallArguments*, Thread*)+0x3c9 [libjvm.so]'
        b'JavaCalls::call_virtual(JavaValue*, Handle, Klass*, Symbol*, Symbol*, Thread*)+0x1e5 [libjvm.so]'
        b'thread_entry(JavaThread*, Thread*)+0x6c [libjvm.so]'
        b'JavaThread::thread_main_inner()+0x1be [libjvm.so]'
        b'Thread::call_run()+0x10d [libjvm.so]'
        b'thread_native_entry(Thread*)+0xe7 [libjvm.so]'
        b'start_thread+0xdf [libpthread-2.30.so]'
[...]

En le lisant de bas en haut, on voit tour à tour Tomcat (1), Spring (2), et on finit sur une classe de PetClinic org.springframework.samples.petclinic.owner.OwnerController (3). Plus précisément, on voit que c’est la méthode initFindForm de la classe OwnerController qui a causé l’allocation mémoire. On n’a pas l’indication de la ligne en cause. Mais on sait que cette allocation mémoire est un tableau. Et qu’elle est faite directement dans le corps de la méthode initFindForm.

On peut maintenant aller modifier le code source de l’application pour régler le problème.

Pour finir sur cette commande, attention à bien utiliser trace sur du code optimisé par la JVM. Les outils BPF s’exécutent en dehors de la JVM. Ils peuvent inspecter une JVM en cours de fonctionnement mais ne sont pas aussi bien intégrés que des outils comme jstack. En particulier, lorsque le code Java est interprété, la commande trace ne produira pas de résultats satisfaisants. Le listing ci-après est ce que la commande "voit" lorsque le code est interprété. On avouera que Interpreter+0x17b3, c’est quand même pas très parlant…

545     748     http-nio-8080-e _ZN15G1CollectedHeap22humongous_obj_allocateEm
        b'G1CollectedHeap::humongous_obj_allocate(unsigned long)+0x0 [libjvm.so]'
        b'G1CollectedHeap::mem_allocate(unsigned long, bool*)+0x105 [libjvm.so]'
        b'MemAllocator::allocate() const+0x9a [libjvm.so]'
        b'TypeArrayKlass::allocate_common(int, bool, Thread*)+0xb8 [libjvm.so]'
        b'InterpreterRuntime::newarray(JavaThread*, BasicType, int)+0x20 [libjvm.so]'
        b'Interpreter+0x17399 [perf-545.map]'
        b'Interpreter+0x1500 [perf-545.map]'
        b'[unknown] [perf-545.map]'
        b'Interpreter+0x1500 [perf-545.map]'
        b'Interpreter+0x17b3 [perf-545.map]'
        b'Interpreter+0x1500 [perf-545.map]'
[...]

Argdist

Pour aller plus loin, je me suis ensuite intéressé à la commande argdist. Mais sans parvenir au résultat escompté. Cette section contiendra donc le résultat de mes recherches, et les questions restées en suspens.

Ma question est la suivante: quelle est la taille des objets alloués?

D’après sa signature, la méthode G1CollectedHeap::humongous_obj_allocate(size_t size) doit pouvoir nous fournir la réponse. Il suffit d’inspecter la valeur de son premier et unique argument. C’est exactement ce à quoi sert argdist.

Je sais que l’application allouait des tableaux de 250000 valeur de type long. Ceci devrait représenter environ 2 Mo de mémoire (2 000 000 d’octets, auquel on devra ajouter le header du tableau). Je m’attends donc à retrouver cette valeur.

Étant donné que j’utilise une JVM 64bits, le type size_t devrait correspondre à un nombre entier non signé codé sur 8 octets. Mais lorsque j’indique à argdist que le type du paramètre est un uint64, j’obtiens des valeurs aberrantes (environ 140 To).

[alarm@archlinux ~]$ sudo argdist -i 5 -p `pgrep java` -C "p:$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u64:size"
[19:30:56]
p:/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u64:size
	COUNT      EVENT
	31         size = 140652730090208
[19:31:01]
p:/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u64:size
	COUNT      EVENT
	38         size = 140652730090208
[19:31:06]
p:/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u64:size
	COUNT      EVENT
	38         size = 140652730090208

J’ai donc supposé que le type size_t corresponde à un nombre entier non signé code sur 4 octets, au lieu des 8 d’origine. Mais même si j’obtiens des résultats moins aberrants (environ 1.1 Go), ils sont toujours bien éloignés de la valeur attendue.

[alarm@archlinux ~]$ sudo argdist -i 5 -p `pgrep java` -C "p:$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u32:size"
[19:34:24]
p:/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u32:size
	COUNT      EVENT
	39         size = 1141080800
[19:34:29]
p:/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u32:size
	COUNT      EVENT
	39         size = 1141080800
[19:34:34]
p:/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm(size_t size):u32:size
	COUNT      EVENT
	38         size = 1141080800
[..]

Le livre "BPF Performance Tools" mentionne également plusieurs fois des conversions de Big Endian vers Little Endian. J’ai donc essayé de convertir les valeurs récupérées précédemment, mais sans parvenir à de meilleurs résultats. Si vous savez ce qui se passe, je vous invite à m’envoyer un message sur Twitter !

Stackcount

Pour finir, parlons d’un autre échec. La commande trace liste toutes les allocations, sans ordre ni regroupement. Dans l’application de test, il n’y a que 3 endroits dans le code où ces objets sont alloués. On peut donc facilement les cataloguer.

Dans une application plus volumineuse, les lieux d’allocations pourraient être bien plus nombreux. Il serait alors utile de pouvoir déterminer lequel est le plus fréquent pour le résoudre en priorité. C’est exactement ce pourquoi stackcount a été créé.

Malheureusement, je n’ai pas pu obtenir la moindre stacktrace lisible avec cet outil.

[alarm@archlinux ~]$ sudo stackcount -p `pgrep java` "$LIBJVM:_ZN15G1CollectedHeap22humongous_obj_allocateEm"
Tracing 1 functions for "/home/alarm/.sdkman/candidates/java/13.0.1.hs-adpt/lib/server/libjvm.so:_ZN15G1CollectedHeap22humongous_obj_allocateEm"... Hit Ctrl-C to end.
^C
  b'[unknown]'
  b'[unknown]'
  b'[unknown]'
  b'[unknown]'
  b'[unknown]'
  b'[unknown]'
[...]

Si vous parvenez à faire fonctionner cette commande, envoyez moi un tweet. Je pense qu’elle serait particulièrement utile dans ce cas de figure.

Conclusion

Les outils BPF sont décidément très versatiles. En comprenant plus précisément comment la JVM fonctionne, ils peuvent être utilisés pour diagnostiquer des problèmes ardus comme les allocations humongous. Même s’ils ont été initialement conçus pour des applications compilées (comme les applications C/C++), leur support de la JVM est déjà honorable. Nul doute qu’avec le temps ils deviendront encore plus utiles.

Vous connaissez d’autres méthodes intéressantes dans la JVM qu’il faudrait surveiller? N’hésitez pas à me les partager, cela donnera lieu à d’autres articles.

Si vous avez des questions ou voulez me faire part de vos commentaires, envoyez moi un tweet (@pingtimeout). Et si vous avez apprécié cet article et voulez soutenir mon travail, vous pouvez toujours m’offrir un café sur BuyMeACoffee ☕️.