¿Cómo identificar qué encarece el arranque de tu servicio?

¿Qué encarece el arranque de un servicio?

Arrancar un servicio resulta costoso cuando necesita mucho tiempo, mucha CPU, o ambos, antes de poder atender tráfico. Tres medidas describen el costo:

a. Tiempo hasta Ready: El tiempo hasta Ready es el tiempo desde el inicio del contenedor hasta el momento en que el pod pasa a Ready. Un tiempo hasta Ready largo retrasa los despliegues, ralentiza el escalado horizontal y aumenta el riesgo de que fallen las probes. Este comando imprime las dos marcas de tiempo del contenedor llamado app:

kubectl get pod <pod-name> -o jsonpath='{.status.containerStatuses[?(@.name=="app")].state.running.startedAt}{"\n"}{.status.conditions[?(@.type=="Ready")].lastTransitionTime}{"\n"}'

La diferencia entre los dos valores es el tiempo hasta Ready. La línea de log de Spring Boot "Started ... in N seconds" da un número menor. Comienza cuando arranca la aplicación y no incluye el tiempo que necesitan la JVM y el contenedor para iniciar.

b. Segundos de CPU hasta Ready: Un segundo de CPU es una CPU trabajando durante un segundo. Los segundos de CPU hasta Ready son el trabajo total de CPU del arranque. Un contenedor no puede usar más CPU que su límite, así que los segundos de CPU divididos entre el límite son el tiempo mínimo posible hasta Ready. En cgroup v2, lee el campo usage_usec en cuanto el pod pase a Ready:

kubectl exec <pod-name> -c app -- cat /sys/fs/cgroup/cpu.stat

El campo usage_usec es el tiempo de CPU que el contenedor ha usado desde que inició, en microsegundos. Divídelo entre 1,000,000 para obtener los segundos de CPU. Los campos nr_throttled y throttled_usec del mismo archivo muestran cuánto limitó el kernel al contenedor. Si lees el archivo tarde, el valor incluye trabajo posterior al estado Ready.

c. Calentamiento después de Ready: Ready no significa rápido. Cuando el pod pasa a Ready, la JVM todavía ejecuta muchos métodos en el intérprete, que es lento, y los compiladores JIT siguen compilando en segundo plano. Durante este calentamiento, el servicio usa más CPU que en estado estable y las primeras solicitudes pueden ser lentas. Si reduces los recursos en el momento de Ready, puedes ralentizar el calentamiento. Conviene medir el uso de CPU durante varios minutos después de Ready, y no solo hasta Ready.

Herramientas de perfilado del arranque

Existen tres herramientas para encontrar la causa de un arranque costoso. Puedes empezar con la más económica y pasar a la siguiente solo cuando necesites más detalle:

a. Logs y el endpoint de arranque de Spring Boot: La línea de log de Spring Boot "Started ... in N seconds" da un primer número. Para más detalle, el endpoint startup de Spring Boot Actuator lista cada paso del arranque con su duración. Necesita un BufferingApplicationStartup en la aplicación:

SpringApplication application = new SpringApplication(MyApplication.class);
application.setApplicationStartup(new BufferingApplicationStartup(4096));
application.run(args);

El número 4096 es la capacidad del búfer, es decir, el número máximo de pasos que almacena. Después expón el endpoint. Mantén health en la lista para que tus probes sigan funcionando:

management.endpoints.web.exposure.include=health,startup

Una solicitud GET a /actuator/startup devuelve una instantánea de los pasos. Una solicitud POST devuelve los pasos y vacía el búfer. Cada paso tiene un nombre, una duración y etiquetas como el nombre del bean. Revisa primero los pasos más largos. Nombres como spring.beans.instantiate, spring.context.config-classes.parse y spring.context.refresh muestran a dónde se va el tiempo. En spring.beans.instantiate, la etiqueta beanName indica el bean, así que puedes encontrar el bean más lento. Los nombres de los pasos pueden cambiar entre versiones de Spring.

Dos opciones de log de la JVM agregan más datos. La opción -Xlog:gc* escribe los eventos de recolección de basura y la opción -Xlog:class+load escribe cada carga de clase. Puedes pasar ambas en JAVA_TOOL_OPTIONS.

b. Java Flight Recorder (JFR): JFR viene integrado en el JDK. Registra eventos de la JVM, como recolecciones de basura, compilaciones JIT y muestras de ejecución. La configuración por defecto agrega muy poca sobrecarga, y la configuración profile registra más eventos. JFR arranca junto con la JVM cuando usas la opción -XX:StartFlightRecording, así que captura todo el arranque. Después de copiar el archivo fuera del pod, léelo con la herramienta jfr del JDK o con JDK Mission Control:

jfr summary startup.jfr
jfr print --events jdk.GarbageCollection,jdk.Compilation startup.jfr
jfr print --events jdk.ExecutionSample --stack-depth 8 startup.jfr

El primer comando lista los tipos de evento y sus conteos. El segundo imprime los eventos de recolección de basura y las compilaciones JIT con sus duraciones. El tercero imprime muestras del código que ejecutan los hilos, con una profundidad de pila de 8 frames. El evento jdk.Compilation registra solo las compilaciones que superan el umbral de tu configuración.

c. async-profiler: async-profiler es un perfilador por muestreo para Java que genera flame graphs. Dos de sus modos importan para el arranque. El modo cpu muestrea solo los hilos que usan CPU, así que muestra qué consume CPU. El modo wall muestrea todos los hilos a un intervalo fijo, ya sea que se ejecuten, duerman o esperen, así que muestra a dónde se va el tiempo, incluidas las esperas. async-profiler puede arrancar con la JVM como agente, por lo que captura el primer segundo.

Capturar un perfil de arranque en Kubernetes

La grabación debe iniciar con la JVM y debe ejecutarse bajo las condiciones reales del servicio. Dos puntos importan:

a. Perfila con los límites de CPU de producción: Usa la misma imagen, las mismas flags de la JVM y la misma configuración de CPU y memoria que en producción. Un límite distinto cambia el arranque en sí. Cambia el throttling, el número de CPUs que ve la JVM y el recolector que selecciona la JVM. Un perfil tomado sin el límite de producción muestra un arranque diferente. Para profundizar, lee CPU throttling durante el arranque de la JVM.

Esta plantilla de pod inicia JFR con la JVM y escribe el archivo en un volumen:

spec:
  template:
    spec:
      containers:
        - name: app
          image: registry.example.com/orders-service:1.8.0
          env:
            - name: JAVA_TOOL_OPTIONS
              value: >-
                -XX:StartFlightRecording=filename=/profiles/startup-%p.jfr,settings=profile,duration=120s,dumponexit=true
          resources:
            requests:
              cpu: 300m
              memory: 2Gi
            limits:
              cpu: "2"
              memory: 2Gi
          volumeMounts:
            - name: profiles
              mountPath: /profiles
      volumes:
        - name: profiles
          emptyDir:
            sizeLimit: 500Mi

Cada parámetro tiene una función:

• filename=/profiles/startup-%p.jfr escribe el archivo en el volumen. El texto %p se convierte en el ID del proceso.
• settings=profile registra más eventos que la configuración por defecto.
• duration=120s detiene la grabación después de 120 segundos. Elige un tiempo que cubra el arranque y varios minutos de calentamiento.
• dumponexit=true escribe el archivo incluso si la JVM termina antes de tiempo, por ejemplo cuando una probe mata el contenedor.
• emptyDir ofrece una carpeta con permisos de escritura incluso cuando el sistema de archivos raíz es de solo lectura. El sizeLimit evita que un archivo grande llene el disco del nodo.
• Los valores de CPU y memoria son ejemplos. Usa tus valores de producción.

En un contenedor, la JVM suele ser el proceso 1, así que el texto %p se convierte en 1 y el archivo se llama startup-1.jfr. Si quieres conservar los archivos de varias ejecuciones en un mismo volumen, agrega %t al nombre del archivo. Esto añade una marca de tiempo. Tanto JFR como async-profiler aceptan %t.

Para usar async-profiler, incluye libasyncProfiler.so en la imagen, o en un volumen que un init container llene con el archivo de la release de async-profiler. Luego cambia la variable de entorno:

env:
  - name: JAVA_TOOL_OPTIONS
    value: >-
      -agentpath:/profiler/lib/libasyncProfiler.so=start,event=cpu,threads,timeout=120,file=/profiles/startup-cpu-%p.html

Las opciones del agente funcionan así: start comienza el perfilado cuando arranca la JVM, event=cpu selecciona el modo CPU, threads perfila cada hilo por separado, timeout=120 se detiene a los 120 segundos y file=...html escribe un flame graph. Para un perfil de tiempo de reloj (wall-clock), reemplaza event=cpu por event=wall,interval=10ms. Los contenedores suelen bloquear los eventos de perf. Si el perfilador no logra iniciar, usa event=ctimer, que funciona sin eventos de perf.

Ejecuta un solo perfilador por ejecución y repite cada ejecución tres veces. Una sola ejecución puede llevarte a conclusiones equivocadas.

b. Copiar los perfiles fuera del pod: Usa kubectl cp para copiar la carpeta a tu computadora:

kubectl cp <namespace>/<pod-name>:/profiles ./profiles -c app

El comando necesita el programa tar en la imagen del contenedor. Si la imagen no tiene tar, el comando falla. En ese caso, monta el mismo volumen en un segundo contenedor pequeño que tenga tar y usa su nombre con -c. Copia los archivos antes de que el pod se elimine, porque Kubernetes borra un volumen emptyDir junto con el pod. Abre un archivo HTML en un navegador.

Cómo leer un flame graph de arranque

Un flame graph muestra las trazas de pila de todas las muestras. Cada caja es un método y su ancho es la proporción de las muestras que lo incluyen. En un gráfico de async-profiler, los frames más externos, como main, están abajo, y los frames hoja, que hacen el trabajo, están arriba. Las cajas anchas indican a dónde se va el tiempo. Gracias a la opción threads, cada hilo tiene su propia torre, y la torre comienza con una caja que lleva el nombre del hilo. Linux recorta los nombres de hilo a 15 caracteres, así que los nombres largos se ven más cortos en el gráfico. Tres grupos de hilos importan:

a. Hilos de la aplicación: El hilo que ejecuta main corre el código de arranque de la aplicación. Su caja raíz puede llamarse main o DestroyJavaVM, así que búscalo por el frame SpringApplication.run y no por su nombre. Una torre ancha de SpringApplication.run, o una torre ancha de refresh, significa que el arranque del framework consume la mayor parte del tiempo. Cajas anchas con defineClass o loadClass significan carga de clases. Cajas anchas con los nombres de tus propios paquetes significan tu propio código de arranque, como la carga de una caché o una migración de base de datos.

b. Hilos del compilador JIT: Las raíces que empiezan con C1 CompilerThre y C2 CompilerThre son los compiladores JIT. Los nombres completos de los hilos son C1 CompilerThread0, C2 CompilerThread0, y así sucesivamente. Si estas torres son tan anchas como la torre del hilo de arranque, el trabajo del JIT es una parte importante de la CPU del arranque. Para ver qué frames corren en el intérprete, escribe el perfil en un archivo con la extensión .collapsed y agrega la opción ann. En ese archivo, los frames interpretados terminan en _[0], los frames C1 en _[1], otros frames compilados en _[j] y los frames inlined en _[i]. Muchos frames _[0] en el hilo de arranque significan que el código aún no está compilado. El gráfico HTML no agrega estas terminaciones. Muestra los tipos de frame con colores.

c. Hilos de GC: Con G1, raíces como GC Thread#0, G1 Conc#0 y G1 Refine#0 hacen el trabajo de recolección de basura. Con el recolector Serial, lo hace el VM Thread. Un límite de CPU de 1 CPU o menos, o un límite de memoria por debajo de 1792 MB, hace que la JVM seleccione el recolector Serial, así que un gráfico de un pod en esas condiciones no tiene hilos de trabajo de GC. Una torre ancha de recolección de basura en los primeros segundos significa que el heap es demasiado pequeño para la asignación del arranque, o que crece muchas veces. Confírmalo con los eventos jdk.GarbageCollection de JFR, donde el nombre del evento indica el recolector (por ejemplo, DefNew y SerialOld pertenecen al recolector Serial), o con la opción de log -Xlog:gc*.

Compara un gráfico cpu con un gráfico wall del mismo arranque. Un gráfico wall también muestra muchos hilos inactivos, como los hilos del servidor web. Ignóralos y concéntrate en el hilo de arranque.