• Comment procéder ? • Notions & méthodologie • Etat des lieux rapide • Outils et diagnostic plus avancés • Zoom sur une JVM • Spécificités avec Docker • Scénarios • Surtout en ligne de commande • Sur Linux • Aperçu avancé … de surface • Pas un guide exhaustif • Pas un expert système • Pas de GIF
l’extérieur, typiquement un user • Orienté symptôme • Montre des problèmes en cours • Base de l’alerting (peut faire débat, selon l’actionabilité des remontées internes) • Boîte blanche : • Métriques exposées par l’intérieur du système • Orienté cause • Permet aussi de détecter des problèmes à venir, « signaux faibles » • Prérequis : système observable
est cassé et pourquoi, ex : • Erreurs sur page web utilisateur : job batch sur même machine qui sature le CPU • Latence webservice : fibre optique à nettoyer • En chaîne, une cause contribuant un souci sur la brique suivante … • Sur incident important • Rarement une seule root cause • Plutôt un ensemble d’éléments contributeurs
sur le premier graphe bizarre • Regarder les logs applicatifs et sauter sur le premier souci • Googler et appliquer le premier Stack Overflow • Blame someone else : pas ma faute, c’est le composant ... ou l’équipe … • Drunk man anti pattern • Streetlight anti pattern • Changer des settings au hasard et regarder
ce qui vous fait dire qu’il y a un problème ? • Est-ce que le système a déjà bien fonctionné ? • Qu’est ce qui a changé récemment ? • Qui est concerné, vous ou tout le monde? • Quel environnement : logiciels, matériels, versions, configuration, … ?
de l’application/SI • Du chemin des flux, leurs dépendances entre briques • Des chemins en lecture et en écriture dans les briques • De l’infrastructure sous jacente • Indispensable • Mais contradictoire à l’heure du cloud • Abstraction, « make it someone else problem »
• IOPS, throughput, utilization, saturation • Pour les ressources système (cpu, mémoire, disque, réseau, …) • Analyse de la charge : • Requests • Completion/errors • Latency • Bon vernis sur toutes les couches préférable : du système à l’applicatif • « Measure, don’t guess »
physique : CPUs, mémoire, disque, réseau, … • Et aussi logicielles : lock, thread pool, file descriptor, … • Vérifier : • Utilization : sur un intervalle de temps, le % de temps occupé à travailler • Saturation : > 100 %, même occupé, encore possible d’accepter du travail, la saturation définit à quel point cela n’est plus possible • Errors : nombre d’erreurs • Ne fournit que des pistes mais ferment pleins de mauvaises portes
utilisation peut masquer des pics de charge ou des saturations • Périmètre : • Qu’une sous partie des ressources matérielles ou virtuelles • On ne regarde par exemple pas souvent l’interconnect CPU • Connaissance : known unkowns, unknow unknows • Liste de ressources à vérifier et commandes associées : http://www.brendangregg.com/USEmethod/use-rosetta.html
• Pas pour les ressources système • Mode boîte noire (vue de l’extérieur) : • Rate : requêtes/s, séparer celles en succès et celles en erreur • Errors : … • Duration (latency) : temps de réponse, temps d’attente/queue inclus
golden signals : Latency, Traffic, Errors, and Saturation • « Intersection » de USE & RED • USERED : Utilisation, Saturation, Erreurs, Rate, Duration (Latency) • Comprendre les deux aspects : • Sollicitation utilisateur, service • Ressources et leurs comportements sur la charge • A adapter selon ce que l’on observe U R E D S
un serveur web : • Utilisation : selon le modèle (cnx/process, multi threadé, …), % de workers occupés • Saturation : MaxClients, erreurs 503 • Nb erreurs/s : parsing access logs, server-status, nb de 4XX, 5XX • Nb requêtes/s : idem depuis les logs, à affiner par contexte /uri/site/… • Latence : …, percentile, max
des profilers et méthodes d’analyse : surtout le temps on CPU • Pleins de raisons de ne pas être on CPU • Off CPU : perspective intéressante mais difficile à interpréter • On peut aussi travailler sur le wakeup • Pour bien faire, kernel récent > 4.0, voir > 4.8 pas des 2.6 ou 3.10, RHEL 7.6 en beta
: • Logs • Métriques • Traces • Health check • Plus : • Profiling • Scripts adhoc • Mais quand on est sur un serveur sans rien … et car on ne peut pas centraliser, historiser tout dans le détail => alerting
serveur, sur 1, 5 et 15 minutes • Qui est loggué (peut être aussi en train de faire des actions) • uname -srm • version du kernel • cat /etc/redhat-release ou /etc/lsb-release • version de l’OS • date • Vérifier qu’il n’y a pas un écart trop important avec la vraie date ou entre machines • Peut être très pénalisant sur des systèmes distribués • timedatectl • Sur systemd
cached … mais pas forcément mobilisable instantanément • Disponible -/+ buffers/cache avant RHEL 7 • Available depuis RHEL 7, ajouter -w pour avoir le détail buffer/cache • “Estimation of how much memory is available for starting new applications, without swapping. Unlike the data provided by the cache or free fields, this field takes into account page cache and also that not all reclaimable memory slabs will be reclaimed due to items being in use” • Swap : ca n’est pas parce used != 0 que cela swap, ca peut avoir swappé pour un vrai souci, ou juste le swappiness > 1
interpréter la charge • lscpu • Plus de détail sur la topologie processeur • Nombre de socket, core, hyperthreading • Fréquence • Nombre de nœuds NUMA dédier « partie de RAM » par socket • Attention sur VM : la description est …
un vue globale rapide de l’activité d’un serveur : cpu, charge, mémoire, swap, io • Ignorer la 1ère ligne • Souci si r très supérieur au nombre de core • Souci si ou so (swap in/out) différent de 0 • cs : souci si > 50 000 par core (voir pidstat …) • Colonnes cpu : • Activité CPU séparée en user, system, idle et iowait (stolen jamais valorisée) • Si wa important, attente sur disques (SAN compris), mais interprétation délicate (préférer PSI) • Si sy > 10-20%, possible souci, dépend aussi de l’activité user • -a : affichage partie active et inactive
M • Load average : indice sur la charge du serveur, dépend du nb de core (interprétation subjective) • %CPU process : 100% == 1 core • Switch H pour afficher les threads • Switch 1 pour le détail par core • Peut manquer des short-lived process • VIRT : mem virtuelle, non allouée physiquement ; souvent écart énorme avec RES (malloc per thread arena)
2 • Vue par process (filtre possible), par type de cpu, mémoire, IO, context switch (volontaire ou pas) • Pratique pour identifier qui est responsable de la consommation de CPU system • -t vue par thread • Context switch • 𝑐𝑠𝑤𝑐ℎ/𝑠 × 80 000 𝑛𝑏 𝑐𝑜𝑟𝑒 ∗𝑓𝑟é𝑞𝑢𝑒𝑛𝑐𝑒 𝐶𝑃𝑈 > 5% => possible lock contention (plus de 5% des cycles d’horloges passés sur du ctx switch) • nvcswch/s : indice de surcharge • Ex plusieurs pid : $(pidof postgres | sed -e 's/ /,/g') • %cpu exactement à 100% erroné parfois observé sur VM
écriture et lecture en Mo/s • Souci si await > 1000 ms • Souci « potentiel » si %util 100% (100% du temps à écrire) • « Indication » de random si : • nombre élevé de rrqm/s ou wrqm/s • beaucoup de r/s et/w/s pour peu de rMB/s ou wMB/s • petite taille de requests (avgrq-sz) • Sur VM, correspondance fs • ls -l /dev/disk/by-id
sortie • Aussi nicstat et bwm-ng (taper +) • ethtool <interface> • Vitesse de la « carte » /sbin • ip -s l • mtu : vérification jumbo frame à 9000 pour gros débit, 1500 sinon /sbin
réel • netstat -s | egrep -i "drop|error|loss|low|over" • Erreurs réseau depuis le boot • Dépréciée • nstat • Remplaçant de netstat • Diff depuis dernière exécution par défaut • Nom de métriques « moins friendly » /usr/sbin
LISTEN, ESTABLISHED … SYN_SENT, … • Arguments • -l : state LISTEN • -r : résolution DNS • -o : info timer • -p : info process (mais lent et coûteux sur RHEL6 par rapport à netstat -antup) • -i : interne TCP • Filtre possible, ex : • ss -utan state connected src :5432 • ss -o state fin-wait-1 '( sport = :http or sport = :https )' dst 193.233.7/24 /usr/sbin #root
sous arborescence • locate <un_fichier> • Localise un fichier/pattern • S’appuie sur une DB locale mlocate.db • Mise à jour via updatedb souvent croné • Attention à l’impact au passage de updatedb • Possible de pruner des arborescences dans /etc/updatedb.conf
Exemple avec /tmp : /etc/security/namespace.d/namespace_XXX.conf • Depuis un user confiné, on conserve l’isolation avec sudo su - • Visibilité d’un user confiné
findmnt • SELinux • Quel mode : getenforce • Contexte de sécurité des fichiers : • ls -Z • Champs : utilisateur:rôle:type:niveau • Contexte de sécurité des processus : ps -Z • Outil setroubleshoot-server peut aider à diagnostiquer les erreurs SELinux (mais bcq de dépendances) : sealert -a /var/log/audit/audit.log
: fichiers, sockets, ... • Attention au fichier supprimé mais non libéré : file descriptor “deleted” lsof +L1 : identification rapide des coupables • lsof sans argument : aussi les threads enfants, pas le cas avec -p <pid> • [-i :<port>] : qui écoute sur tel port • sar -v • inode, file … • Ports locaux déjà utilisés et bloquent le start de process, utiliser le setting restreignant la page : • Setting sysctl : net.ipv4.ip_local_port_range = <debut> <fin> /usr/sbin #root
A faire tourner en daemon et avec historisation (légère empreinte CPU au moment de la collecte) • Indispensable pour le post mortem • Ne pas oublier le module kernel pour avoir le réseau par process • Attention, atop est responsable du flush et rotation d’un fichier alloué par un module kernel. Si atop est tué, ce fichier va grossir dans /tmp … #root
fréquence • cat /proc/cpuinfo model name : Intel(R) Xeon(R) CPU E5-2440 0 @ 2.40GHz cpu MHz : 1200.000 • Nombre de threads d’un process • cat /proc/<pid>/status | grep Thread • Scheduler d’IO par disque • cat /sys/block/sdc/queue/scheduler • Indice de contention mémoire • cat /proc/vmstat | grep nr_vmscan_write • Page dirty du cache OS à écrire • cat /proc/meminfo | grep Dirty • Ou via le plugin vmem de collectd
mpstat est à 0 • Le time accounting dans le kernel (option à la compilation) n’est peut être pas activé • Les temps %usr %sys %idle peuvent donc être erronés • Vérifiable avec : grep IRQ_TIME_ACCOUNTING /boot/config-* • Le grep peut être vide et pourtant, c’est bien compté • Vérifier avec /proc/stat
threads dans l’état R (Runnable) ou D (Uninterruptible sleep) • git clone https://github.com/tanelpoder/0xtools • make && make install (pour psn, script et repertoire lib suffisent) • psn -G syscall,wchan,filenamesum -d 10 -r • -kstat pour ajouter la stack kernel
scannées par s, indice de contention • %vmeff mesure intéressante de l’efficacité de la recuperation de page mémoire • Higher is better, “volé” avec succès depuis les inactive • Bas <30% : système en difficulté
Selon la version kernel, en plus : LazyFree ShmemPmdMapped Shared_Hugetlb Private_Hugetlb SwapPss THPeligible • Sur une JVM RSS=Size si -XX:+AlwaysPreTouch • Valeur > 0 sur Inode, address range avec un fichier derrière, si 0 allocation mémoire requise par l’application • [heap] : c’est la native Java heap d’une JVM • 16 KiB sans permission (---p) suivi de 1012 KiB (peut être 1028) avec rw-p : c’est un thread Java • Pour aider à identifier les files mappings : pmap -X <pid> | head -n -2 | awk '{ if ($5 >0 ) printf "%12s %8s %8s %4s %s\n", $1, $6, $7, $2, $13 }‘ • Cet outil peut aider https://github.com/bric3/java-pmap-inspector #root
KiB) • Virtuelle, résident, pages backed by file + shared memory, … • On retrouve bien : 1007776 * 4 = 4031104 • Nombre de pages backed by files ou shared memory : 1540 * 4 = 6160 • Resident set size des memory mapped files in KiB, sans inclure les shared pages qui ne sont pas file backed.
fichiers • Classe du lock : FLOCK ou POSIX (system call fcntl, lockf) • Type de lock : ADVISORY possible d’accéder au fichier mais pas d’autres locks ; MANDATORY pas d’autres accès • READ ou WRITE • PID du process qui tient le lock • Identifiant du fichier locké MAJOR-DEVICE:MINOR-DEVICE:INODE-NUMBER • Début et fin du fichier locké
• Souci si < 300 bytes • Selon la source /dev/random (kernel < 4.8) ou /dev/urandom, comportement bloquant pour l’appelant • Parfois nécessaire d’installer un générateur tiers, type haveged • Le daemon rngd peut aider sur des processeurs avec l’instruction rdrand
process, la mémoire, … • "too many open files", "unable to create new native thread", … • Utilisateur courant • sudo -u <user> sh -c "ulimit -a" • Attention, avec systemd, les /etc/security/*** ne sont pas pris en compte Configuration par service à faire (LimitNOFILE, LimitNPROC, …)
VM ? • Manière de gérer la sur-allocation de mémoire dans un ESX • Mémoire totale allouée à une VM en réalité non disponible totalement • Souci si différent de 0 Mb • Catastrophique sur une JVM
pression » sur mémoire, CPU et IO • Plus fin et simple que la load average Ne dépend pas du nombre de core et c’est real time • Meilleur sur l’iowait • Kernel > 4.20 (plus tôt si backport) • Parfois (RHEL 8) à activer en ajoutant psi=1 à GRUB_CMDLINE_LINUX dans /etc/default/grub, puis grub2- mkconfig -o /boot/grub2/grub.cfg • cat /proc/pressure/cpu|memory|io • En watch : watch -n .1 grep . /proc/pressure/* • some : % de temps, un ou plusieurs tasks ayant subi une latence durant les 10, 60, 300 dernières secondes ; c’est du wallclock time • full : idem mais pour toutes les tasks • total : temps total en microsecondes
Freaking DNS problem") • dig +search <hostname> (query time intéressant) • reverse DNS : dig -x <ip> • A vérifier : • primaire en premier sur le même site • sinon latence inter-site et retry • Alignement DNS et reverse DNS : cause souvent des problèmes sur les systèmes distribués • Si dig n’est pas installé : nslookup <host|ip>
overhead • tcpdump -w <trace.pcap> <filtres> • [-i <une_interface>] • Si beaucoup de « packets dropped by kernel », les options suivantes peuvent aider : • [-nn] : pas de résolution de nom, de protocole • [-B 4096] : taille du buffer • [-s 68] : ne capture pas le paquet entier • Filtres : • Port(s) : port <un_port> • Envoyé ou reçu par une IP : host XXX.XXX.XXX.XXX • Envoyé par une IP : src host XXX.XXX.XXX.XXX • A destination d’une IP : dst host XXX.XXX.XXX.XXX • Combinaison : 'src XXX.XXX.XXX.XXX and|or|not dst XXX.XXX.XXX.XXX' #root
• Sur la cible : iperf3 -s • Sur le client : iperf3 -c <hostname_cible> -t 60 -O 2 -Z -P 8 -w 2M -l 512K • La fenêtre w peut nécessiter quelques sysctl comme sysctl net.core.rmem_max et net.core.wmem_max • Tester les jumbo frame (MTU 9000) : ping -M do -s 8972 <host>
<host>:<port> • peut nécessiter -CAfile avec la chaîne à truster • se méfier également par rapport à un browser du SNI, donc ajouter éventuellement -servername <host> • Vérifier SAN (Subject Alt Name) • | openssl x509 -noout -text | grep DNS: • testssl.sh • https://codeload.github.com/drwetter/testssl.sh/zip/3.0.4 • ./testssl.sh <host>:<port> docker run --rm -ti drwetter/testssl.sh <host>:<port> • Sortie claire et lisible • Test des versions de SSL, TLS et cipher suite • Test session resumption • … • Test de certaines vulnérabilités • Quels ports ouverts ? • nmap -sS -sV -T2 <host>
• Overhead très important • strace -s 64000000 -T -v -ttt -o strace.log -fp <pid> • strace -fc -p <pid> • Statistiques sur les syscall • Possible bug sur les durées en seconds • perf trace -p <pid> • Trace aussi les pages fault • Appels aux librairies : ltrace
par cpu • Analyse IPC : sur du physique ou virtuel si exposé (vPMC sur ESX) • If your IPC is < 1.0, you are likely memory stalled, and software tuning strategies include reducing memory I/O, and improving CPU caching and memory locality, especially on NUMA systems. Hardware tuning includes using processors with larger CPU caches, and faster memory, busses, and interconnects. • If your IPC is > 1.0, you are likely instruction bound. Look for ways to reduce code execution: eliminate unnecessary work, cache operations, etc. CPU flame graphs are a great tool for this investigation. For hardware tuning, try a faster clock rate, and more cores/hyperthreads. • Plus de core ou plus rapide pas forcément utile #root
du CPU • Visualiser rapidement le comportement d’une application (on-cpu) • Axe Y : stack d’appel, feuille en haut et on-cpu, thread en bas • Axe X : tri alphabétique, la largeur dépend du temps passé (nb de samples) • Couleur random (ou pas) • Linux 2.6.x • perf record -F 99 -a --call-graph dwarf -- sleep 10 • git --depth 1 clone https://github.com/brendangregg/FlameGraph • perf script [-i perf.data]| ./FlameGraph/stackcollapse-perf.pl | ./FlameGraph/flamegraph.pl > perf.svg • Linux 4.9+ • git clone --depth 1 https://github.com/brendangregg/FlameGraph • git clone --depth 1 https://github.com/iovisor/bcc • ./bcc/tools/profile.py -df -F 99 10 | ./FlameGraph/flamegraph.pl > perf.svg #root
• Stats : attention, une moyenne cache les outliers, moyenne de moyenne, de percentiles, … • CPU : • Bon ou mauvais : si beaucoup d’IO wait, plus de CPU ne sert à rien • % CPU IO wait : comparaison délicate, élevé peut être car disques très lents ; charge consommant énormément de CPU user, masquant les IO wait • Si CPU en attente de mémoire, plus de CPU ne sert à rien • Compréhension délicate, parfois pas de doc outre les sources du kernel • Outillage à installer partout, par défaut (qq exceptions sécurité)
more you know, the more you don’t know". It’s the same principle: the more you learn about systems, the more unknown unknowns you become aware of, which are then known-unknowns that you can check on.
: • RED • Niveau système : • USE method sur CPU, RAM, IO … • Qu’est ce qui « domine » : CPU user, system, iowait, idle ? • Oriente très vite les analyses • Niveau JVM : • GC, thread, JIT … • Niveau applicatif : • Algo en premier, thread/pooling, lock • Bas niveau • Cache CPU, alignement, miss, … • Processus d’analyse complet (conférence d’Aleksey Shipilev et Kirk Pepperdine)
thread dump • freeze la JVM un court instant • kill -3 • sortie dans /proc/<pid>/fd/1 • jstack fonctionne aussi mais d’expérience, pas sur une JVM mal en point • ou jcmd <pid> Thread.print -l -e > <un_fichier> • corrélation consommation cpu • a noter que jcmd ne sait pas rentrer dans les namespaces Linux avec des versions anciennes comme JDK 8 (et 11 mais pas certain) • top -b -H -n 1 -p<pid> | head -15 • printf "%x\n" <tid> • Recherche dans le thread dump de "nid=0x…"
: jvm-tools • https://github.com/aragozin/jvm-tools • Top thread, allocation, cpu user et system • GC • A installer sur toutes machines hébergeant une JVM • [sudo -u <user>] java -jar sjk-plus-<version>.jar ttop -o CPU -n 10 -p <pid>
heap dump • Freeze potentiellement très long, voir impossible • Plusieurs moyen de le déclencher : • Sur OOM avec -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=… • En JMX • Avec jmap -dump:format=b,file=<dump.hprof> <pid> • Avec jcmd <pid> GC.heap_dump <full_path_dump.hprof> • Avec core dump, très rapide à générer mais nécessite gdb et la JVM qui faisait tourner le process • gdb --pid=<pid> • gcore <coredump.core> • detach • quit • Java < 9 # jmap -dump:format=b,file=<dump.hprof> java <coredump.core> • Java > 9 # jhsdb jmap --exe <java> --core <coredump.core> --binaryheap --dumpfile <dump.hprof> • Sur JVM ko, coredump et kill la JVM : kill -6 • De préférence avec la même version du JDK que la cible • Attention à ne pas faire swapper ou « oomer » la machine en écrivant dans /dev/shm • Parfois impossible à lire • À analyser avec Eclipse MAT
NativeMemoryTracking • -XX:NativeMemoryTracking=summary ou -XX:NativeMemoryTracking=detail • jcmd <pid> VM.native_memory summary|detail • Détection leak : jcmd <pid> VM.native_memory baseline et summary.diff|detail.diff • Overhead de perf de 5 à 10% • Uniquement les allocations depuis l’intérieur de la JVM Pas les MappedByteBuffers (fichiers memory mappé en mémoire virtuelle, via FileChannel.map) • Possible de rapprocher ces résultats (pour le détail) avec le contenu du fichier /proc/[pid]/smaps qui liste les pages mémoires allouées par le process ou pmap -x <pid> • NMT will shut itself down when it detects low resource conditions, such as when running low on native memory. Sometimes that may be the situation when you would really want the data! This is the flag to disable auto shutdown: -XX:-AutoShutdownNMT
+ overhead) • Souci si beaucoup de deallocated • Virtual space : bien du virtuel et pas du resident • 1GB de reserved si pas de MaxMetapaceSize • MaxMetaspaceSize : limite haute de • Compress class space • Metaspace
être nécessaire de limiter : -XX:MaxDirectMemorySize Attention à -XX:+DisableExplicitGC, cela semble utilisé dans la réclamation des DirectByteBuffer, au besoin avec le CMS, plutôt utiliser ExplicitGCInvokesConcurrent & ExplicitGCInvokesConcurrentAndUnloadsClasses • Pour les I/O avec Java NIO, les non-direct ByteBuffers utilisent des DirectByteBuffers temporaires par thread Pas de limite par défaut, forte utilisation possible de mémoire native Limite de DirectByteBuffers par thread (>1.8.0_102) : -Djdk.nio.maxCachedBufferSize Permet seulement d’éviter la mise en cache et réutilisation de buffer plus grand que la limite. • Sur le NMT, avant Java 11, la zone Internal incluait les DirectByteBuffers, après c’est comptabilisé dans la zone Other. • Allocator glibc peut allouer n core * MALLOC_ARENA_MAX * 64M MALLOC_ARENA_MAX = 8 par défaut Identifiable en voyant des blocs mémoire de 65536 sur un pmap 2 ou 4 peut aider, mais à tester, performance comprise
(utile pour avoir des adresses contiguës) avec nmap ou malloc, mais garantie sans mémoire physique derrière (PROT_NONE) • Commited : mapped (autre que avec PROT_NONE) mais pas forcément avec mémoire physique derrière Donc resident peut être inférieur à commited. • Resident : actuellement en mémoire physique • Virtual : somme de tous les mappings, pas significatif sur une JVM • Différence entre le total NMT et RSS vu par l’OS peut être due à de l’allocator malloc (et arena) : allocation d’objets de taille différente, GC, fragmentation
vue sur les chemins d’allocation mémoire • Peut être utilisé en production (~2% avec beaucoup de malloc) • https://github.com/jemalloc/jemalloc/releases/latest Doit être buildé avec --enable-prof Installer graphviz export LD_PRELOAD=/usr/local/lib/libjemalloc.so export MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:17,prof_prefix:<dump_path>/app java -jar ... jeprof --show_bytes --svg /path/to/java app*.heap > memory-profiling.svg • % de mémoire référencée par la JVM : osmalloc@... os:malloc doit être à 98-99% • « Ne voit pas » le code compilé/jitté
en production • JDK8: -XX:+PrintGCCause -XX:+PrintGCDetails -XX:+PrintTenuringDistribution -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 - XX:GCLogFileSize=10M -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -Xloggc:<un_fichier> • JDK9+ : -Xlog:gc*,gc+age*=trace,safepoint:/app/log/gc-%p- %t.log:t,level,tags:filecount=10,filesize=10M • Quelques évidences visuelles ou greppable comme le « failure » de « (concurrent mode failure) », le « failed » de « (promotion failed) » ou le « Metadata GC Threshold » • Sinon via un outil comme gceasy.io, GC Log Viewer ou Censum (commercial … Microsoft) • Via jstat -gc <pid> 2s
Durée et fréquence • Bloquant ou pas • Concurrent ou pas • Multithreadé • Points d’attention • Taille du Live data set, des espace (Young : eden + survivor), Old, Perm|Metaspace • Allocation rate et taille récupérée • Premature promotion • Cause des GC • …
Total time for which application threads were stopped: 0.1202298 seconds, Stopping threads took: 0.0008189 seconds 2020-02-29T15:54:41.217+0100: 347584.527: Application time: 0.0011745 seconds • « thread were stopped: xx seconds » • En théorie xx == real • Si pause sans GC, investigation nécessaire • -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 (std out et déprécié JDK 11+) -Xlog:safepoint+stats=debug (à partir JDK 13) • « Stopping thread took: xx seconds » • Le GC doit attendre que les threads soient dans un état bien défini, un safepoint • Temps pour que tous les threads atteignent cet état • Pas toujours du à un GC stop the world, mais aussi heap dump, deop, … • Facteur agravant : bcq de page fault, trop de thread comparé au nombre de core et context switch, counted loop avec gros calcul • Diagnostic : -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=100
• Beaucoup d’autres outils : • Détail sur le JIT • Classloader et hiérarchie • Activation de flags • VM.info : beaucoup d’informations en une commande • Flight Recorder • Démarrage JMX : jcmd <pid> ManagementAgent.start config.file=<path.to.file> • …
: défauts, surcharge et ergonomics • java -XX:+PrintFlagsFinal -XX:+UnlockDiagnosticVMOptions -version • | grep ':=' valeurs modifiés manuellement ou par les ergonomics • jcmd <pid> VM.flags -all • Mais n’affiche pas tout … • Depuis le JDK11, c’est encore plus clair, on sait si c’est la « command line », les « ergonomics », … • Plusieurs sites avec la liste complète par version … https://chriswhocodes.com/hotspot_options_jdk11.html
au flag systemd PrivateTmp avec pour conséquence une localisation du hsperfdata exotique : /tmp/systemd-private-xxx-elasticsearch.service- xxxx/tmp/hsperfdata_elasticsearch/ • Utile pour browser facilement le tmp en question : nsenter -t $(systemctl show --property=MainPID --value elasticsearch.service) -m ls -la /tmp
diagnostic, attachement live (nécessite telnet) • http://repository.sonatype.org/service/local/artifact/maven/redirect?r=central- proxy&g=com.taobao.arthas&a=arthas-packaging&e=zip&c=bin&v=LATEST ./as.sh • Certains nombres de commandes accélérant le diagnostic
fichier hs_err_pid<pid>.log (chemin customisable via -XX:ErrorFile) qui contient pleins d’informations intéressantes pour le diagnostic • Doc Oracle : • The operating exception or signal that provoked the fatal error • Version and configuration information • Details on the thread that provoked the fatal error and thread's stack trace • The list of running threads and their state • Summary information about the heap • The list of native libraries loaded • Command line arguments • Environment variables • Details about the operating system and CPU • Un fichier core peut aussi être généré
futur • MBean JMX sans plugin • GUI jcmd • FlightRecorder • Fantastique outil • Utilisable en production et en continu • Utilisable en ligne de commande • Allocation/lock/exception/safepoint • Opensourcé depuis JDK 11 (commercial sur JDK 8 mais backporté 8u262) • Builds officiels http://jdk.java.net/jmc/ ou officieux https://builds.shipilev.net/jmc/ • Accounting du profiling est erroné et profiling arrayCopy() impossible
overhead max • profile : collecte plus de données, overhead plus grand • custom.jfc : via JMC Flight Recording Template Manager • Possible au démarrage de la JVM -XX:StartFlightRecording=settings=default|profile,duration=12m,name=record,filename=record.jfr avec un délai : delay=5m • Sur une durée : jcmd <pid> JFR.start duration=30s settings=default|profile filename=record.jfr avec un settings custom : settings=<full_path_vers_jfr> • La commande JFR.start renvoie un name=<id> Il sert aussi sur le JFR.stop name=<id>
JFR.start maxsize=500MB settings=default|profile • Repository par défaut temporaire : java.io.tmpdir • -XX:FlightRecorderOptions=repository=<path> • ou jcmd <pid> JFR.configure repositorypath=<path> stackdepth=96 • Nom du path : date_heure_pid ; donc change à chaque restart • Ecrit des chunks de 12Mo ou plus • S’accumule jusqu’à maxsize • Dump régulier possible jcmd <pid> JFR.dump filename=record-$(date +%Y%m%d%H%M%S).jfr • La taille max du dump sera aussi maxsize • Assemblage des chunks : jfr assemble <path> finalcapture.jfr
: Old Object Sample • jcmd <pid> JFR.dump path-to-gc-roots=true • Pleins d’informations : => Où l’objet a été alloué (setting profile only) ? => Qui tient encore l’objet ? • Configurer le nombre d‘objets à tracker : -XX:FlightRecordingOptions=old- object-queue-size=512 (256 par défaut)
commande pour capture JFR • Disponible depuis JDK 12 et 11.0.6 • Stack complète (OS->JVM) dans la capture • Exemple : • jfr print --events GarbageCollection <capture.jfr>
des problématiques liées aux safepoints • « Stop the world » tous les threads pour sampler • Ne voit que le « Java », pas le reste : OS, kernel, runtime JVM (GC, compiler), librairie native, code interprété, inlining, … • Modifie le code, donc pas compilé de la même manière • S’appuyer sur perf et AsyncGetCallTrace • A installer tout le temps (il peut y avoir qq settings sécurité) • AsyncGetCallTrace (API interne JDK)
• /proc/sys/kernel/perf_event_mlock_kb • echo 1 > /proc/sys/kernel/perf_event_paranoid • echo 0 > /proc/sys/kernel/kptr_restrict • Si pas loadé en tant qu’agent, pour être plus fiable : -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints • Pas besoin de root mais perf_event_paranoid setté correctement • Le fichier libasyncProfiler.so doit être accessible en lecture par le user du process cible • ./profiler.sh -d 10 -f perf.html [-i 500us] <pid> • Si service systemd avec PrivateTmp, viser un chemin sur le -f non namespacé • Palette de couleur • green : Java compilé ou classique // aqua : Java inliné brown : kernel // yellow : C++ // red : code natif
• $ pip3 install -r requirements.txt • $ python3 run.py • By default, FlameScope will load a list of files from the examples dir • Peut nécessiter : • pip3 install --upgrade werkzeug
Periodic activity • One busy-wait thread, once per second This thread does about 20 ms of work, then sleeps for a whole second (1000 ms). It's a common pattern, and results in the wakeup offset creeping forward each second. • Variance • CPUs 50% utilized • Variable load Every 30 seconds there is 5 seconds of heavier work. • Perturbations • CPU perturbations Every so often, all CPUs max out for 100s of ms. (Eg, GC).
système (maintenir petite taille image et faible surface d’attaque) • JDK ou JRE ? • Mémoire limitée • PIDs différents • syscalls bloqués par seccomp • Throttling tooling du fait des quotas • Sur le host Linux • Nécessite des privilèges élevés, pas simple sur plateforme mutualisée • Doit pouvoir rentrer dans les namespaces • Avec un JDK (>10 pour avoir Attach API dans Docker), montage /tmp éventuel • Avec tout l’outillage classique (sysstat, perf, …) • Volume d’échange assez pratique (log, heap dump, flame graph, …)
docker ps --no-trunc : id complet • cat /sys/fs/cgroup/cpuacct/docker/<container-id>/cpuacct.stat • cat /sys/fs/cgroup/cpu,cpuacct/docker/<container-id>/cpu.stat /sys/fs/cgroup/cpu.stat en cgroup v2 Ex : throttling moyen de 148 ms • Event JFR (<JDK 17) jdk.ContainerCPUThrottling • CPU share et cap causent du context switch involontaire grep nonvoluntary_ctxt_switches /proc/<pid>/task/*/status
• echo 1 > /proc/sys/kernel/perf_event_paranoid • docker run --cap-add SYS_ADMIN et/ou docker run --security-opt seccomp:unconfined ou profile seccomp avec whitelisting des syscall nécessaires ou --fdtransfer • Si on ne peut pas changer perf_event_paranoid : ./profile … --all-user • Mettre async-profiler à la racine d’un volume partagé • ./profile … -f <volume>/perf.svg
JFR.start duration=30s filename=/path/in/container/perf-tbl.jfr • jcmd <pid> JFR.dump • docker cp <container-id>:/path/in/container/perf-tbl.jfr /path/in/host ou plus rapide sur un volume • Analyse avec Mission Control
en compte toutes les sources de consommation mémoire, cf slide • Résident totale du process ps --no-header -o rss <pid> • Composée de • Bien se rappeler que le NMT ne suffit pas à faire le total jcmd <pid> VM.native_memory | grep -P "Total.*committed=" | grep -o -P "(?<=committed=)[0-9]+(?=KB) " • Résident des mapped files pmap -X <pid> | head -n -2 | awk '{ if (NR > 2 && $5 >0 ) sum += $7 } END { print sum }‘ • Plus mémoire possiblement utilisée par malloc or mmap, via des librairies natives et le native allocator overhead
à ne pas faire » • Etat des lieux rapides, quelques commandes à connaître • Outils plus perfectionnés • Outillage spécifique JVM • Interprétation toujours délicate : pas de conclusions hâtives @vladislavpernin
vladislavpernin
tarotaro0129
rayuron
os1ma
chanyou0311
nishiuma
oniak3ibm
shotashiratori
handy
shujisado
loglass2019
bgpat
taichinakamura
mongodb
tanoku
colly
paulrobertlloyd
addyosmani
bluesmoon
morganepeng
zakiyama
tammyeverts
marktimemedia
panda_program
destraynor
![• ss -tuna[ropi] • Connexions • Etat des connexions :](https://files.speakerdeck.com/presentations/7c862d9e04a243b8a393e547abc1e1fe/slide_35.jpg){kind=link}
![• lsof -P [-p <pid>] • Fichiers ouverts [par process]](https://files.speakerdeck.com/presentations/7c862d9e04a243b8a393e547abc1e1fe/slide_47.jpg){kind=link}
![• perf top [-p <pid>] #root](https://files.speakerdeck.com/presentations/7c862d9e04a243b8a393e547abc1e1fe/slide_98.jpg){kind=link}
![• perf stat -ad -- sleep 10 • [-A] detail](https://files.speakerdeck.com/presentations/7c862d9e04a243b8a393e547abc1e1fe/slide_100.jpg){kind=link}
![• Les deux • Filtrage possible sur arguments ('params[0].contains("jms")'), duration](https://files.speakerdeck.com/presentations/7c862d9e04a243b8a393e547abc1e1fe/slide_150.jpg){kind=link}
