Cosa rende costoso l'avvio del suo servizio? Ecco come scoprirlo

Cosa rende costoso l'avvio di un servizio?

Un servizio è costoso da avviare quando ha bisogno di molto tempo, molta CPU, o entrambi, prima di poter servire traffico. Tre misure descrivono il costo:

a. Tempo fino a Ready: Il tempo fino a Ready è il tempo che intercorre tra l'avvio del container e il momento in cui il pod diventa Ready. Un tempo fino a Ready lungo ritarda i rollout, rallenta lo scale-out e aumenta il rischio di probe fallite. Questo comando stampa i due timestamp per il container denominato app:

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

La differenza tra i due valori è il tempo fino a Ready. La riga di log di Spring Boot "Started ... in N seconds" fornisce un numero più piccolo: parte dall'avvio dell'applicazione e non include il tempo necessario alla JVM e al container per avviarsi.

b. CPU-secondi fino a Ready: Un CPU-secondo è una CPU che lavora per un secondo. I CPU-secondi fino a Ready sono il lavoro CPU totale dell'avvio. Un container non può usare più CPU del suo limite, quindi i CPU-secondi divisi per il limite rappresentano il tempo fino a Ready minimo possibile. Su cgroup v2, leggere il campo usage_usec non appena il pod diventa Ready:

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

Il campo usage_usec è il tempo di CPU usato dal container dal momento dell'avvio, in microsecondi. Dividerlo per 1.000.000 per ottenere i CPU-secondi. I campi nr_throttled e throttled_usec nello stesso file mostrano quanto il kernel ha applicato throttling al container. Se il file viene letto in ritardo, il valore include anche il lavoro successivo al Ready.

c. Warmup dopo la readiness: Ready non significa veloce. Quando il pod diventa Ready, la JVM esegue ancora molti metodi nell'interprete, che è lento, e i compilatori JIT continuano a compilare in background. Durante questo warmup il servizio usa più CPU rispetto al funzionamento a regime e le prime richieste possono essere lente. Riducendo le risorse al momento del Ready si rischia di rallentare il warmup. È opportuno misurare l'uso di CPU per diversi minuti dopo il Ready, e non solo fino al Ready.

Strumenti di profiling dell'avvio

Esistono tre strumenti per trovare la causa di un avvio costoso. Si può iniziare dal più economico e passare allo strumento successivo solo quando serve maggiore dettaglio:

a. Log ed endpoint startup di Spring Boot: La riga di log di Spring Boot "Started ... in N seconds" fornisce un primo numero. Per maggiore dettaglio, l'endpoint startup di Spring Boot Actuator elenca ogni step di avvio con la sua durata. Richiede un BufferingApplicationStartup nell'applicazione:

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

Il numero 4096 è la capacità del buffer, ovvero il numero massimo di step che può contenere. Esporre quindi l'endpoint, mantenendo health nell'elenco affinché le probe continuino a funzionare:

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

Una richiesta GET a /actuator/startup restituisce uno snapshot degli step. Una richiesta POST restituisce gli step e svuota il buffer. Ogni step ha un nome, una durata e tag come il nome del bean. Controllare prima gli step più lunghi. Nomi come spring.beans.instantiate, spring.context.config-classes.parse e spring.context.refresh mostrano dove va il tempo. Per spring.beans.instantiate, il tag beanName indica il bean, così da individuare il bean più lento. I nomi degli step possono cambiare tra le versioni di Spring.

Due opzioni di log della JVM aggiungono altri dati. L'opzione -Xlog:gc* scrive gli eventi di garbage collection e l'opzione -Xlog:class+load scrive ogni caricamento di classe. Entrambe possono essere passate in JAVA_TOOL_OPTIONS.

b. Java Flight Recorder (JFR): JFR è integrato nel JDK. Registra eventi dalla JVM, come garbage collection, compilazioni JIT e campioni di esecuzione. Le impostazioni predefinite aggiungono un overhead minimo, mentre le impostazioni profile registrano più eventi. JFR parte insieme alla JVM quando si usa l'opzione -XX:StartFlightRecording, quindi cattura l'intero avvio. Dopo aver copiato il file fuori dal pod, lo si può leggere con lo strumento 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

Il primo comando elenca i tipi di evento e i relativi conteggi. Il secondo comando stampa gli eventi di garbage collection e le compilazioni JIT con le rispettive durate. Il terzo comando stampa campioni del codice eseguito dai thread, con una profondità di stack di 8 frame. L'evento jdk.Compilation registra solo le compilazioni che superano la soglia definita nelle impostazioni.

c. async-profiler: async-profiler è un profiler a campionamento per Java e genera flame graph. Due delle sue modalità sono rilevanti per l'avvio. La modalità cpu campiona solo i thread che usano CPU, quindi mostra cosa consuma CPU. La modalità wall campiona tutti i thread a intervalli fissi, che siano in esecuzione, in sleep o in attesa, quindi mostra dove va il tempo, attese incluse. async-profiler può partire con la JVM come agent, così cattura anche il primo secondo.

Catturare un profilo di avvio in Kubernetes

La registrazione deve partire con la JVM e deve avvenire nelle condizioni reali del servizio. Due punti sono importanti:

a. Profilare con i limiti di CPU di produzione: Usare la stessa immagine, gli stessi flag JVM e le stesse impostazioni di CPU e memoria della produzione. Un limite diverso cambia l'avvio stesso: cambia il throttling, il numero di CPU che la JVM vede e il collector che la JVM seleziona. Un profilo acquisito senza il limite di produzione mostra un avvio diverso. Per un approfondimento, si veda il CPU throttling durante l'avvio della JVM.

Questo template di pod avvia JFR con la JVM e scrive il file su 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

Ogni impostazione ha un compito preciso:

• filename=/profiles/startup-%p.jfr scrive il file sul volume. Il testo %p diventa l'ID del processo.
• settings=profile registra più eventi rispetto alle impostazioni predefinite.
• duration=120s interrompe la registrazione dopo 120 secondi. Scegliere una durata che copra l'avvio e diversi minuti di warmup.
• dumponexit=true scrive il file anche se la JVM termina prima, ad esempio quando una probe termina il container.
• emptyDir fornisce una cartella scrivibile anche quando il file system root è in sola lettura. Il sizeLimit evita che un file di grandi dimensioni riempia il disco del nodo.
• I valori di CPU e memoria sono esempi. Usare i propri valori di produzione.

In un container la JVM è di solito il processo 1, quindi il testo %p diventa 1 e il file si chiama startup-1.jfr. Per conservare i file di più run in un unico volume, aggiungere %t al nome del file: aggiunge un timestamp. Sia JFR sia async-profiler accettano %t.

Per usare async-profiler, inserire libasyncProfiler.so nell'immagine, oppure in un volume che un init container riempie con l'archivio di release di async-profiler. Poi modificare la variabile d'ambiente:

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

Le opzioni dell'agent funzionano così: start avvia il profiling quando parte la JVM, event=cpu seleziona la modalità CPU, threads profila ogni thread separatamente, timeout=120 si ferma dopo 120 secondi e file=...html scrive un flame graph. Per un profilo wall-clock, sostituire event=cpu con event=wall,interval=10ms. I container spesso bloccano i perf event. Se il profiler non parte, usare event=ctimer, che funziona senza perf event.

Eseguire un solo profiler per ogni run e ripetere ogni run tre volte. Una singola run può trarre in inganno.

b. Copiare i profili fuori dal pod: Usare kubectl cp per copiare la cartella sul proprio computer:

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

Il comando richiede il programma tar nell'immagine del container. Se l'immagine non include tar, il comando fallisce. In tal caso, montare lo stesso volume in un piccolo secondo container dotato di tar e usare il suo nome con -c. Copiare i file prima che il pod venga rimosso, perché Kubernetes elimina un volume emptyDir insieme al pod. Aprire un file HTML in un browser.

Leggere un flame graph di avvio

Un flame graph mostra gli stack trace di tutti i campioni. Ogni riquadro è un metodo e la sua larghezza è la quota di campioni che lo includono. In un grafico di async-profiler i frame più esterni, come main, stanno in basso, mentre i frame foglia, che svolgono il lavoro, stanno in alto. I riquadri larghi indicano dove va il tempo. Grazie all'opzione threads, ogni thread ha la sua torre, che inizia con un riquadro con il nome del thread. Linux tronca i nomi dei thread a 15 caratteri, quindi i nomi lunghi appaiono accorciati nel grafico. Tre gruppi di thread sono rilevanti:

a. Thread dell'applicazione: Il thread che esegue main esegue il codice di avvio dell'applicazione. Il suo riquadro radice può chiamarsi main o DestroyJavaVM, quindi va individuato tramite il frame SpringApplication.run e non dal nome. Una torre SpringApplication.run larga, o una torre refresh larga, significa che l'avvio del framework usa la maggior parte del tempo. Riquadri larghi con defineClass o loadClass indicano il caricamento delle classi. Riquadri larghi con i nomi dei propri package indicano il proprio codice di avvio, come il caricamento di una cache o una migrazione del database.

b. Thread del compilatore JIT: Le radici che iniziano con C1 CompilerThre e C2 CompilerThre sono i compilatori JIT. I nomi completi dei thread sono C1 CompilerThread0, C2 CompilerThread0 e così via. Se queste torri sono larghe quanto la torre del thread di avvio, il lavoro JIT è una parte consistente della CPU di avvio. Per vedere quali frame girano nell'interprete, scrivere il profilo in un file con estensione .collapsed e aggiungere l'opzione ann. In quel file, i frame interpretati terminano con _[0], i frame C1 con _[1], gli altri frame compilati con _[j] e i frame inlined con _[i]. Molti frame _[0] nel thread di avvio significano che il codice non è ancora compilato. Il grafico HTML non aggiunge questi suffissi: mostra i tipi di frame con i colori.

c. Thread GC: Con G1, radici come GC Thread#0, G1 Conc#0 e G1 Refine#0 svolgono il lavoro di garbage collection. Con il collector Serial, lo fa il VM Thread. Un limite di CPU di 1 CPU o meno, o un limite di memoria sotto i 1792 MB, fa sì che la JVM selezioni il collector Serial, quindi un grafico proveniente da un pod di questo tipo non ha thread worker del GC. Una torre di garbage collection larga nei primi secondi significa che l'heap è troppo piccolo per le allocazioni dell'avvio, o che cresce molte volte. Confermarlo con gli eventi jdk.GarbageCollection di JFR, dove il nome dell'evento indica il collector (ad esempio DefNew e SerialOld appartengono al collector Serial), oppure con l'opzione di log -Xlog:gc*.

Confrontare un grafico cpu con un grafico wall dello stesso avvio. Un grafico wall mostra anche molti thread inattivi, come i thread del web server. Ignorarli e concentrarsi sul thread di avvio.