Debugging mémoire: quatre jours pour une ligne

Tout commence par un série de crashs de liquidsoap sur GeekRadio, causés par une pénurie de mémoire. Pendant quatre jours j'ai passé pas mal de temps à émettre des hypothèses, fausses pour la plupart, lire des analyses, mais surtout chercher des outils pour obtenir des analyses plus précises, pour finalement arriver à la fonction respondable et remarquer l'absence évidente d'une unique ligne de code.

La recherche de techniques de debugging aurait du être plus simple, j'ajoute donc un peu d'information utile dans la soupe, au cas où ça peut aider quelqun un jour...

Pour information liquidsoap est un logiciel de streaming audio programmé en OCaml, mais il utilise de nombreuses librairies interfaçant OCaml avec de fameuses librairies C comme Vorbis, Mad ou Shout. Dans un premier temps j'ai soupçonné un problème dans le tas Caml (les valeurs gérées par le garbage collector) pour finir par comprendre que c'était une bête fuite de mémoire dans le tas C (géré par malloc).

Ce n'est qu'à la fin de ce post que vient l'information la plus utile potentiellement. En effet j'y décris quelques techniques de débuguage avec le malloc standard GNU, qui sont peu connues à mon avis mais très pratiques.

exmap

Je ne m'attarderai pas sur cet outil car il est compliqué à mettre en place, puisqu'il repose sur un module du noyau linux. Je soupçonne que la plupart de ce que j'ai appris par gexmap était accessible dans /proc/$PID/maps ou autre. En plus ça m'a induit en erreur. L'outil nous a indiqué que ce n'est pas le tas qui explosait ([heap]) mais la mémoire anonyme ([anon]), et nous avons cru qu'il s'agissait du tas Caml. En fait, j'ai appris plus tard que le malloc() du GNU utilisait mmap() pour les "grosses" allocations ("largement plus" d'une page, soit 4092 octets typiquement), et les régions mmap()ées sont en fait ce qu'on appelle la mémoire [anon]nyme.

/proc/$PID/status

Sous linux ce fichier contient une description de l'état d'un processus. Les champs qui nous intéressent sont: VmSize, la totale de mémoire allouée au processus; et VmRSS, l'espace actuellement occupé par le processus dans la mémoire physique. La première valeur peut excéder la quantité de mémoire disponible, la mémoire allouée mais non accédée n'a en effet pas besoin d'être effectivement présente physiquement.

Mon erreur ici a été de tracer VmRSS, je crois. On obtient un graphe qui grimpe doucement, se stabilise progressivement, puis explose subitement. Je me suis conforté dans l'idée d'un défaut dans le tas Caml en interprétant cela comme un dérapage du garbage collector sur un tas corrompu. On s'aperçoit plus loin que le tas Caml n'a rien à voir là dedans, que le tas C croit progressivement sans raison. L'explosion du VmRSS est peut être dû à un rapatriement en mémoire physique d'un paquet de pages dû à un passage du GC, je ne sais toujours pas vraiment.

ocaml-memprof

Nous avons commencé par chercher un outil pour analyser le contenu du tas Caml. Quelques recherches m'ont mené à ce patch du compilateur initialement écrit par Fabrice Lefessant il y a bien longtemps, adapté et amélioré par je-sais-pas-qui pour ocaml-3.08.3 depuis, et enfin mis-à-jour pour la version 3.09 par Sam. Le patch se trouve donc maintenant ici et la doc là. Il y a peut-être encore quelques erreurs unused variable simples à corriger. La vraie difficulté est de comprendre comment utiliser la bête, la doc n'étant que très minimale.

D'abord, cela ne marche que pour le code natif. C'est marqué dans le README, mais il ne faut pas le rater car du bytecode tournera sans problème, dumpera ses images du tas, mais l'analyseur plantera avec une erreur des moins explicites.

Une fois le compilateur compilé, il faut l'installer. S'il n'est pas installé il ne trouvera pas ses librairies. Pour m'a part j'ai configuré avec --prefix /home/dbaelde/local. Ensuite j'ai écrit une config alternative ~/local/ocamlfind.conf, car j'utilise ocamlfind pour compiler liquidsoap:

ocamlc="/home/dbaelde/local/bin/ocamlc.opt"
stdlib="/home/dbaelde/local/lib/ocaml"
destdir="/dev/null"
path="/usr/lib/ocaml/3.09.2/METAS"

Pour l'utiliser il suffit d'exporter les bonnes variables d'environnement:

export OCAMLFIND_CONF=~dbaelde/local/ocamlfind.conf
export PATH=~dbaelde/local/bin:$PATH

Avec ça la version patchée de caml sera détectée pour les projets n'utilisant pas ocamlfind (toutes les libs de savonet), et ocamlfind l'utilisera aussi (pour liquidsoap).

Il ne reste qu'à lancer le programme Caml, qui fera appel régulièrement à Gc.dump_heap pour écrire un image du tas Caml sur le disque. Attention à ce que l'utilisateur qui lance le programme ait les droits d'écriture dans le répertoire courant, sinon ça plante violemment. Attention aussi à ne pas trop dumper, ça prend de la place. On obtient normalement des fichiers heap.dump.PID.N. On les compile en exécutant heapstats -heaps PID. Et on trace un joli graphe de tout ça avec hp2ps blocks_per_type.PID.hp et hp2ps sizes_per_type.PID.hp. On obtient deux postscript avec les graphes de l'évolution du nombre et de la taille cumulée des valeurs Caml, classées par type.

Pour liquidsoap, le graphe était très stable, aucune trace d'explosion.

GNU malloc

J'ai cherché des outils pointus pour avoir des statistiques sur l'allocation sur le tas C. J'ai trouvé des machins compliqués et d'autres qui ne marchent pas. Pour finalement me rendre compte que le malloc du GNU que j'utilisais déja avait tout ce qu'il me fallait!

Pour les statistiques mallinfo() donne plein d'information intéressante. La mémoire allouée au programme, la partie de cette mémoire qui est encore libre, la mémoire mmap()ée, etc. Ca m'a permis de rayer l'hypothèse de la fragmentation mémoire: en fait GNU malloc se comporte bien malgré l'utilisation frénétique qu'on en fait dans les bindings de Shout et Vorbis. Pour la petite histoire j'ai appellé mallinfo() depuis gcc, à l'aveuglette. Les champs de la structure mallinfo sont documentés dans /usr/include/malloc.h, ce sont tous des int, on peut donc y accéder sur une archi 32bits comme suit:

call mallinfo()
x/1dw $1 # Total space allocated from system
x/1dw ($1+16) # Mmap()ed space
x/1dw ($1+28) # Total allocated
x/1dw ($1+32) # Total free

Autant dire qu'à ce stade d'emmerdements je me sentais mériter d'en finir vite.

Mais la réponse est venue d'une analyse plus fine des allocations, permettant de remonter assez efficacement les fuites, toujours avec le GNU malloc standard. La fonction mtrace() permet en effet de stocker dans un fichier une trace de toutes les opérations mémoire effectuées. Un appel suffit et provoque l'ouverture du fichier indiqué dans la variable d'environnement MALLOC_TRACE, qui est mis à jour à chaque opération. Il prend rapidement beaucoup de place, attention donc.

Ensuite le programme mtrace analyse tout cela, et affiche à la fin les blocs non libérés. Si on lui donne le binaire responsable de la trace, compilé avec -g il associe un numéro de ligne aux allocations, ce qui permet de remonter aux allocations non nettoyées. Dans liquidsoap j'ai ainsi vu que de trop nombreux descripteurs de décodeurs Vorbis étaient alloués, alors que deux tout au plus devraient pouvoir exister à un instant donné. L'info était en fait même un peu plus précise que ça, en tout cas ça a permis d'en finir avec toutes ces histoires!