How Do You Identify What Makes Your Service Expensive to Start?

What Makes a Service Expensive to Start?

A service is expensive to start when it needs much time, much CPU, or both before it can serve traffic. Three measures describe the cost:

a. Time to Ready: Time to Ready is the time from the start of the container to the moment when the pod becomes Ready. A long time to Ready delays rollouts, slows scale-out, and raises the risk of failed probes. This command prints the two timestamps for the container named app:

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

The difference between the two values is the time to Ready. The Spring Boot log line “Started ... in N seconds” gives a smaller number. It starts when the application starts, and it does not include the time that the JVM and the container need to start.

b. CPU-seconds until Ready: One CPU-second is one CPU working for one second. CPU-seconds until Ready is the total CPU work of startup. A container cannot use more CPU than its limit, so the CPU-seconds divided by the limit is the shortest possible time to Ready. On cgroup v2, read the field usage_usec as soon as the pod becomes Ready:

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

The field usage_usec is the CPU time that the container has used since it started, in microseconds. Divide it by 1,000,000 to get CPU-seconds. The fields nr_throttled and throttled_usec in the same file show how much the kernel throttled the container. If you read the file late, the value includes work after Ready.

c. Warmup after readiness: Ready does not mean fast. When the pod becomes Ready, the JVM still runs many methods in the interpreter, which is slow, and the JIT compilers keep compiling in the background. During this warmup, the service uses more CPU than in the steady state, and the first requests can be slow. If you lower the resources at the moment of Ready, you can slow the warmup. You should measure the CPU use for several minutes after Ready, and not only until Ready.

Startup Profiling Tools

There are three tools to find the cause of an expensive startup. You can start with the cheapest one, and use the next tool only when you need more detail:

a. Logs and the Spring Boot startup endpoint: The Spring Boot log line “Started ... in N seconds” gives a first number. For more detail, the startup endpoint of Spring Boot Actuator lists each startup step with its duration. It needs a BufferingApplicationStartup in the application:

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

The number 4096 is the capacity of the buffer, which is the maximum number of steps that it holds. Then expose the endpoint. Keep health in the list, so that your probes keep working:

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

A GET request to /actuator/startup returns a snapshot of the steps. A POST request returns the steps and clears the buffer. Each step has a name, a duration, and tags such as the bean name. Check the longest steps first. Names such as spring.beans.instantiate, spring.context.config-classes.parse, and spring.context.refresh show where the time goes. For spring.beans.instantiate, the tag beanName names the bean, so you can find the slowest bean. The step names can change between Spring versions.

Two JVM log options add more data. The option -Xlog:gc* writes the garbage collection events, and the option -Xlog:class+load writes each class load. You can pass both in JAVA_TOOL_OPTIONS.

b. Java Flight Recorder (JFR): JFR is built into the JDK. It records events from the JVM, such as garbage collections, JIT compilations, and execution samples. The default settings add very little overhead, and the profile settings record more events. JFR starts with the JVM when you use the option -XX:StartFlightRecording, so it captures the whole startup. After you copy the file out of the pod, read it with the jfr tool of the JDK or with 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

The first command lists the event types and their counts. The second command prints the garbage collection events and the JIT compilations with their durations. The third command prints samples of the code that the threads run, with a stack depth of 8 frames. The event jdk.Compilation records only compilations that take longer than the threshold of your settings.

c. async-profiler: async-profiler is a sampling profiler for Java, and it writes flame graphs. Two of its modes matter for startup. The cpu mode samples only the threads that use CPU, so it shows what consumes CPU. The wall mode samples all threads at a fixed interval, whether they run, sleep, or wait, so it shows where the time goes, including waits. async-profiler can start with the JVM as an agent, so it captures the first second.

Capturing a Startup Profile in Kubernetes

The recording must start with the JVM, and it must run under the real conditions of the service. Two points matter:

a. Profile under production CPU limits: Use the same image, the same JVM flags, and the same CPU and memory settings as in production. A different limit changes the startup itself. It changes the throttling, the CPU count that the JVM sees, and the collector that the JVM selects. A profile that you take without the production limit shows a different startup. For deep-dive, read CPU throttling during JVM startup.

This pod template starts JFR with the JVM and writes the file to a 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

Each setting has one job:

• filename=/profiles/startup-%p.jfr writes the file to the volume. The text %p becomes the process ID.
• settings=profile records more events than the default settings.
• duration=120s stops the recording after 120 seconds. Choose a time that covers the startup and several minutes of warmup.
• dumponexit=true writes the file even if the JVM exits early, for example when a probe kills the container.
• emptyDir gives a writable folder even when the root file system is read-only. The sizeLimit stops a large file from filling the disk of the node.
• The CPU and memory values are examples. Use your production values.

In a container, the JVM is usually process 1, so the text %p becomes 1, and the file is named startup-1.jfr. If you want to keep the files of several runs in one volume, add %t to the file name. It adds a timestamp. Both JFR and async-profiler accept %t.

To use async-profiler, put libasyncProfiler.so in the image, or in a volume that an init container fills with the release archive of async-profiler. Then change the environment variable:

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

The agent options work like this: start begins profiling when the JVM starts, event=cpu selects the CPU mode, threads profiles each thread separately, timeout=120 stops after 120 seconds, and file=...html writes a flame graph. For a wall-clock profile, replace event=cpu with event=wall,interval=10ms. Containers often block perf events. If the profiler fails to start, use event=ctimer, which works without perf events.

Run one profiler in each run, and repeat each run three times. One run can mislead you.

b. Copying profiles out of the pod: Use kubectl cp to copy the folder to your computer:

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

The command needs the tar program in the container image. If the image has no tar, the command fails. In that case, mount the same volume in a small second container that has tar, and use its name with -c. Copy the files before the pod is removed, because Kubernetes deletes an emptyDir volume with the pod. Open an HTML file in a browser.

Reading a Startup Flame Graph

A flame graph shows the stack traces of all samples. Each box is a method, and its width is the share of the samples that include it. In an async-profiler graph, the outermost frames, such as main, are at the bottom, and the leaf frames, which do the work, are at the top. Wide boxes are where the time goes. Because of the threads option, each thread has its own tower, and the tower starts with a box that names the thread. Linux cuts thread names to 15 characters, so long names look shorter in the graph. Three groups of threads matter:

a. Application threads: The thread that runs main runs the startup code of the application. Its root box can be named main or DestroyJavaVM, so find it by the frame SpringApplication.run and not by its name. A wide SpringApplication.run tower, or a wide refresh tower, means that framework startup uses most of the time. Wide boxes with defineClass or loadClass mean class loading. Wide boxes with your own package names mean your own startup code, such as a cache load or a database migration.

b. JIT compiler threads: Roots that start with C1 CompilerThre and C2 CompilerThre are the JIT compilers. The full thread names are C1 CompilerThread0, C2 CompilerThread0, and so on. If these towers are as wide as the tower of the startup thread, JIT work is a large part of the startup CPU. To see which frames run in the interpreter, write the profile to a file with the extension .collapsed, and add the option ann. In that file, interpreted frames end with _[0], C1 frames with _[1], other compiled frames with _[j], and inlined frames with _[i]. Many _[0] frames in the startup thread mean that the code is not compiled yet. The HTML graph does not add these endings. It shows the frame types with colors.

c. GC threads: With G1, roots such as GC Thread#0, G1 Conc#0, and G1 Refine#0 do the garbage collection work. With the Serial collector, the VM Thread does it. A CPU limit of 1 CPU or less, or a memory limit below 1792 MB, makes the JVM select the Serial collector, so a graph from such a pod has no GC worker threads. A wide garbage collection tower in the first seconds means that the heap is too small for the allocation of startup, or that it grows many times. Confirm this with the jdk.GarbageCollection events of JFR, where the event name shows the collector (for example, DefNew and SerialOld belong to the Serial collector), or with the log option -Xlog:gc*.

Compare a cpu graph with a wall graph of the same startup. A wall graph also shows many idle threads, such as web server threads. Ignore them, and focus on the startup thread.