¿JVMs siendo eliminados por OOM? Pruebe los informes de alta memoria de SapMachine
By s4pcademy
Analizar OOM-kills no es divertido. Vuela mayormente a ciegas, no tiene registros significativos: sus JVM simplemente siguen desapareciendo. Puede ser un trabajo muy frustrante.
Si eso le suena familiar, es posible que tengamos algo para usted.
OOM-kills significa muerte súbita. La JVM no recibe ninguna advertencia, solo recibe un SIGKILL del kernel. O su propio contenedor puede quedar bloqueado desde el exterior.
Dato interesante: otros Unices te avisan. AIX, por ejemplo, envía a su proceso un SIGDANGER antes de eliminarlo. Un poco de cortesía hace mucho. Pero, por desgracia, el kernel de Linux no se preocupa por las sutilezas.
Dado que la JVM se elimina, no puede escribir un registro de fallas. Es posible que tengamos registros del sistema operativo o registros del contenedor, por lo que podemos conocer el tamaño de la memoria infractora del proceso JVM. Pero a menudo, tenemos poca información sobre lo que sucedió dentro de la JVM.
Ingresar Informes de memoria alta de SapMachine – una instalación integrada en nuestro SapMachine JVM eso hace que casos como estos sean más fáciles de analizar.
Cómo funciona:
La JVM define un umbral de memoria en el que espera ser en peligro inminente de ser purgado por el asesino OOM. Dicho umbral depende del contexto: memoria física en una caja física, cgroup límites en un recipiente. Ese valor suele funcionar, pero se puede anular manualmente.
Los puntos de activación se establecen en 66%, 75%y 90% de ese umbral primario.
La JVM luego monitorea RSS: al llegar a cada punto de activación, genera un informe. Además, ejecuta un conjunto de comandos programables.
La teoría detrás de este diseño simple es que incluso si nos matan sin dejar rastro, al menos uno, con suerte más, de los tres puntos de activación se habrá disparado de antemano, atrapando a la JVM con una huella ya patológica y dándonos suficiente información para comenzar. analizando
Los informes generados contienen, entre otras cosas, SapMachine Vitals y TNM informes. SapMachine Vitals es una grabación de JVM y métricas del sistema. Le permite mirar «hacia atrás en el tiempo» para ver el desarrollo hasta la escasez de memoria. Seguimiento de memoria nativa (NMT) contiene información sobre el consumo de memoria de la JVM central.
Curva de activación del informe de memoria alta de SapMachine
Habilitación de informes de memoria alta
La función HiMem Report está habilitada con -XX:+HiMemReport:
java -XX:+HiMemReportControlando el umbral
si empiezas con -Xlog:vitals, SapMachine le indica el umbral principal que dedujo. Por ejemplo, iniciado en un contenedor con un límite de memoria de 2G, también establece el umbral principal en 2G:
thomas@container1: $ java -XX:+HiMemReport -Xlog:vitals
[vitals] Vitals HiMemReport: Setting limit to cgroup memory limit (2048000 K).
Puede anular el límite con -XX:HiMemReportMax=<size>. Esto cambiará los puntos de activación. Por ejemplo, si especifica -XX:HiMemReportMax=1Glos puntos de activación se establecerán en 660M, 750M y 900M, respectivamente.
¿Adónde va el informe?
Los informes de memoria alta van a `stderr`, a menos que los redirija con -XX:HiMemReportDir=<directory>:
java -XX:+HiMemReport -XX:HiMemReportDir=~/my-himem-reports
El archivo, o archivos, contendrán el PID del proceso JVM, así como una marca de tiempo, por ejemplo:
thomas@starfish:~/my-himem-reports$ ls
sapmachine_himemalert_pid758099_2023_02_10_16_03_41.logEjecutar jcmds arbitrarios en los puntos de activación
High Memory Reports puede ejecutar jcmds arbitrarios por usted cada vez que se activa una alerta. Los comandos se especifican mediante -XX:HiMemReportExec=<commands>. Se pueden especificar varios comandos, pero deben estar separados por punto y coma.
Por ejemplo, este comando:
java -XX:+HiMemReport '-XX:HiMemReportExec=VM.info;VM.flags -all;VM.metaspace show-loaders'se ejecutará en cada punto de activación:
jcmd <my-pid> VM.infojcmd <my-pid> VM.flags -alljcmd <my-pid> VM.metaspace show-loader
Estos comandos son una forma potente y flexible de ampliar los informes. Por ejemplo, ejecutar -XX:HiMemReportExec=GC.heap_dump para obtener un volcado de pila de Java en cada punto de activación. Por favor mira [2] para más detalles.
Un ejemplo
Iniciemos una aplicación Spring-Boot que ocupa unos 400 MB.
Establecemos su umbral principal en 500 MB y redirigimos los informes al sistema de archivos. En cada punto de alerta, imprimimos indicadores de VM y creamos un volcado de pila de Java:
java -XX:+HiMemReport \
-XX:HiMemReportMax=500m \
-XX:HiMemReportExec="VM.flags -all;GC.heap_dump" \
-XX:HiMemReportDir=my-himem-reports \
-XX:NativeMemoryTracking=summary -jar $SPRING
Mientras se ejecuta, ahora activamos dos alertas: al 66% y al 75%. No alcanzamos el límite del 90 %, por lo que no hay una tercera alerta:
|\ _,,,--,,_
/,`.-'`' ._ \-;;,_
_______ __|,4- ) )_ .;.(__`'-'__ ___ __ _ ___ _______
| | '---''(_/._)-'(_\_) | | | | | | | | |
| _ | ___|_ _| | | | | |_| | | | __ _ _
| |_| | |___ | | | | | | | | | | \ \ \ \
| ___| ___| | | | _| |___| | _ | | _| \ \ \ \
| | | |___ | | | |_| | | | | | | |_ ) ) ) )
|___| |_______| |___| |_______|_______|___|_| |__|___|_______| / / / /
==================================================================/_/_/_/
HiMemoryReport: rss+swap=367772 K - alert level increased to 1 (>=66%).
############
#
# High Memory Report:
# pid: 758099 thread id: 758115
# rss+swap (367772 K) larger than 66% of HiMemReportMaximum (512000 K).
# 2023-02-10 16:03:41
# Spike number: 1
#
# Printing to /home/thomas/my-himem-reports/sapmachine_himemalert_pid758099_2023_02_10_16_03_41.log
# Done.
#
HiMemReport: Successfully executed "VM.flags -all" (217 ms), output redirected to report dir
HiMemReport: Successfully executed "GC.heap_dump /home/thomas/my-himem-reports/GC.heap_dump_pid758099_2023_02_10_16_03_41.dump" (176 ms), output redirected to report dir
HiMemoryReport: ... captured NMT baseline
HiMemoryReport: rss+swap=413984 K - alert level increased to 2 (>=75%).
############
#
# High Memory Report:
# pid: 758099 thread id: 758115
# rss+swap (413984 K) larger than 75% of HiMemReportMaximum (512000 K).
# 2023-02-10 16:03:44
# Spike number: 1
#
# Printing to /home/thomas/my-himem-reports/sapmachine_himemalert_pid758099_2023_02_10_16_03_44.log
# Done.
#
HiMemReport: Successfully executed "VM.flags -all" (100 ms), output redirected to report dir
HiMemReport: Successfully executed "GC.heap_dump /home/thomas/my-himem-reports/GC.heap_dump_pid758099_2023_02_10_16_03_44.dump" (233 ms), output redirected to report dir
Y mire esto: varios archivos de registro aparecieron en nuestro directorio de informes.
thomas@starfish:~/my-himem-reports$ ls
GC.heap_dump_pid758099_2023_02_10_16_03_41.dump
GC.heap_dump_pid758099_2023_02_10_16_03_41.err
GC.heap_dump_pid758099_2023_02_10_16_03_41.out
GC.heap_dump_pid758099_2023_02_10_16_03_44.dump
GC.heap_dump_pid758099_2023_02_10_16_03_44.err
GC.heap_dump_pid758099_2023_02_10_16_03_44.out
sapmachine_himemalert_pid758099_2023_02_10_16_03_41.log
sapmachine_himemalert_pid758099_2023_02_10_16_03_44.log
VM.flags_pid758099_2023_02_10_16_03_41.err
VM.flags_pid758099_2023_02_10_16_03_41.out
VM.flags_pid758099_2023_02_10_16_03_44.err
VM.flags_pid758099_2023_02_10_16_03_44.outPara cada una de nuestras dos alertas, obtenemos:
- el propio informe:
sapmachine_himemalert_pid758099_<timestamp>.log. Contiene informes Vitals y NMT. - Un volcado de montón:
GC.heap_dump_pid758099_<timestamp>.dumpasí como stdout y stderr de su invocación jcmd. - Una copia impresa de todas las banderas de VM:
VM.flags_pid758099_<timestamp>.out
¿Por qué es solo para SapMachine? ¿Por qué no contribuir a la línea principal OpenJDK?
Planeamos contribuir con esta característica en sentido ascendente, pero esperamos que esto tome algún tiempo. Por lo general, características como estas no se aportan palabra por palabra, sino que tendrán que pasar por un largo proceso de diseño. Ya veremos.
[1] SapMachine.io
[2] Informes de memoria alta de SapMachine
[3] SapMachine Vitals
