Was macht den Start Ihres Java-Service so teuer?

Was macht den Start eines Service teuer?

Der Start eines Service ist teuer, wenn er viel Zeit, viel CPU oder beides benötigt, bevor er Traffic bedienen kann. Drei Messgrößen beschreiben die Kosten:

a. Zeit bis Ready: Die Zeit bis Ready ist die Zeitspanne vom Start des Containers bis zu dem Moment, in dem der Pod Ready wird. Eine lange Zeit bis Ready verzögert Rollouts, verlangsamt das Scale-out und erhöht das Risiko fehlgeschlagener Probes. Dieser Befehl gibt die beiden Zeitstempel für den Container mit dem Namen app aus:

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

Die Differenz der beiden Werte ist die Zeit bis Ready. Die Spring-Boot-Logzeile "Started ... in N seconds" liefert einen kleineren Wert. Sie beginnt erst mit dem Start der Anwendung und enthält nicht die Zeit, die JVM und Container zum Starten benötigen.

b. CPU-Sekunden bis Ready: Eine CPU-Sekunde ist eine CPU, die eine Sekunde lang arbeitet. Die CPU-Sekunden bis Ready sind die gesamte CPU-Arbeit des Startvorgangs. Ein Container kann nicht mehr CPU nutzen als sein Limit, daher ergeben die CPU-Sekunden geteilt durch das Limit die kürzestmögliche Zeit bis Ready. Lesen Sie auf cgroup v2 das Feld usage_usec aus, sobald der Pod Ready wird:

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

Das Feld usage_usec ist die CPU-Zeit, die der Container seit seinem Start verbraucht hat, in Mikrosekunden. Teilen Sie den Wert durch 1.000.000, um CPU-Sekunden zu erhalten. Die Felder nr_throttled und throttled_usec in derselben Datei zeigen, wie stark der Kernel den Container gedrosselt hat. Wenn Sie die Datei zu spät auslesen, enthält der Wert auch Arbeit nach Ready.

c. Warmup nach Ready: Ready heißt nicht schnell. Wenn der Pod Ready wird, führt die JVM noch viele Methoden im Interpreter aus, der langsam ist, und die JIT-Compiler kompilieren im Hintergrund weiter. Während dieses Warmups verbraucht der Service mehr CPU als im stabilen Zustand, und die ersten Anfragen können langsam sein. Wenn Sie die Ressourcen in dem Moment reduzieren, in dem der Pod Ready wird, verlangsamen Sie unter Umständen das Warmup. Messen Sie die CPU-Nutzung daher mehrere Minuten nach Ready, nicht nur bis Ready.

Tools für das Startup-Profiling

Es gibt drei Tools, um die Ursache eines teuren Starts zu finden. Beginnen Sie mit dem günstigsten und greifen Sie nur dann zum nächsten Tool, wenn Sie mehr Details benötigen:

a. Logs und der Spring-Boot-Startup-Endpunkt: Die Spring-Boot-Logzeile "Started ... in N seconds" liefert einen ersten Wert. Für mehr Details listet der startup-Endpunkt des Spring Boot Actuator jeden Startup-Schritt mit seiner Dauer auf. Er benötigt ein BufferingApplicationStartup in der Anwendung:

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

Die Zahl 4096 ist die Kapazität des Buffers, also die maximale Anzahl von Schritten, die er aufnimmt. Geben Sie anschließend den Endpunkt frei. Behalten Sie health in der Liste, damit Ihre Probes weiter funktionieren:

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

Ein GET-Request an /actuator/startup liefert einen Snapshot der Schritte. Ein POST-Request liefert die Schritte und leert den Buffer. Jeder Schritt hat einen Namen, eine Dauer und Tags wie den Bean-Namen. Prüfen Sie zuerst die längsten Schritte. Namen wie spring.beans.instantiate, spring.context.config-classes.parse und spring.context.refresh zeigen, wohin die Zeit fließt. Bei spring.beans.instantiate nennt das Tag beanName die Bean, sodass Sie die langsamste Bean finden können. Die Schrittnamen können sich zwischen Spring-Versionen ändern.

Zwei JVM-Log-Optionen liefern zusätzliche Daten. Die Option -Xlog:gc* schreibt die Garbage-Collection-Ereignisse, die Option -Xlog:class+load protokolliert jeden Klassenladevorgang. Beide können Sie über JAVA_TOOL_OPTIONS übergeben.

b. Java Flight Recorder (JFR): JFR ist im JDK eingebaut. Er zeichnet Ereignisse der JVM auf, etwa Garbage Collections, JIT-Kompilierungen und Execution Samples. Die Standardeinstellungen verursachen nur minimalen Overhead, die profile-Einstellungen zeichnen mehr Ereignisse auf. JFR startet zusammen mit der JVM, wenn Sie die Option -XX:StartFlightRecording verwenden, und erfasst so den gesamten Startvorgang. Nachdem Sie die Datei aus dem Pod kopiert haben, lesen Sie sie mit dem jfr-Tool des JDK oder mit 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

Der erste Befehl listet die Ereignistypen und ihre Anzahl auf. Der zweite Befehl gibt die Garbage-Collection-Ereignisse und die JIT-Kompilierungen mit ihren Dauern aus. Der dritte Befehl gibt Samples des Codes aus, den die Threads ausführen, mit einer Stack-Tiefe von 8 Frames. Das Ereignis jdk.Compilation erfasst nur Kompilierungen, die länger dauern als der Schwellenwert Ihrer Einstellungen.

c. async-profiler: async-profiler ist ein Sampling-Profiler für Java und erzeugt Flame Graphs. Zwei seiner Modi sind für den Start relevant. Der cpu-Modus sampelt nur Threads, die CPU nutzen, und zeigt damit, was CPU verbraucht. Der wall-Modus sampelt alle Threads in einem festen Intervall – egal ob sie laufen, schlafen oder warten – und zeigt damit, wohin die Zeit geht, einschließlich der Wartezeiten. async-profiler kann als Agent mit der JVM starten und erfasst so auch die erste Sekunde.

Ein Startup-Profil in Kubernetes erfassen

Die Aufzeichnung muss mit der JVM starten und unter den realen Bedingungen des Service laufen. Zwei Punkte sind wichtig:

a. Profiling unter Produktions-CPU-Limits: Verwenden Sie dasselbe Image, dieselben JVM-Flags und dieselben CPU- und Speichereinstellungen wie in der Produktion. Ein anderes Limit verändert den Startvorgang selbst. Es verändert das Throttling, die CPU-Anzahl, die die JVM sieht, und den Collector, den die JVM auswählt. Ein Profil, das Sie ohne das Produktionslimit aufnehmen, zeigt einen anderen Start. Einen tieferen Einblick gibt der Beitrag CPU-Throttling während des JVM-Starts.

Dieses Pod-Template startet JFR zusammen mit der JVM und schreibt die Datei auf ein 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

Jede Einstellung hat eine Aufgabe:

• filename=/profiles/startup-%p.jfr schreibt die Datei auf das Volume. Der Platzhalter %p wird zur Prozess-ID.
• settings=profile zeichnet mehr Ereignisse auf als die Standardeinstellungen.
• duration=120s stoppt die Aufzeichnung nach 120 Sekunden. Wählen Sie eine Zeitspanne, die den Start und mehrere Minuten Warmup abdeckt.
• dumponexit=true schreibt die Datei auch dann, wenn die JVM vorzeitig beendet wird, zum Beispiel wenn eine Probe den Container beendet.
• emptyDir stellt einen beschreibbaren Ordner bereit, auch wenn das Root-Dateisystem schreibgeschützt ist. Das sizeLimit verhindert, dass eine große Datei die Festplatte des Nodes füllt.
• Die CPU- und Speicherwerte sind Beispiele. Verwenden Sie Ihre Produktionswerte.

In einem Container ist die JVM in der Regel Prozess 1, der Platzhalter %p wird also zu 1, und die Datei heißt startup-1.jfr. Wenn Sie die Dateien mehrerer Läufe in einem Volume aufbewahren möchten, fügen Sie %t zum Dateinamen hinzu. Das ergänzt einen Zeitstempel. Sowohl JFR als auch async-profiler akzeptieren %t.

Um async-profiler zu verwenden, legen Sie libasyncProfiler.so in das Image oder in ein Volume, das ein Init-Container mit dem Release-Archiv von async-profiler befüllt. Ändern Sie dann die Umgebungsvariable:

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

Die Agent-Optionen funktionieren so: start beginnt das Profiling beim Start der JVM, event=cpu wählt den CPU-Modus, threads profiliert jeden Thread separat, timeout=120 stoppt nach 120 Sekunden, und file=...html schreibt einen Flame Graph. Für ein Wall-Clock-Profil ersetzen Sie event=cpu durch event=wall,interval=10ms. Container blockieren häufig Perf-Events. Wenn der Profiler nicht startet, verwenden Sie event=ctimer, das ohne Perf-Events funktioniert.

Lassen Sie pro Lauf nur einen Profiler laufen, und wiederholen Sie jeden Lauf dreimal. Ein einzelner Lauf kann Sie in die Irre führen.

b. Profile aus dem Pod kopieren: Kopieren Sie den Ordner mit kubectl cp auf Ihren Rechner:

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

Der Befehl benötigt das Programm tar im Container-Image. Hat das Image kein tar, schlägt der Befehl fehl. Mounten Sie in diesem Fall dasselbe Volume in einen kleinen zweiten Container mit tar und verwenden Sie dessen Namen mit -c. Kopieren Sie die Dateien, bevor der Pod entfernt wird, denn Kubernetes löscht ein emptyDir-Volume zusammen mit dem Pod. Öffnen Sie eine HTML-Datei im Browser.

Einen Startup-Flame-Graph lesen

Ein Flame Graph zeigt die Stacktraces aller Samples. Jedes Kästchen ist eine Methode, seine Breite entspricht dem Anteil der Samples, in denen sie vorkommt. In einem async-profiler-Graphen stehen die äußersten Frames, etwa main, unten und die Leaf-Frames, die die eigentliche Arbeit leisten, oben. Breite Kästchen zeigen, wohin die Zeit geht. Durch die threads-Option hat jeder Thread einen eigenen Turm, der mit einem Kästchen mit dem Namen des Threads beginnt. Linux kürzt Thread-Namen auf 15 Zeichen, lange Namen erscheinen im Graphen also verkürzt. Drei Gruppen von Threads sind wichtig:

a. Anwendungs-Threads: Der Thread, der main ausführt, führt den Startup-Code der Anwendung aus. Sein Root-Kästchen kann main oder DestroyJavaVM heißen, suchen Sie ihn daher über den Frame SpringApplication.run und nicht über seinen Namen. Ein breiter SpringApplication.run-Turm oder ein breiter refresh-Turm bedeutet, dass der Framework-Start den Großteil der Zeit beansprucht. Breite Kästchen mit defineClass oder loadClass bedeuten Klassenladen. Breite Kästchen mit Ihren eigenen Paketnamen bedeuten eigenen Startup-Code, etwa das Laden eines Caches oder eine Datenbankmigration.

b. JIT-Compiler-Threads: Roots, die mit C1 CompilerThre und C2 CompilerThre beginnen, sind die JIT-Compiler. Die vollständigen Thread-Namen lauten C1 CompilerThread0, C2 CompilerThread0 und so weiter. Sind diese Türme so breit wie der Turm des Startup-Threads, macht JIT-Arbeit einen großen Teil der Startup-CPU aus. Um zu sehen, welche Frames im Interpreter laufen, schreiben Sie das Profil in eine Datei mit der Endung .collapsed und fügen die Option ann hinzu. In dieser Datei enden interpretierte Frames auf _[0], C1-Frames auf _[1], andere kompilierte Frames auf _[j] und Inline-Frames auf _[i]. Viele _[0]-Frames im Startup-Thread bedeuten, dass der Code noch nicht kompiliert ist. Der HTML-Graph fügt diese Endungen nicht hinzu. Er zeigt die Frame-Typen über Farben an.

c. GC-Threads: Bei G1 erledigen Roots wie GC Thread#0, G1 Conc#0 und G1 Refine#0 die Garbage-Collection-Arbeit. Beim Serial Collector übernimmt das der VM Thread. Bei einem CPU-Limit von 1 CPU oder weniger oder einem Speicherlimit unter 1792 MB wählt die JVM den Serial Collector, ein Graph aus einem solchen Pod hat also keine GC-Worker-Threads. Ein breiter Garbage-Collection-Turm in den ersten Sekunden bedeutet, dass der Heap für die Allokationen des Starts zu klein ist oder viele Male wächst. Bestätigen Sie das mit den jdk.GarbageCollection-Ereignissen von JFR, bei denen der Ereignisname den Collector zeigt (zum Beispiel gehören DefNew und SerialOld zum Serial Collector), oder mit der Log-Option -Xlog:gc*.

Vergleichen Sie einen cpu-Graphen mit einem wall-Graphen desselben Starts. Ein wall-Graph zeigt auch viele untätige Threads, etwa Webserver-Threads. Ignorieren Sie diese und konzentrieren Sie sich auf den Startup-Thread.