Duniter 1.2.5 | Fuite mémoire : la saga continue

cgeek · 29 May 2017 14:17

J’ai vérifié à nouveau sur mon serveur à 3 nœuds, la consommation mémoire continue d’augmenter. Je constate également que la heap JS n’augmente pas, elle. Donc c’est toujours un module C++ qui fuite.

Par ailleurs j’ai aussi recommencé à faire des tests bouclés, et je suis tombé là-dessus :

2017-05-29T16:00:18+02:00 - warn: Test 1/100000 usage = 139 MB
2017-05-29T16:00:20+02:00 - warn: Test 2/100000 usage = 139 MB
2017-05-29T16:00:21+02:00 - warn: Test 3/100000 usage = 141 MB
2017-05-29T16:00:22+02:00 - warn: Test 4/100000 usage = 142 MB
2017-05-29T16:00:23+02:00 - warn: Test 5/100000 usage = 144 MB
2017-05-29T16:00:24+02:00 - warn: Test 6/100000 usage = 144 MB
2017-05-29T16:00:25+02:00 - warn: Test 7/100000 usage = 145 MB
2017-05-29T16:00:26+02:00 - warn: Test 8/100000 usage = 146 MB
2017-05-29T16:00:27+02:00 - warn: Test 9/100000 usage = 148 MB
2017-05-29T16:00:28+02:00 - warn: Test 10/100000 usage = 148 MB
2017-05-29T16:00:29+02:00 - warn: Test 11/100000 usage = 149 MB
2017-05-29T16:00:30+02:00 - warn: Test 12/100000 usage = 150 MB
2017-05-29T16:00:31+02:00 - warn: Test 13/100000 usage = 151 MB
2017-05-29T16:00:32+02:00 - warn: Test 14/100000 usage = 152 MB
2017-05-29T16:00:33+02:00 - warn: Test 15/100000 usage = 154 MB
2017-05-29T16:00:34+02:00 - warn: Test 16/100000 usage = 155 MB
2017-05-29T16:00:35+02:00 - warn: Test 17/100000 usage = 156 MB
2017-05-29T16:00:36+02:00 - warn: Test 18/100000 usage = 157 MB
2017-05-29T16:00:37+02:00 - warn: Test 19/100000 usage = 158 MB
2017-05-29T16:00:38+02:00 - warn: Test 20/100000 usage = 159 MB
2017-05-29T16:00:39+02:00 - warn: Test 21/100000 usage = 161 MB
2017-05-29T16:00:41+02:00 - warn: Test 22/100000 usage = 162 MB
2017-05-29T16:00:42+02:00 - warn: Test 23/100000 usage = 163 MB
2017-05-29T16:00:43+02:00 - warn: Test 24/100000 usage = 165 MB
2017-05-29T16:00:44+02:00 - warn: Test 25/100000 usage = 166 MB
2017-05-29T16:00:45+02:00 - warn: Test 26/100000 usage = 167 MB
2017-05-29T16:00:46+02:00 - warn: Test 27/100000 usage = 167 MB
2017-05-29T16:00:47+02:00 - warn: Test 28/100000 usage = 170 MB
2017-05-29T16:00:48+02:00 - warn: Test 29/100000 usage = 170 MB
2017-05-29T16:00:49+02:00 - warn: Test 30/100000 usage = 171 MB
2017-05-29T16:00:50+02:00 - warn: Test 31/100000 usage = 173 MB
2017-05-29T16:00:51+02:00 - warn: Test 32/100000 usage = 173 MB
2017-05-29T16:00:52+02:00 - warn: Test 33/100000 usage = 175 MB
2017-05-29T16:00:53+02:00 - warn: Test 34/100000 usage = 177 MB
2017-05-29T16:00:54+02:00 - warn: Test 35/100000 usage = 177 MB
2017-05-29T16:00:55+02:00 - warn: Test 36/100000 usage = 179 MB
2017-05-29T16:00:56+02:00 - warn: Test 37/100000 usage = 179 MB
2017-05-29T16:00:57+02:00 - warn: Test 38/100000 usage = 180 MB
2017-05-29T16:00:58+02:00 - warn: Test 39/100000 usage = 182 MB
2017-05-29T16:00:59+02:00 - warn: Test 40/100000 usage = 182 MB
2017-05-29T16:01:00+02:00 - warn: Test 41/100000 usage = 184 MB
2017-05-29T16:01:01+02:00 - warn: Test 42/100000 usage = 185 MB
2017-05-29T16:01:02+02:00 - warn: Test 43/100000 usage = 187 MB
2017-05-29T16:01:03+02:00 - warn: Test 44/100000 usage = 188 MB
2017-05-29T16:01:04+02:00 - warn: Test 45/100000 usage = 189 MB
2017-05-29T16:01:05+02:00 - warn: Test 46/100000 usage = 190 MB
2017-05-29T16:01:06+02:00 - warn: Test 47/100000 usage = 191 MB
2017-05-29T16:01:07+02:00 - warn: Test 48/100000 usage = 192 MB
2017-05-29T16:01:08+02:00 - warn: Test 49/100000 usage = 193 MB
2017-05-29T16:01:09+02:00 - warn: Test 50/100000 usage = 195 MB
2017-05-29T16:01:10+02:00 - warn: Test 51/100000 usage = 196 MB
2017-05-29T16:01:12+02:00 - warn: Test 52/100000 usage = 197 MB
2017-05-29T16:01:13+02:00 - warn: Test 53/100000 usage = 197 MB
2017-05-29T16:01:14+02:00 - warn: Test 54/100000 usage = 200 MB

On observe clairement l’augmentation mémoire, à un rythme de (200 - 139) / 54 = 1,12 Mo / test.

Or ce test, c’est celui d’une synchro de piscine : le code prépare un paquet de données à envoyer, et fait notamment de nombreux tests de distance avec le module wotb. Aujourd’hui la synchro est très fréquente : 8 fois / heure / par nœud. Étant donné que les 8 requêtes sont réparties sur le réseau, on peut approximer en disant que chaque nœud reçoit 8 requêtes de synchro de piscine / heure. Soit 192 requêtes en moyenne par jour, ce qui donne environ +215 Mo / jour. On se rapproche des chiffres relevés dans nos graphes.

Cela peut également expliquer pourquoi la fuite peut être foudroyante comme plus lente : cela dépend des aléas de connexion à tel ou tel nœud pour effectuer la synchro.

Je continue d’investiguer, mais la piste me semble prometteuse !

Beun · 29 May 2017 14:35

Il y a d’autres modules c++ que celui lié à la WoT ou c’est toujours celui-là que tu soupçonnes ?

cgeek · 29 May 2017 14:36

C’est toujours celui-là, très clairement.

edit : et je pense avoir identifié la fuite !

cgeek · 29 May 2017 15:27

Je suis confiant, je vais directement faire une 1.2.6.

Détails du correctif

Le problème se produisait lors de l’appel à memcopy(), qui permet de se créer une WoT temporaire en mémoire dans laquelle on ajouter les liens présents en piscine, afin de faire des tests de distance car c’est l’une des données retournées :

https://github.com/duniter/wotb/blob/d85c3ecf89fa6279c87f56b2e1678a4e5542d60d/functions.cc#L67

Or pour cette copie, je faisais appel à la méthode getWoT() : cette fonction était censée retourner la WoT présente soit dans un fichier, soit dans la mémoire, puis le new MemoryWoT(...) d’en faire une copie pour nos futurs tests de distance avec les données de piscine.

Le problème est que, dans le cas du fichier, je créais 2 fois cette copie : 1 fois en chargeant le fichier avec getWoT(), 1 fois en faisant la copie effective avec new MemoryWoT(...). Or, je ne libérais pas celle chargée depuis le fichier, car structurellement j’en avais besoin.

J’ai donc écrit :

2 tests unitaires révélant cette fuite
1 commit correctif, renommant cette méthode getWoT() en cloneWoT() pour lui donner un rôle plus explicite, et lui laisser le soin de libérer la mémoire dans le cas du fichier, après avoir produit sa copie. Ainsi la mémoire est correctement allouée une fois, puis libérée une fois.

A noter que bien que la fuite existe depuis de nombreuses versions, c’est le volume d’appels déclenché par la synchronisation des piscines qui a permis de le révéler plus clairement, soit depuis la version 1.2.0.

Ouf !

elois · 29 May 2017 15:41

Félicitations, elle était dur à trouvée celle-ci !!!

florck · 29 May 2017 18:56

Chapeau !

cgeek · 13 June 2017 13:45

Du coup je vais arrêter mon envoi de stats, je crois même que le kibana est arrêté / en erreur.

florck · 13 June 2017 14:18

Oui, un pb de maj ! Mais les données sont stockées quand même, je vais les purger !

On pourra le remettre en place au besoin.