Memory leaks - HeadDump analysis - Dynatrace profiling

Request description

Memory leaks

Bonjour,
Nous sommes toujours en train d’avancer sur nos problèmes de fuites de mémoire. Le problème est toujours présent même si les plantages sont plus rares aujourd’hui.
Peut-être pouvez vous nous aiguiller par rapport à ce que nous remontent nos outils. Je vous le partage.

Nous sommes dans cette configuration de mémoire, depuis plusieurs jours:

Nous avons décidé de générer un heapdump
L’analyse via Memory Analyzer nous donne comme problème suspect numéro 1 la classe org.apache.tomcat.util.log.SystemLogHandler qui semble occuper 78% de la mémoire

Nous pouvons partager si nécessaire le dump.

Nous avons eu un pic hier vers 16H. J’ai regardé avec le profiler de Dynatrace ce qu’ils appellent les survivors, c’est à dire les objest qui ont servécu à un ou plusieurs de GC, et voici ce que j’obtiens:

Merci par avance de toute information que vous pourriez nous fournir.

Technical information

Instance /health

[Platform]
Status=OK
Version=5.1.22
BuiltOn=2021-12-29 12:44
Git=release/a4a4aafa93310ec3387ad178ae2001072320c3f3
Encoding=UTF-8
EndpointIP=172.20.54.195
EndpointURL=http://mla-api-6575469957-lhxnc:8080
TimeZone=Europe/Paris
SystemDate=2022-03-16 15:16:11

[Application]
ApplicationVersion=0.10
ContextPath=
ContextURL=https://app-mla.gke.ope.gcp.renault.com
ActiveSessions=17
TotalUsers=173
EnabledUsers=172
LastLoginDate=2022-03-16 15:16:01

[Server]
ServerInfo=Apache Tomcat/9.0.56
ServerType=WEB
ServerActiveSessions=55

[OS]
Name=Linux
Architecture=amd64
Version=5.4.144+
DockerImageName=centos7
SystemEncoding=UTF-8

[Disk]
DiskFree=36603
DiskUsable=36587
DiskTotal=96551

[JavaVM]
Version=17.0.1
Vendor=Eclipse Adoptium
VMName=OpenJDK 64-Bit Server VM
VMVersion=17.0.1+12
ScriptEngine=rhino
ScriptEngineVersion=Rhino 1.7.13 2020 09 02
HeapFree=813990
HeapSize=5242880
HeapMaxSize=14262272
TotalFreeSize=9833382

[Cache]
GrantCache=0
GrantCacheMax=0
GrantCacheRatio=0
ObjectCache=934
ObjectCacheMax=10000
ObjectCacheRatio=9
ProcessCache=16
ProcessCacheMax=10000
ProcessCacheRatio=0

[Database]
Vendor=3
ProductName=PostgreSQL
ProductVersion=11.13
DriverName=PostgreSQL JDBC Driver
DriverVersion=42.3.1
DBDate=2022-03-16 15:16:11
DBDateOffset=0
DBPatchLevel=5;P01;8eec3aaa281ce44b39212dcadbfe22cf
UsingBLOBs=true

[Healthcheck]
Date=2022-03-16 15:16:11
ElapsedTime=44

Simplicité logs
---paste the content of the **relevant** server-side logs---
Browser logs
---paste content of the **relevant** browser-side logs---
Other relevant information

----E.g. type of deployment, browser vendor and version, etc.----

Nous n’utilisons pas cette classe dans notre code. Nous n’utilisons d’ailleurs aucune classes en org.apache.tomcat.

De manière plus générale, nous utilisons Log4J pour les traces logs de la plateforme Simplicité (celles qui vont dans le simplicite.log via la classe logger AppLog). Certaines traces logs dans les phases initiales du démarrage de la webapp sont toutefois directement envoyées au default logger (car à ce stade il n’y a pas encore la configuration nécessaire au traces logs gérée par Log4J).

Dans nos images Docker nous livrons, au niveau de la webapp Simplicité, une configuration Log4J log4j2.xml en niveau “info” (cela exclut donc les traces plus verbeuses de niveau inférieur = “debug”).

S’agissant du default logger nous livrons une configuration logging.properties en niveau “FINE” qui n’est pas non plus le plus fin (sur ce logger il existe “FINER” et FINEST").

.

En première analyse je ne vois donc pas trop pourquoi les logs issues de Simplicité pourraient poser pb.

Pour aller plus loin il faudrait:

  • vérifier quel niveau de trace vous avez activé sur les log events de la plateforme (ex: si vous avez passé des event prévus pour être de niveau debug en info ça peut générer du volume mais au niveau Log4J)
  • vérifier quel nombre de traces logs vous avez mis dans votre code
  • regarder la taille des fichiers logs générés par Simplicité (/usr/local/tomcat/webapps/ROOT/WEB-INF/simplicite*.log) et par Tomcat (/usr/local/tomcat/logs/*) et dites nous si vous voyez des tailles anormales (i.e. > à qques Mb / fichier), si oui regardez quelles traces induisent ce volume.
  • etc.

FileTool.readFileByLine => ça correspond peut être à des usages de cette méthode dans vos traitements d’import de données ou autre code spécifique ? Si oui, il faudrait nous fournir le code en question qui utilise cette méthode pour qu’on regarde de plus près.

Sinon le seul endroit dans le code de la plateforme Simplicité où cette méthode est utilisée c’est dans l’outil legacy “log viewer”. Celui-ci est un outil de dev qui n’est absolument pas sensé être utilisé sur une instance en production, ou alors seulement très ponctuellement et quand il n’y a vraiment strictement aucun autre moyen plus normal pour accéder aux logs. Si vous avez un volume important de logs applicatives + un usage plus ou moins permanent de cet outil ça peut avoir des effets que je ne sais pas estimer…

1 Like

Comme @david je vois 2 pistes :

  • Instanciez vous des logger dans votre code sans passer par ceux du socle prévu à cet effet (via les méthodes static de AppLog) ?
  • Sur les reader persistants en mémoire, c’est peut être un oubli de fermeture des fichiers (ou input stream…) lors de vos imports après les readFileByLine ?

Il va falloir regarder de notre côté si le log “log viewer” legacy ferme bien ses ressources.

Le code du log viewer utitlise bien des “try with” sur les streams donc à priori pas de pb de resources laissées ouvertes.

Il y a juste a une petite piste d’optimisation sur le matching de l’expression régulière qui sera poussée dans le cadre de la prochaine révision 5.1.35.

En tout état de cause comme dit plus haut ce n’est pas un outil normal pour suivre les logs, surtout en production, c’est un outil pas optimal à n’utiliser que ponctuellement quand, vraiment, on ne peut pas faire autrement.

Bonjour,
J’ai récupéré le fichier log4J à partir du pod.
Ce que je constate c’est que le rootLogger est au level DEBUG.
Du coup SIMPLICITE-FILE et SIMPLICITE-CONSOLE sont en DEBUG.

SIMPLICITE-SESSION et SIMPLICITE-REDOLOG sont par contre en INFO.

            <Root level="debug">
                    <AppenderRef ref="SIMPLICITE-CONSOLE"/>
                    <AppenderRef ref="SIMPLICITE-FILE"/>
            </Root>

            <Logger name="SIMPLICITE-SESSION" level="info" additivity="false">
                    <AppenderRef ref="SIMPLICITE-SESSION"/>
            </Logger>

            <Logger name="SIMPLICITE-REDOLOG" level="info" additivity="false">
                    <AppenderRef ref="SIMPLICITE-REDOLOG"/>
            </Logger>

            <!-- JGit logging to info level -->
            <Logger name="org.eclipse.jgit.util.SystemReader" level="info"/>
            <Logger name="org.eclipse.jgit.util.FS" level="info"/>
            <Logger name="org.eclipse.jgit.internal.storage.file.PackFile" level="info"/>
            <Logger name="org.eclipse.jgit.internal.storage.file.FileSnapshot" level="info"/>

    </Loggers>

Avec cette configuration aucune trace de niveau debug (en tout cas celles gérées via AppLog) ne se retrouvent, par défaut, ni dans la console, ni dans le fichier. A ce niveau de log par défaut la plateforme ne génère que peu de logs.

Bien entendu, en production, le paramètre système LOG_DEBUG qui active globalement le niveau debug doit être à no => en production il ne faut jamais le mettre à yes sauf pour investiguer très ponctuellement un éventuel pb, en dev c’est pareil il faut éviter de le mettre à yes sauf quand on a besoin d’investiguer quelque chose plus en détail.

D’autres paramètres système ne doivent jamais non plus être activés en production : typiquement pas les LOG_SQL_USER et LOG_SQL_SYSTEM qui induisent des traces très verbeuses et qui n’ont d’utilité que très ponctuellement en dev.

Bref:

  • Vérifiez le paramétrage de vos params système `LOG_* mais le mieux c’est de regarder ce que contiennent les logs générées sur la console et dans les fichiers. Si le volume est anormalement élevé il faudra regarder de plus près quelles sont les traces en question
  • Vérifiez le niveau de trace de votre code spécifique et assurez vous qu’elles utilisent bien AppLog et pas un autre mécanisme de logging non prévu.
  • Vérifiez qu’il n’y a pas d’erreurs récurrentes dans votre code specifique qui induiraient des stacktraces énormes et en masse dans les logs
  • etc.

EDIT Sinon il y a toujours la possibilité d’inhiber le niveau debug de Log4J via une customisation de l’image, genre:

FROM simplicite/platform:<tag>
RUN sed -i 's/level="debug"/level="info"/g' /usr/local/tomcat/webapps/ROOT/WEB-INF/classes/log4j2.xml`

On verra éventuellement pour rendre ça forçable via une variable d’environnement si besoin.

PS:

Vous n’avez pas répondu sur notre supposition d’utilisation permanente du composant “log viewer”.

A nouveau celui ci n’est absolument pas conçu pour servir d’outil de suivi permanent des logs, à fortiori en production et à fortiori si le volume de logs générés est excessif.

Pour mémoire nous l’avons conservé dans la plateforme pour aider les développeurs car parfois l’accès aux logs via des canaux normaux (= accès direct sur le serveur, ou via la console du navigateur quand les websockets sont utilisables) est compliqué => c’est un outil “workaround” pour le dev, pas un outil “industriel” pour la prod

Dans les prochains images Docker (i.e. à partir de la 5.1.35) il y aura de nouvelles variables d’environnement pour customiser, si besoin, les niveau de trace des loggers de la webapp, cf. Simplicité® documentation/90-operation/docker

PS: J’attends votre confirmation sur votre usage du composant “Log viewer” car cela reste à ce stade la suspicion principale par rapport à votre pb (en dehors, bien sûr, d’un niveau de trace abusif dans votre code spécifique et/ou induit par votre paramétrage)

Salut David,
J’ai posé la question à l’équipe, j’attends leur retour. Je serai absent la semaine prochaine, je les laisse le soin d’animer ce topic. Merci déjà de vos retours.

cdt

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.