Como identificar o que torna seu serviço caro para iniciar?

O que torna um serviço caro para iniciar?

Um serviço é caro para iniciar quando precisa de muito tempo, muita CPU, ou ambos, antes de poder atender tráfego. Três medidas descrevem esse custo:

a. Tempo até Ready: O tempo até Ready é o tempo entre o início do contêiner e o momento em que o pod fica Ready. Um tempo até Ready longo atrasa os rollouts, deixa o scale-out mais lento e aumenta o risco de falha nas probes. Este comando imprime os dois timestamps para o contêiner chamado app:

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

A diferença entre os dois valores é o tempo até Ready. A linha de log do Spring Boot "Started ... in N seconds" mostra um número menor. Ela começa a contar quando a aplicação inicia e não inclui o tempo que a JVM e o contêiner precisam para iniciar.

b. CPU-segundos até o Ready: Um CPU-segundo é uma CPU trabalhando por um segundo. Os CPU-segundos até o Ready representam o trabalho total de CPU da inicialização. Um contêiner não pode usar mais CPU do que o seu limite, então os CPU-segundos divididos pelo limite são o menor tempo possível até Ready. No cgroup v2, leia o campo usage_usec assim que o pod ficar Ready:

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

O campo usage_usec é o tempo de CPU que o contêiner usou desde que iniciou, em microssegundos. Divida-o por 1.000.000 para obter os CPU-segundos. Os campos nr_throttled e throttled_usec no mesmo arquivo mostram quanto o kernel aplicou throttling ao contêiner. Se você ler o arquivo tarde demais, o valor inclui o trabalho feito depois do Ready.

c. Warmup depois do Ready: Ready não significa rápido. Quando o pod fica Ready, a JVM ainda executa muitos métodos no interpretador, que é lento, e os compiladores JIT continuam compilando em segundo plano. Durante esse warmup, o serviço usa mais CPU do que no estado estável, e as primeiras requisições podem ser lentas. Se você reduzir os recursos no momento do Ready, pode deixar o warmup mais lento. Meça o uso de CPU por vários minutos depois do Ready, e não apenas até o Ready.

Ferramentas de profiling de inicialização

Existem três ferramentas para encontrar a causa de uma inicialização cara. Comece pela mais barata e use a próxima só quando precisar de mais detalhes:

a. Logs e o endpoint de startup do Spring Boot: A linha de log do Spring Boot "Started ... in N seconds" dá um primeiro número. Para mais detalhes, o endpoint startup do Spring Boot Actuator lista cada etapa da inicialização com sua duração. Ele exige um BufferingApplicationStartup na aplicação:

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

O número 4096 é a capacidade do buffer, ou seja, o número máximo de etapas que ele armazena. Depois, exponha o endpoint. Mantenha health na lista para que as suas probes continuem funcionando:

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

Uma requisição GET para /actuator/startup retorna um snapshot das etapas. Uma requisição POST retorna as etapas e limpa o buffer. Cada etapa tem um nome, uma duração e tags, como o nome do bean. Verifique primeiro as etapas mais longas. Nomes como spring.beans.instantiate, spring.context.config-classes.parse e spring.context.refresh mostram para onde o tempo está indo. Para spring.beans.instantiate, a tag beanName identifica o bean, então você consegue encontrar o bean mais lento. Os nomes das etapas podem mudar entre versões do Spring.

Duas opções de log da JVM acrescentam mais dados. A opção -Xlog:gc* grava os eventos de coleta de lixo, e a opção -Xlog:class+load grava cada carregamento de classe. Você pode passar as duas em JAVA_TOOL_OPTIONS.

b. Java Flight Recorder (JFR): O JFR vem embutido no JDK. Ele registra eventos da JVM, como coletas de lixo, compilações JIT e amostras de execução. As configurações padrão adicionam pouquíssimo overhead, e as configurações profile registram mais eventos. O JFR inicia junto com a JVM quando você usa a opção -XX:StartFlightRecording, então ele captura toda a inicialização. Depois de copiar o arquivo para fora do pod, leia-o com a ferramenta jfr do JDK ou com o 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

O primeiro comando lista os tipos de evento e suas contagens. O segundo imprime os eventos de coleta de lixo e as compilações JIT com suas durações. O terceiro imprime amostras do código que as threads executam, com uma profundidade de pilha de 8 frames. O evento jdk.Compilation registra apenas compilações que levam mais tempo do que o limite das suas configurações.

c. async-profiler: O async-profiler é um profiler por amostragem para Java que gera flame graphs. Dois dos seus modos são relevantes para a inicialização. O modo cpu amostra apenas as threads que usam CPU, mostrando o que consome CPU. O modo wall amostra todas as threads em um intervalo fixo, estejam elas executando, dormindo ou esperando, mostrando para onde o tempo vai, incluindo as esperas. O async-profiler pode iniciar junto com a JVM como agente, capturando o primeiro segundo.

Capturando um perfil de inicialização no Kubernetes

A gravação precisa iniciar junto com a JVM e rodar sob as condições reais do serviço. Dois pontos importam:

a. Faça o profiling com os limites de CPU de produção: Use a mesma imagem, as mesmas flags de JVM e as mesmas configurações de CPU e memória da produção. Um limite diferente muda a própria inicialização. Ele altera o throttling, a contagem de CPUs que a JVM enxerga e o coletor que a JVM seleciona. Um perfil capturado sem o limite de produção mostra uma inicialização diferente. Para se aprofundar, leia CPU throttling during JVM startup.

Este template de pod inicia o JFR junto com a JVM e grava o arquivo em um 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

Cada configuração tem uma função:

• filename=/profiles/startup-%p.jfr grava o arquivo no volume. O texto %p vira o ID do processo.
• settings=profile registra mais eventos do que as configurações padrão.
• duration=120s encerra a gravação após 120 segundos. Escolha um tempo que cubra a inicialização e vários minutos de warmup.
• dumponexit=true grava o arquivo mesmo se a JVM encerrar antes, por exemplo, quando uma probe mata o contêiner.
• emptyDir oferece uma pasta gravável mesmo quando o sistema de arquivos raiz é somente leitura. O sizeLimit evita que um arquivo grande encha o disco do node.
• Os valores de CPU e memória são exemplos. Use os seus valores de produção.

Em um contêiner, a JVM geralmente é o processo 1, então o texto %p vira 1 e o arquivo fica com o nome startup-1.jfr. Se você quiser manter os arquivos de várias execuções em um único volume, adicione %t ao nome do arquivo. Ele adiciona um timestamp. Tanto o JFR quanto o async-profiler aceitam %t.

Para usar o async-profiler, coloque o libasyncProfiler.so na imagem ou em um volume que um init container preenche com o arquivo de release do async-profiler. Depois, mude a variável de ambiente:

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

As opções do agente funcionam assim: start inicia o profiling quando a JVM inicia, event=cpu seleciona o modo de CPU, threads faz o profiling de cada thread separadamente, timeout=120 encerra após 120 segundos e file=...html grava um flame graph. Para um perfil de wall-clock, substitua event=cpu por event=wall,interval=10ms. Contêineres costumam bloquear eventos perf. Se o profiler não iniciar, use event=ctimer, que funciona sem eventos perf.

Use apenas um profiler em cada execução e repita cada execução três vezes. Uma única execução pode enganar você.

b. Copiando os perfis para fora do pod: Use kubectl cp para copiar a pasta para o seu computador:

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

O comando precisa do programa tar na imagem do contêiner. Se a imagem não tiver tar, o comando falha. Nesse caso, monte o mesmo volume em um pequeno segundo contêiner que tenha tar e use o nome dele com -c. Copie os arquivos antes que o pod seja removido, porque o Kubernetes apaga um volume emptyDir junto com o pod. Abra um arquivo HTML no navegador.

Lendo um flame graph de inicialização

Um flame graph mostra os stack traces de todas as amostras. Cada caixa é um método, e a sua largura é a fração das amostras que o incluem. Em um gráfico do async-profiler, os frames mais externos, como main, ficam na base, e os frames folha, que fazem o trabalho, ficam no topo. Caixas largas mostram para onde o tempo vai. Por causa da opção threads, cada thread tem a sua própria torre, e a torre começa com uma caixa que traz o nome da thread. O Linux corta os nomes das threads em 15 caracteres, então nomes longos aparecem encurtados no gráfico. Três grupos de threads importam:

a. Threads da aplicação: A thread que executa main roda o código de inicialização da aplicação. A sua caixa raiz pode se chamar main ou DestroyJavaVM, então encontre-a pelo frame SpringApplication.run, e não pelo nome. Uma torre larga de SpringApplication.run, ou uma torre larga de refresh, significa que a inicialização do framework consome a maior parte do tempo. Caixas largas com defineClass ou loadClass indicam carregamento de classes. Caixas largas com os nomes dos seus próprios pacotes indicam código de inicialização seu, como o carregamento de um cache ou uma migração de banco de dados.

b. Threads do compilador JIT: Raízes que começam com C1 CompilerThre e C2 CompilerThre são os compiladores JIT. Os nomes completos das threads são C1 CompilerThread0, C2 CompilerThread0 e assim por diante. Se essas torres forem tão largas quanto a torre da thread de inicialização, o trabalho do JIT é uma parte grande da CPU da inicialização. Para ver quais frames rodam no interpretador, grave o perfil em um arquivo com a extensão .collapsed e adicione a opção ann. Nesse arquivo, frames interpretados terminam com _[0], frames do C1 com _[1], outros frames compilados com _[j] e frames inlined com _[i]. Muitos frames _[0] na thread de inicialização significam que o código ainda não foi compilado. O gráfico HTML não adiciona esses sufixos. Ele mostra os tipos de frame com cores.

c. Threads de GC: Com o G1, raízes como GC Thread#0, G1 Conc#0 e G1 Refine#0 fazem o trabalho de coleta de lixo. Com o coletor Serial, a VM Thread faz esse trabalho. Um limite de CPU de 1 CPU ou menos, ou um limite de memória abaixo de 1.792 MB, faz a JVM selecionar o coletor Serial, então um gráfico de um pod assim não tem worker threads de GC. Uma torre larga de coleta de lixo nos primeiros segundos significa que o heap é pequeno demais para a alocação da inicialização, ou que ele cresce muitas vezes. Confirme isso com os eventos jdk.GarbageCollection do JFR, em que o nome do evento mostra o coletor (por exemplo, DefNew e SerialOld pertencem ao coletor Serial), ou com a opção de log -Xlog:gc*.

Compare um gráfico cpu com um gráfico wall da mesma inicialização. Um gráfico wall também mostra muitas threads ociosas, como as threads do servidor web. Ignore-as e foque na thread de inicialização.