GC, Segfault, Youpi

[Florian Dutey]

Salut a tous,

Apres 2 semaines au bord du suicide a buter sur une segfault, je m'en viens quemander du partage d'experience parmi vous.

Background: 

Nouvelle boite pour moi. Le mois dernier a ete consacrer a migrer notre appli de:

- rails 3.2.19 vers rails 4.2 (en passant par rails 4.0 et 4.1 au milieu pour rendre le process plus souple)

- ruby 2.0.0 vers ruby 2.2.1 (en passant par 2.1.5 au milieu)

Y'a 3 ans de dev dessus, beaucoup de legacy, et la suite sera de refactorer tout ca, splitter l'appli en 4 tiers etc..

Toute la migration s'est plutot bien deroulee, jusqu'a ce qu'on deploie en prod et que l'on voie apparaitre des exception sans aucun sens, disant que notre data contenait des false et des nil a des endroits completement illogiques (et qui disparaissaient immediatement quand on faisait on rollback de l'app). Et une derniere qui disait carrement qu'une string contenait un nullbyte.

En meme temps, on a constate sur newrelic que les instance unicorn redemarraient en boucle comme des malades, mais sans que la consommation de memoire ne bouge. La frequence etant trop elevee pour conclure a un leak, ou alors tellement massif qu'on n'aurait pas pu l'eviter en developement.

Apres 1 semaine a ne pas comprendre ces exceptions, a constater le caractere tres aleatoire de leurs apparitions, j'ai fait le postulat que c'etait des segfault. Il m'a fallu 2 jours de plus pour les faire apparaitre.

Evidemment le probleme est impossible a reproduire en environnement de developement. Meme en demarrant l'appli avec les parametres de production en local (ce qui est tres complique de plus a cause des CDN, des serveurs de cache etc..).

Nous n'avons toujours pas non plus reussi a le reproduire en console, donc nous avons un protocole assez nul pour reproduire l'erreur (spammer le serveur sur une action precise).

Nous avons tout de meme trouve un fix qui nous permet de ne plus avoir le probleme, mais ca ne resoud pas l'erreur qui est en dessous et qu'on n'arrive pas a identifier.

Le probleme:

J'ai d'un cote, un modele (Page) qui a une propriete "content". Il s'agit d'un JSON serialize, qui est plutot massif 90% du temps (legacy code). 

Au milieu un controller, qui fait trop de travail

Enfin, plusieurs vues parce qu'on utilise gon + jbuilder et un bon vieux template haml (legacy, ya un plan pour switcher en SPA avec Rails::API en backend)

Regulierement (environ 5% du temps), je me mange une segfault quand j'essaie d'acceder a la propriete "content" de mon objet Page. La variable ne contient plus rien, car elle a ete garbage collected, bien qu'etant toujours referencee pourtant.

Le caractere aleatoire etant quand est ce que GC a ete trigger. Il y a plusieurs "mauvais endroits" ou il peut etre trigger et cela resulte en des exceptions differentes (parce qu'on n'accede pas au meme clefs du hash, mais le principe reste le meme).

Le fix temporaire a ete de desactiver GC pour cette action (et 5 autres dans le meme controller qui ont un comportement similaire mais qui n'ont jamais fail, par precaution), au moyen de before_action et after_action (pas de OobGc donc).

Ca nous permet de faire tourner l'appli en prod mais le code "defectueux" le reste. Nous cherchons donc a comprendre et resoudre ce probleme une bonne fois pour toutes, mais nous n'avons absolument aucune idee de ce qui peut pousser GC a nous virer nos objets.

Le probleme est present en ruby 2.1.5 et en ruby 2.2.0 (et 2.2.1)

J'avais deja experimente un probleme similaire d'objets GCed alors qu'ils n'auraient pas du (ruby 2.2.0+ only):

define_method :"#{attr}=" do ... end dans un module pour AR acts_as like.

Quand je sauvais l'objet, AR#save activait le GC et tous mes writers disparaissaient de la table des methodes de ma classe (donc obj.respond_to?(:attr=) renvoyait false) et je me mangeais des NoMethodError. Le fix a ete de virer le : au debut de la string pour en faire une string qui sera transformee en symbol immortel par la suite.

Avez vous deja vu ce genre de choses? Je n'ai trouve personne qui pleurait sur google que GC degageait des objets absolument "vivants", alors que j'ai experimente le probleme 2x en 2 semaines.

Si vous avez deja vu ca, y'a-t-il une raison evidente que je loupe, et/ou un fix solide? 

Je suis aussi preneur de tout conseil qui pourrait m'aider a trouver l'origine de l'erreur.

Merci d'avance :)

[Olivier El Mekki]

Hello,

Bon courage !

Tu ne précises pas ton infrastructure, est-ce que vous êtes sur un seul serveur ? Plusieurs ? Est-ce un dédié ou des machines virtuelles heroku / ec2 ? (un pb hardware n'est pas à exclure dans le premier cas).

Également, est-ce que tu as une idée du niveau d'usage de ta ram au moment des fails ? (mais je doute que ce soit le pb, parce qu'une saturation de la ram se remarquerait pas des problèmes beaucoup moins isolés et spécifiques).

Tu mentionnes que les process unicorn restart en permanence, c'est généralement le signe d'une app rails qui n'arrive pas à booter. Que disent les log d'erreur d'unicorn, à ce sujet ? (c'est un fichier de log différent des logs standard rails, réglé en utilisant la directive `#stderr_path` dans la conf de unicorn).

Comment as-tu isolé les segfaults, et sur quel process se produisent-il ?

[Florian Dutey]

Merci Olivier. Je n'ai pas precise parce que dans un premier temps, je voulais savoir si quelqu'un avait experimente un probleme similaire (GC qui fait mal son boulot).

Mais puisque tu demandes, je vais ajouter ce que je peux:

Les serveurs (staging et production) sont hostes sur amazon EC2. nous utilisons docker, 2 hosts avec chacun 1 unicorn de 8 workers. L'OS est centOS (3.10.57-57.140.amzn1.x86_64). Pas de nginx mais un HAProxy au sommet qui balance sur les instances. Tout est virtualise donc peu de risque d'erreur materielle.

Une instance consomme en moyenne 300Mb de RAM, assez stable sur la duree, avec ou sans les erreurs. Au niveau du serveur lui meme, on est tres loin de prendre toute la ram. Sur la longueur, on est stable avec 15Gb d'utilisation (sans pics) sur 30gb dispo.

Pour rails cache et rack cache, on utilise elasticache (2 instances pour 1 appli), on a du redis qui traine un peu partout aussi, postgres (9.3) pour la bdd.

Les gems avec des extensions natives (sanitize, oj, nokogiri ...) sont toutes a jour, si besoin est de preciser.

Le process unicorn boote sans probleme. Les tests de stress sont assez violents, du coup, la segfault apparait souvent, ce qui fait redemarrer le worker qui la subit a chaque fois. C'est un mecanisme classique de unicorn, pas de gem speciale pour ca.

Merci pour le tips de std_err path au passage, nous n'avons pas de logs pour ca. Il m'a fallu 1 semaine pour decouvrir que c'etait une segfault justement parce que ni newrelic, ni logentries ne le detecte.

Pour voir la segfault, j'ai deploye le code de l'appli dans un repertoire separe sur le serveur d'application. J'ai demarre manuellement unicorn (environnement EC2 donc redis et elasticache peuvent etre contactes et toutes les variables d'env sont set) et lance les stress test pour enfin voir l'erreur.

Ce repertoire separe est sur une branche a part, donc je peux faire les modifs que je veux, je deploie tres rapidement en faisant juste un pull / unicorn et je peux modifier le code en live (ce qui est proche de l'impossible avec des dockers). Je fais tourner les stress tests a chaque fois. L'erreur apparait tres rapidement en general. 

Quand elle n'apparait plus, je lance les tests 500x pour etre sur. C'est impossible que 3 millions de requetes (3 en parallele) sur cette action ne genere aucun segfault (20 suffisent en general, 150 obtient une proba de 100%).

Je comprends pas specialement la question de "quel process". On essaie de lire une string qui n'existe plus (GC) et donc n'importe quelle function C va segfault. Ca peut etre :gsub, :initialize_copy (string) ou :dump (json), tout depend quand est ce que GC a nique son monde :p. Dans tous les cas, on reste dans le process unicorn, on n'en sort pas. 

--
--
Vous avez reçu ce message, car vous êtes abonné au groupe "Railsfrance" de Google Groups.
Pour transmettre des messages à ce groupe, envoyez un e-mail à l'adresse rails...@googlegroups.com
Pour résilier votre abonnement envoyez un e-mail à l'adresse railsfrance...@googlegroups.com
---
Vous recevez ce message, car vous êtes abonné au groupe Google Groupes "Railsfrance".
Pour vous désabonner de ce groupe et ne plus recevoir d'e-mails le concernant, envoyez un e-mail à l'adresse railsfrance...@googlegroups.com.
Pour obtenir davantage d'options, consultez la page https://groups.google.com/d/optout.

[Thibault Jouan]

On 2015-03-18 17:02:07 +0800, Florian Dutey wrote:
> Apres 1 semaine a ne pas comprendre ces exceptions, a constater le
> caractere tres aleatoire de leurs apparitions, j'ai fait le postulat que
> c'etait des segfault. Il m'a fallu 2 jours de plus pour les faire
> apparaitre.

Qu'as tu changé dans tes tests pour les « faire apparaitre » ?
D'expérience avec ruby soit tout se passe bien et tu as ton exception
écrite sur la sortie d'erreur, avec un code de statut de sortie de 1.
Soit en cas de segfault, tu as un rapport d'erreur généré par ruby
(sur la sortie d'erreur) différent des cas d'exception, le code de
statut de sortie ne sera pas 1, et ton noyau va logger l'erreur.

J'imagine que tu ne peux partager le code source responsable de
l'erreur, mais as-tu possibilité de nous copier au moins l'erreur ?
(éventuellement en « masquant » les chemins si confidentiel). Les
backtraces C et ruby devraient aider un minimum.

Quel est le code de statut de sortie que tu obtiens, et que log ton
noyau dans ce cas ?

> Evidemment le probleme est impossible a reproduire en environnement de
> developement. Meme en demarrant l'appli avec les parametres de production
> en local (ce qui est tres complique de plus a cause des CDN, des serveurs
> de cache etc..).
> Nous n'avons toujours pas non plus reussi a le reproduire en console, donc
> nous avons un protocole assez nul pour reproduire l'erreur (spammer le
> serveur sur une action precise).

C'est bien le même ruby utilisé dans les deux cas ? Compilé de la
même façon et sur la même plateforme ?

> J'ai d'un cote, un modele (Page) qui a une propriete "content". Il s'agit
> d'un JSON serialize, qui est plutot massif 90% du temps (legacy code).
>
> Au milieu un controller, qui fait trop de travail
> Enfin, plusieurs vues parce qu'on utilise gon + jbuilder et un bon vieux
> template haml (legacy, ya un plan pour switcher en SPA avec Rails::API en
> backend)
>
> Regulierement (environ 5% du temps), je me mange une segfault quand
> j'essaie d'acceder a la propriete "content" de mon objet Page. La variable
> ne contient plus rien, car elle a ete garbage collected, bien qu'etant
> toujours referencee pourtant.
> Le caractere aleatoire etant quand est ce que GC a ete trigger. Il y a
> plusieurs "mauvais endroits" ou il peut etre trigger et cela resulte en des
> exceptions differentes (parce qu'on n'accede pas au meme clefs du hash,
> mais le principe reste le meme).

As-tu également du code C dans cette appli ? Cela pourrait être un
appel free() ou similaire erroné côté C, qui est appliqué sur un autre
pointeur que celui souhaité. Ou alors le GC détruit légitimement un
objet, mais c'est la fonction qu'on a spécifié pour nettoyer l'objet
(si free() ne convient pas) qui fait quelque chose d'incorrect.

> Avez vous deja vu ce genre de choses? Je n'ai trouve personne qui pleurait
> sur google que GC degageait des objets absolument "vivants", alors que j'ai
> experimente le probleme 2x en 2 semaines.
> Si vous avez deja vu ca, y'a-t-il une raison evidente que je loupe, et/ou
> un fix solide?

Pas vu non plus d'erreur concernant le GC. Tu as bien vérifié que
nul part ton appli (une dépendance ?) ne modifie les paramètres du
GC ? Il s'agit bien d'un build ruby « officiel » (pas trop bricolé) de
ton OS ?

Les derniers soucis de segmentation fault que j'ai vu, c'est soit
ça : https://bugs.ruby-lang.org/issues/10685, soit dans 99% des cas
mon propre code :P

> Je suis aussi preneur de tout conseil qui pourrait m'aider a trouver
> l'origine de l'erreur.

À défaut de nous montrer le code, nous montrer au moins l'erreur :-)

--
Thibault Jouan

[Olivier El Mekki]

> Je comprends pas specialement la question de "quel process".

En fait, je me demandais si c'était le master unicorn ou un de ses 

workers qui segfaultait, d'une part, et si ça arrivait aussi par exemple 

dans des background jobs. J'avoue que je ne soumettrais pas ma phrase 

originale à un concours de clareté d'expression :)

Je n'ai pas eu de mauvaises expériences avec GC pour ma part, "it just 

works". Est-ce qu'il y a dans ton projet des particularités qui peuvent 

influer sur le global space, comme par exemple l'emploi de threads ?

[Florian Dutey]

> Qu'as tu changé dans tes tests pour les « faire apparaitre » ?

J'ai lance manuellement unicorn pour voir les logs des workers dans mon terminal et ne rien louper

> C'est bien le même ruby utilisé dans les deux cas ? Compilé de la même façon et sur la même plateforme ?

rvm install 2.2.1.

Cependant, en local nous sommes sur mac, en prod / staging nous sommes sur Docker hoste sur du amazon EC2 (centOS)

> As-tu également du code C dans cette appli ? Cela pourrait être un

> appel free() ou similaire erroné côté C, qui est appliqué sur un autre
> pointeur que celui souhaité. Ou alors le GC détruit légitimement un
> objet, mais c'est la fonction qu'on a spécifié pour nettoyer l'objet
> (si free() ne convient pas) qui fait quelque chose d'incorrect.

Non. Le seul code C provient de gems (sanitize, nokogiri, Oj ...)

> Pas vu non plus d'erreur concernant le GC. Tu as bien vérifié que
> nul part ton appli (une dépendance ?) ne modifie les paramètres du
> GC ? Il s'agit bien d'un build ruby « officiel » (pas trop bricolé) de
> ton OS ?

Il s'agit bien d'un build "officiel" de ruby. Je n'ai pas verifie qu'aucune gem ne modifie le GC (on a 180 gems, donc bon)

Normalement, notre appli ne le modifie pas du tout mais c'est une tres bonne question et je regarderai

> À défaut de nous montrer le code, nous montrer au moins l'erreur :-)

Je l'ai pas fait a la base parce que les segfault trace, c'est jamais interessant, et vraiment, je voulais pas specialement deranger quelqu'un en mode "aidez moi a debug", plutot "avez vous deja vu ca?".

https://gist.github.com/strikyflo/083ca08885e617d1124a

https://gist.github.com/strikyflo/00b9f49670c3332b2e94

https://gist.github.com/strikyflo/7f2160e078a1651081fd

Ce sont les 3 differentes segfault que j'obtiens (1.7mb chacune) en fonction de quand est ce que le GC est passe.

Le modele + controller, reduits a leur minimum en tests font ca:

https://gist.github.com/strikyflo/6c531a3803eda2367d03

Il me reste encore a savoir si c'est la vue qui fait tout peter: ya beaucoup (beaucoup ...) de haml, donc de nokogiri et cette derniere pourrait etre la responsable.

J'ai fait enormement de tests, donc le fait de ne pas avoir (encore) elimine la vue tient au volumes de tests sur les modeles et le controller. Et aussi l'enchainement de meetings pour decider des strategies a adopter vis a vis de ca (ya d'autres teams et des clients qui sont suspendu a cause de cette migration).

La decision a ete prise ce matin (heure chinoise) de rollback sur ruby 2.0.0 puisque le probleme n'existe pas dans cette version, pour pouvoir release quelque chose de stable (toutes les equipes sont en stand by pour la nouvelle version de rails depuis 3 semaines, ca complique enormement les process et les merge de stagner). Donc je vais pas travailler sur le probleme dans la semaine qui va suivre.

Je posais la question surtout pour savoir si quelqu'un avait deja experimente un probleme similaire et avait un bon hint a filer (ouais je sais, c'est une segfault, donc ca n'arrive jamais en vrai).

Si je trouve la solution, je n'hesiterai pas a partager par contre, au cas ou quelqu'un tombe dessus un jour :)

[Florian Dutey]

> En fait, je me demandais si c'était le master unicorn ou un de ses workers qui segfaultait

Clairement le worker, pas le master unicorn.

[Florian Dutey]

Pour ceux que ca interesserait, le probleme a finalement ete resolu: il s'agissait de la bonne vieille gem libxml-ruby qui etait en dependance d'une biblio d'un de nos fournisseurs.

J'ai evidemment cree une pull request chez eux pour les avertir de l'obsolescence absolue de cette pourriture.

J'en profite donc pour vous passer le message: si vous utilisez encore cette gem dans un de vos projets, essayez de la degager. Elle a la facheuse tendance a (re)definir la constante XML, ce qui fait que l'inclure dans un projet sans l'utiliser aura pour effet d'en faire le defaut pour toute gem qui considereraient que si XML est definie, cela veut dire que vous imposez votre parser (nokogiri par exemple), et donc de spread le probleme a peu pres partout.

A plus pour de nouvelles aventures :) 

[Tim]

Salut !
Merci pour ton retour.

Je me suis rendu compte en mode dev que j'avais une mega fuite de mémoire. (juste à chaque chargement de page....)

J'ai bien lu ton post, je suis en ruby 1.8, rails 2, et j'ai le gem libxml-ruby v2.8 dans le gemfile.lock.

Tu parles de constantes redéfinies, mon apply en définie des tonnes à plein d'endroit, et je vois pendant les tests le message "warning: already initialized constant MA_CONSTANTE" : que faut il éviter pour échapper à la fuite de mémoire lié aux constantes ?

Merci.

[Florian Dutey]

Procedons dans l'ordre:

1) Je n'ai aucune idee de ce qu'est "la fuite de memoire liee aux constantes". Ce n'est pas ce que je decrivais precedemment. 

Ce que je disais, c'est que libxml-ruby definit la constante XML et que cela modifie le comportement de beaucoup d'autres bibliotheques, meme si toi, developpeur, n'utilise jamais libxml directement.

Si tu inclus Oj (parser JSON) dans ton projet, il ne redefinit pas la constante JSON, ce qui fait que sa presence n'aura aucune incidence (a priori) sur le reste du code et n'affectera que les endroits ou tu appelleras explicitement Oj.

Dans mon cas, libxml etait une dependance d'une autre gem, donc pas une gem que NOUS avions ajoute nous meme (pour expliquer vaguement que c'etait un peu cache quoi). Aucune gem autre que la gem incrimine n'utilisait directement libxml mais le fait que libxml redefinisse la constante XML impactait d'autres parties du code. 

Il est possible aussi que libxml-ruby ait des consequence sur la compilation de nokogiri (les 2 gems sont liees historiquement et pour des raisons de nommages pourraient interferer ensemble).

2) Tu as libxml-ruby dans ton projet, debarasse-toi en. Elle n'est plus maintenue depuis longtemps et le code C est visiblement incompatible avec le GC pour sur de ruby 2+ (aucune idee pour 1.8 et 1.9).

Mais d'abord cherche a savoir pourquoi tu en avais besoin a la base. Si c'est pour nokogiri, ce n'est plus necessaire. Nokogiri embarque son propre libxml depuis longtemps. Si tu fais du parsing xml "a la mano", alors il existe d'autres gems tres sympa pour ca. Nokogiri, Ox ...

3) Si ton probleme de leak n'est qu'en mode dev, c'est moins critique qu'en prod. Tu devrais cependant verifier que ta prod est ok.

4) Si tu redefinis pleins de constantes a plein d'endroits, et ben... fixe le probleme et arrete de definir des constantes plusieurs fois :p

Pour chacune des constantes redefinie, cherche a savoir pourquoi elle l'est. Si c'est un probleme d'inclusion du meme fichier plusieurs fois, demmerde toi pour n'inclure le fichier qu'une fois (au demarrage?).

Si c'est necessaire, alors l'utilisation de constantes n'est pas approprie. 

De maniere generale, les constantes, c'est tres C et Java. Regarde ce que font les gems pas trop mal construites, en general, elles definissent un objet de configuration (https://github.com/plataformatec/devise/blob/master/lib/devise.rb#L281) plutot que l'utilisation de constantes qui posent probleme avec la portabilite du code.

A l'interieur d'un namespace, je preferere les mattr_reader au lieu des constantes, c'est plus sexy. Mais si tu penses que l'utilisation de constantes est approprie, fous les dans des namespace et interroge toi de la raison pour laquelle, au milieu de ton programme, tu ecris un truc du genre ClassName::CONSTANT = value.

Si c'est pour changer de maniere temporaire le fonctionnement de quelque chose, alors tu devrais considerer l'utilisation d'instance, ou de methodes avec un parametre (et une valeur par defaut pour le cas courant).

5) D'ou sors-tu le "probleme de fuite de memoire liee aux constantes"? C'est un probleme connu (sauf de moi) en Ruby ou je me suis mal exprime?

[Tim]

<< 5) D'ou sors-tu le "probleme de fuite de memoire liee aux constantes"? C'est un probleme connu (sauf de moi) en Ruby ou je me suis mal exprime? >>

Juste de ton texte que j'ai compris de travers :-)

Merci pour le détail pour libxml.