Comment identifier ce qui rend le démarrage de votre service coûteux ?

Qu'est-ce qui rend un service coûteux à démarrer ?

Un service est coûteux à démarrer lorsqu'il a besoin de beaucoup de temps, de beaucoup de CPU, ou des deux, avant de pouvoir traiter du trafic. Trois mesures décrivent ce coût :

a. Temps avant Ready : Le temps avant Ready est le temps entre le démarrage du conteneur et le moment où le pod devient Ready. Un temps avant Ready élevé retarde les déploiements, ralentit la montée en charge et augmente le risque d'échec des probes. Cette commande affiche les deux horodatages pour le conteneur nommé app :

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

La différence entre les deux valeurs est le temps avant Ready. La ligne de log Spring Boot Started ... in N seconds donne un nombre plus petit. Elle démarre quand l'application démarre, et elle n'inclut pas le temps dont la JVM et le conteneur ont besoin pour démarrer.

b. CPU-secondes avant Ready : Une CPU-seconde correspond à un CPU travaillant pendant une seconde. Les CPU-secondes avant Ready représentent le travail CPU total du démarrage. Un conteneur ne peut pas utiliser plus de CPU que sa limite, donc les CPU-secondes divisées par la limite donnent le temps avant Ready le plus court possible. Sur cgroup v2, lisez le champ usage_usec dès que le pod devient Ready :

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

Le champ usage_usec est le temps CPU que le conteneur a utilisé depuis son démarrage, en microsecondes. Divisez-le par 1 000 000 pour obtenir des CPU-secondes. Les champs nr_throttled et throttled_usec du même fichier montrent dans quelle mesure le noyau a throttlé le conteneur. Si vous lisez le fichier trop tard, la valeur inclut du travail postérieur à Ready.

c. Warmup après Ready : Ready ne veut pas dire rapide. Lorsque le pod devient Ready, la JVM exécute encore de nombreuses méthodes dans l'interpréteur, ce qui est lent, et les compilateurs JIT continuent de compiler en arrière-plan. Pendant ce warmup, le service utilise plus de CPU qu'en régime stable, et les premières requêtes peuvent être lentes. Si vous réduisez les ressources au moment du Ready, vous risquez de ralentir le warmup. Mesurez la consommation CPU pendant plusieurs minutes après Ready, et pas seulement jusqu'à Ready.

Les outils de profiling du démarrage

Il existe trois outils pour trouver la cause d'un démarrage coûteux. Commencez par le moins coûteux, et passez à l'outil suivant seulement quand vous avez besoin de plus de détails :

a. Les logs et l'endpoint startup de Spring Boot : La ligne de log Spring Boot Started ... in N seconds donne un premier chiffre. Pour plus de détails, l'endpoint startup de Spring Boot Actuator liste chaque étape du démarrage avec sa durée. Il nécessite un BufferingApplicationStartup dans l'application :

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

Le nombre 4096 est la capacité du buffer, c'est-à-dire le nombre maximal d'étapes qu'il conserve. Exposez ensuite l'endpoint. Gardez health dans la liste, pour que vos probes continuent de fonctionner :

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

Une requête GET sur /actuator/startup renvoie un instantané des étapes. Une requête POST renvoie les étapes et vide le buffer. Chaque étape a un nom, une durée et des tags comme le nom du bean. Examinez d'abord les étapes les plus longues. Des noms comme spring.beans.instantiate, spring.context.config-classes.parse et spring.context.refresh montrent où passe le temps. Pour spring.beans.instantiate, le tag beanName nomme le bean, ce qui permet de trouver le bean le plus lent. Les noms des étapes peuvent changer entre les versions de Spring.

Deux options de log JVM ajoutent des données supplémentaires. L'option -Xlog:gc* écrit les événements de garbage collection, et l'option -Xlog:class+load écrit chaque chargement de classe. Vous pouvez passer les deux dans JAVA_TOOL_OPTIONS.

b. Java Flight Recorder (JFR) : JFR est intégré au JDK. Il enregistre des événements de la JVM, comme les garbage collections, les compilations JIT et les échantillons d'exécution. Les réglages par défaut ajoutent très peu d'overhead, et les réglages profile enregistrent davantage d'événements. JFR démarre avec la JVM lorsque vous utilisez l'option -XX:StartFlightRecording, il capture donc l'intégralité du démarrage. Après avoir copié le fichier hors du pod, lisez-le avec l'outil jfr du JDK ou avec 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

La première commande liste les types d'événements et leur nombre. La deuxième commande affiche les événements de garbage collection et les compilations JIT avec leurs durées. La troisième commande affiche des échantillons du code exécuté par les threads, avec une profondeur de pile de 8 frames. L'événement jdk.Compilation n'enregistre que les compilations qui dépassent le seuil défini dans vos réglages.

c. async-profiler : async-profiler est un profileur par échantillonnage pour Java, et il produit des flame graphs. Deux de ses modes comptent pour le démarrage. Le mode cpu n'échantillonne que les threads qui utilisent le CPU, il montre donc ce qui consomme du CPU. Le mode wall échantillonne tous les threads à intervalle fixe, qu'ils s'exécutent, dorment ou attendent, il montre donc où passe le temps, attentes comprises. async-profiler peut démarrer avec la JVM en tant qu'agent, ce qui lui permet de capturer la toute première seconde.

Capturer un profil de démarrage dans Kubernetes

L'enregistrement doit démarrer avec la JVM, et il doit s'exécuter dans les conditions réelles du service. Deux points comptent :

a. Profiler avec les limites CPU de production : Utilisez la même image, les mêmes flags JVM et les mêmes réglages CPU et mémoire qu'en production. Une limite différente change le démarrage lui-même. Elle change le throttling, le nombre de CPU que voit la JVM et le collecteur que la JVM sélectionne. Un profil capturé sans la limite de production montre un démarrage différent. Pour aller plus loin, lisez CPU throttling during JVM startup.

Ce template de pod démarre JFR avec la JVM et écrit le fichier sur un volume :

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

Chaque réglage a un rôle précis :

• filename=/profiles/startup-%p.jfr écrit le fichier sur le volume. Le texte %p devient l'ID du processus.
• settings=profile enregistre plus d'événements que les réglages par défaut.
• duration=120s arrête l'enregistrement après 120 secondes. Choisissez une durée qui couvre le démarrage et plusieurs minutes de warmup.
• dumponexit=true écrit le fichier même si la JVM se termine prématurément, par exemple quand une probe tue le conteneur.
• emptyDir fournit un dossier accessible en écriture même quand le système de fichiers racine est en lecture seule. Le sizeLimit empêche un fichier volumineux de remplir le disque du nœud.
• Les valeurs CPU et mémoire sont des exemples. Utilisez vos valeurs de production.

Dans un conteneur, la JVM est généralement le processus 1, donc le texte %p devient 1 et le fichier s'appelle startup-1.jfr. Si vous voulez conserver les fichiers de plusieurs exécutions dans un même volume, ajoutez %t au nom de fichier. Il ajoute un horodatage. JFR et async-profiler acceptent tous deux %t.

Pour utiliser async-profiler, placez libasyncProfiler.so dans l'image, ou dans un volume qu'un init container remplit avec l'archive de release d'async-profiler. Modifiez ensuite la variable d'environnement :

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

Les options de l'agent fonctionnent ainsi : start démarre le profiling au lancement de la JVM, event=cpu sélectionne le mode CPU, threads profile chaque thread séparément, timeout=120 arrête après 120 secondes, et file=...html écrit un flame graph. Pour un profil wall-clock, remplacez event=cpu par event=wall,interval=10ms. Les conteneurs bloquent souvent les perf events. Si le profileur ne démarre pas, utilisez event=ctimer, qui fonctionne sans perf events.

Exécutez un seul profileur par exécution, et répétez chaque exécution trois fois. Une seule exécution peut vous induire en erreur.

b. Copier les profils hors du pod : Utilisez kubectl cp pour copier le dossier sur votre machine :

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

La commande nécessite le programme tar dans l'image du conteneur. Si l'image n'a pas tar, la commande échoue. Dans ce cas, montez le même volume dans un second petit conteneur qui possède tar, et utilisez son nom avec -c. Copiez les fichiers avant que le pod ne soit supprimé, car Kubernetes supprime un volume emptyDir avec le pod. Ouvrez ensuite un fichier HTML dans un navigateur.

Lire un flame graph de démarrage

Un flame graph montre les stack traces de tous les échantillons. Chaque bloc représente une méthode, et sa largeur correspond à la part des échantillons qui l'incluent. Dans un graphe async-profiler, les frames les plus externes, comme main, sont en bas, et les frames feuilles, qui font le travail, sont en haut. Les blocs larges indiquent où passe le temps. Grâce à l'option threads, chaque thread a sa propre tour, et la tour commence par un bloc qui nomme le thread. Linux tronque les noms de threads à 15 caractères, les noms longs apparaissent donc raccourcis dans le graphe. Trois groupes de threads comptent :

a. Les threads applicatifs : Le thread qui exécute main exécute le code de démarrage de l'application. Son bloc racine peut s'appeler main ou DestroyJavaVM, repérez-le donc par la frame SpringApplication.run et non par son nom. Une tour SpringApplication.run large, ou une tour refresh large, signifie que le démarrage du framework consomme la majeure partie du temps. Des blocs larges avec defineClass ou loadClass indiquent du chargement de classes. Des blocs larges avec vos propres noms de packages indiquent votre propre code de démarrage, comme un chargement de cache ou une migration de base de données.

b. Les threads des compilateurs JIT : Les racines qui commencent par C1 CompilerThre et C2 CompilerThre sont les compilateurs JIT. Les noms de threads complets sont C1 CompilerThread0, C2 CompilerThread0, et ainsi de suite. Si ces tours sont aussi larges que celle du thread de démarrage, le travail JIT représente une grande partie du CPU de démarrage. Pour voir quelles frames s'exécutent dans l'interpréteur, écrivez le profil dans un fichier avec l'extension .collapsed et ajoutez l'option ann. Dans ce fichier, les frames interprétées se terminent par _[0], les frames C1 par _[1], les autres frames compilées par _[j], et les frames inlinées par _[i]. De nombreuses frames _[0] dans le thread de démarrage signifient que le code n'est pas encore compilé. Le graphe HTML n'ajoute pas ces suffixes. Il indique les types de frames par des couleurs.

c. Les threads GC : Avec G1, des racines comme GC Thread#0, G1 Conc#0 et G1 Refine#0 effectuent le travail de garbage collection. Avec le collecteur Serial, c'est le VM Thread qui s'en charge. Une limite CPU de 1 CPU ou moins, ou une limite mémoire inférieure à 1792 Mo, conduit la JVM à sélectionner le collecteur Serial, donc un graphe issu d'un tel pod n'a pas de threads workers GC. Une tour de garbage collection large dans les premières secondes signifie que le heap est trop petit pour les allocations du démarrage, ou qu'il grandit de nombreuses fois. Confirmez-le avec les événements jdk.GarbageCollection de JFR, où le nom de l'événement indique le collecteur (par exemple, DefNew et SerialOld appartiennent au collecteur Serial), ou avec l'option de log -Xlog:gc*.

Comparez un graphe cpu avec un graphe wall du même démarrage. Un graphe wall montre aussi de nombreux threads inactifs, comme les threads du serveur web. Ignorez-les et concentrez-vous sur le thread de démarrage.