《Java 虚拟机原理与性能调优》9.1 启动耗时分解：类加载、解释执行与首请求

本节目标：把「服务启动要多久」拆成可分别测量的五段，并说明每一段该用什么工具证明，最后给出 libraryd 的启动探针与 readiness 设计。
适用版本：JDK 25（Temurin 25.0.5+8）。本机口径：Apple M1 Pro，10 核，32 GB，macOS 26.3 (25D125)，默认 G1，压缩 oops，默认 MaxHeapSize 8 GB，G1 Region 4 MB。

承接的问题

libraryd 的容器启动日志里有两行时间：一行是进程拉起，一行是 Javalin 打印监听端口。运维看到 readiness 探针变绿，就把流量切进来，然后在监控上看到第一个借阅请求的 p99 比后续请求高一个数量级。

团队里出现了三种说法：

• 「启动慢是 JVM 参数问题，加 -XX:TieredStopAtLevel=1 就好。」
• 「readiness 已经通过，说明服务已经就绪，首请求慢是偶发。」
• 「启动时间就是 main 方法前后打两个时间戳。」

这三种说法都只看到了启动的一段。进程从 execve 到能稳定处理业务请求，至少经过：

1. 操作系统加载可执行文件、初始化 JVM 运行时。
2. VM 初始化：创建堆、加载 java.lang 核心类、启动 VMThread。
3. 应用 main 执行：加载框架类、建立连接池、绑定端口。
4. main 返回或服务器开始监听，此时 readiness 可以变绿。
5. 第一个真实业务请求：按需加载领域类、序列化类、JIT 编译热点方法。

本节逐个测量这五段。所有数字都是本机单次实验的重复统计，不代表生产环境的绝对启动时间。

一、把启动拆成五个时间点

先用一个最小的 Hello 和一个与 libraryd 同构的最小 HTTP 服务做对照。Hello 只有一行输出，用来隔离 JVM 自身的启动成本；MiniHttpd 用 com.sun.net.httpserver 加虚拟线程，暴露 /health 与 /api/loans/{id}，端口 18150。

测量脚本用 Python 的 perf_counter 包住子进程，避免 shell 计时把脚本自身的启动算进去：

import subprocess, time

JAVA = "/Users/bingrong.yan/.jdks/jdk-25.0.5+8/Contents/Home/bin/java"

def bench(cmd, n=10):
    times = []
    for _ in range(n):
        t = time.perf_counter()
        subprocess.run(cmd, capture_output=True, check=True)
        times.append((time.perf_counter() - t) * 1000)
    return times

本机运行 10 次，Hello 的分布是：

Hello default: min=55.4 median=86.8 mean=88.9 max=116.3 ms runs=10

同一个 JVM、同一个 classpath，最短 55 ms，最长 116 ms，相差一倍。这个波动来自操作系统调度、文件缓存、ASLR、后台进程竞争，不是 JVM 参数能消除的。单次启动数字没有意义，至少跑 10 次看中位数和范围。

最小 HTTP 服务的「进程启动到打印监听」是：

MiniHttpd ready(default): min=97.2 median=117.8 mean=115.7 max=133.2 ms runs=10

比 Hello 多约 30 ms。这 30 ms 就是加载 com.sun.net.httpserver、虚拟线程调度器、MiniHttpd 自身类和绑定端口的成本。此时进程已经能接受 TCP 连接，但还没有处理过任何业务请求。

jcmd 能佐证 VM 自己的计时。对一个刚启动 1.3 秒的进程执行：

jcmd <pid> VM.uptime

本机输出：

73430:
1.295 s

VM.uptime 从 VM 初始化完成开始算，不包含操作系统加载二进制的时间。它适合判断「JVM 活了多久」，不适合作为对外承诺的启动时间。同一时刻 VM.info 还会给出堆大小和 CDS 映射信息，这些在 9.2 会用到。

二、VM 初始化：-Xlog:init 没有输出，startuptime 才有

很多资料会建议用 -Xlog:init 看 VM 初始化。本机 Temurin 25.0.5+8 上实测：

java "-Xlog:init" -cp out Hello
java "-Xlog:init=trace" -cp out Hello

两条命令都只输出 libraryd hello，没有任何 [init] 日志。-Xlog:help 里确实列出了 init 标签，但这个构建在这个路径上没有对应的日志点。不要因为「标签存在」就认为「一定有输出」。

真正可用的是 startuptime。注意 zsh 下 -Xlog: 参数必须加引号，否则 * 或逗号可能被 shell 处理：

java "-Xlog:startuptime" -cp out MiniHttpd 18150

本机输出的关键阶段：

[0.016s][info][startuptime] Genesis, 0.0045007 secs
[0.017s][info][startuptime] Interpreter generation, 0.0003988 secs
[0.018s][info][startuptime] Start VMThread, 0.0001307 secs
[0.032s][info][startuptime] Initialize java.lang classes, 0.0139598 secs
[0.032s][info][startuptime] Initialize java.lang.invoke classes, 0.0001850 secs
[0.034s][info][startuptime] Initialize module system, 0.0013092 secs
[0.034s][info][startuptime] Create VM, 0.0313538 secs

Create VM 约 31 ms，其中 Initialize java.lang classes 约 14 ms，占了一半。Genesis 是堆和基础结构的创建，约 4.5 ms。这些数字与 Hello 的 55 到 116 ms 对得上：VM 初始化只是启动的一部分，剩下的时间在加载应用类、初始化框架和等待调度。

startuptime 的粒度是 JVM 内部阶段，不包含 main 之后的业务初始化。要测后者，仍然要在应用代码里打点，或者用 JFR 的类加载事件。

三、类加载：415 个类里 412 个来自共享归档

用 -Xlog:class+load=info 统计启动时加载了多少类。命令仍然要加引号：

java "-Xlog:class+load=info" -cp out Hello

本机统计结果：

Hello -> total=415 shared=412 jar=0 appfile=1
MiniHttpd -> total=873 shared=834 jar=0 appfile=1

Hello 启动了 415 个类，其中 412 个来自 JDK 自带的 CDS 共享归档（日志里写 source: shared objects file）。只有 Hello 自己来自 file:。最小 HTTP 服务加载 873 个类，834 个仍然来自共享归档。

这解释了为什么 9.2 的 AppCDS 对很小的应用收益有限：JDK 核心类已经被默认归档覆盖，应用自己只有一两个类，能额外归档的东西太少。

还有一个容易忽略的细节：MiniHttpd 启动时日志里只有 MiniHttpd 一个应用类，MiniHttpd$Loan 直到第一个 /api/loans/42 请求才被加载。类加载是惰性的，readiness 通过时，业务类很可能还没进元空间。

JFR 也能记录类加载事件，但默认的 profile 设置下 jdk.ClassLoad 可能是关闭的。直接开录会看到 0 个事件：

java -XX:StartFlightRecording=filename=classload.jfr,settings=profile \
  -cp out MiniHttpd 18150
jfr summary classload.jfr

本机 jdk.ClassLoad 计数为 0。需要显式开启：

java "-XX:StartFlightRecording=filename=classload.jfr,settings=profile,jdk.ClassLoad#enabled=true,jdk.ClassDefine#enabled=true" \
  -cp out MiniHttpd 18150

开启后，同一段启动加三个请求的记录里：

jdk.ClassLoad                             545          8518
jdk.ClassDefine                           385          4659
jdk.ClassLoadingStatistics                  1            10

jdk.ClassLoad 是「尝试加载」，jdk.ClassDefine 是「真正定义类」。两者数量不同，因为有些类由父加载器命中缓存，不需要重新定义。排查「启动时到底加载了哪些应用类」时，用 jfr print --events jdk.ClassLoad 过滤 source: file: 比数总数更有用。

四、解释执行与 JIT：短命进程的取舍

-XX:TieredStopAtLevel=1 让 JIT 只用到 C1，不进入 C2。对短命进程，这能省掉 C2 编译线程和编译时间；对长跑服务，会损失峰值性能。本机对照：

Hello default:              min=55.4 median=86.8 mean=88.9 max=116.3 ms
Hello TieredStopAtLevel=1:  min=56.3 median=66.1 mean=69.8 max=96.2 ms
Hello -Xint:                min=59.5 median=72.0 mean=71.0 max=86.8 ms
MiniHttpd ready(default):   median=117.8 ms
MiniHttpd ready(C1 only):   median=104.3 ms

TieredStopAtLevel=1 把 Hello 的中位数从 86.8 ms 降到 66.1 ms，约 24%。-Xint 也接近，因为 Hello 根本没有多少代码要编译。这个结论只适用于「启动后很快退出」的进程。

对 libraryd 这种长跑服务，C1 only 会让前几秒的吞吐明显低于 C2，而启动只省十几毫秒。除非是 CLI 或一次性批处理，不要为了启动时间牺牲稳态性能。

反过来，CPU 密集型端点的稳态性能完全依赖 JIT。10.3 会用同一套基线脚本对比：/api/reports/summary?n=20000 在默认模式下约 6190 req/s，加 -Xint 后只剩 69.5 req/s。启动阶段看不出这个差距，因为请求还没开始。

五、首请求就绪：readiness 通过不等于业务就绪

启动脚本打印监听后，连续发四个请求，测每次的端到端耗时（每次新建 TCP 连接，包含连接建立）：

first loan:   87.2 63.3 52.7 54.5 63.5 ms
second loan:   3.6  4.2  3.4  3.0  3.1 ms
third loan:    3.5  2.9  3.1  2.8  3.3 ms
first report: 10.1 11.8 10.1  9.7 10.2 ms

第一个 /api/loans/42 要 52 到 87 ms，第二个降到 3 ms 左右。差距不是网络，而是第一次请求触发的类加载、JIT 编译和 Loan record 的初始化。/api/reports/summary 的首次请求也要 10 ms，因为它要加载报告路径上的类。

如果 readiness 只探 /health，它不会触发 /api/loans 路径的类加载。Kubernetes 看到 readiness 变绿就切流量，第一个真实用户就要承担这 50 到 80 ms。对 p99 敏感的服务，这段延迟会直接体现为「发布后第一分钟 p99 尖刺」。

正确的做法不是把 readiness 做成重负载自检，而是：

1. 启动完成后主动 warmup 代表路径，把类加载和首轮 JIT 提前。
2. readiness 检查依赖（数据库、连接池）和一个已经 warmup 的轻量端点。
3. 在发布策略上给新实例一个短暂的「预热窗口」，再逐步放大流量。

在 libraryd 里落地

libraryd-app 增加一个 StartupTimeline，把五个时间点记录下来：

package com.plume.library.app;

import java.lang.management.ManagementFactory;

public final class StartupTimeline {

    private final long processStartNanos;
    private final long vmStartMillis;
    private long readyNanos;
    private long firstRequestNanos;

    public StartupTimeline(long processStartNanos) {
        this.processStartNanos = processStartNanos;
        this.vmStartMillis = ManagementFactory.getRuntimeMXBean().getStartTime();
    }

    public void markReady() {
        readyNanos = System.nanoTime();
    }

    public void markFirstRequest() {
        if (firstRequestNanos == 0) {
            firstRequestNanos = System.nanoTime();
        }
    }

    public String oneLine() {
        long vmToReady = (readyNanos - processStartNanos) / 1_000_000;
        long readyToFirst = firstRequestNanos == 0 ? -1
                : (firstRequestNanos - readyNanos) / 1_000_000;
        return "vmStart=" + vmStartMillis
                + " processToReady=" + vmToReady + "ms"
                + " readyToFirstRequest=" + readyToFirst + "ms";
    }
}

AppMain 在 main 第一行记录 System.nanoTime()，在 Javalin 启动完成后调用 markReady()，在第一个借阅请求的过滤器里调用 markFirstRequest()。这三个点合起来才能回答「用户感知的启动」是多少，而不是只看 main 的耗时。

启动 warmup 放在 readiness 之前：

package com.plume.library.app;

import com.plume.library.domain.FinePolicy;
import com.plume.library.domain.Loan;

import java.time.LocalDate;

public final class StartupWarmup {

    private static final LocalDate TODAY = LocalDate.of(2026, 10, 28);

    public void run() {
        Loan loan = new Loan(1L, "978-0-13-468599-0", "m-1",
                TODAY.minusDays(Loan.LOAN_DAYS), TODAY.plusDays(1), null, 0);
        for (int i = 0; i < 1_000; i++) {
            loan.state(TODAY);
            loan.fineCents(TODAY);
        }
        FinePolicy.DEFAULT.fineCents(7);
    }
}

Loan 与 FinePolicy 沿用 4.1 的定义，这里只展示 warmup 的调用面。这个 warmup 不做数据库查询，只把领域类加载、record 访问器、LoanState 分支和罚金计算跑热。它不能让 JDBC 连接池就绪，那部分由连接池的初始化负责。warmup 的循环次数不需要 1 万次，1000 次足够触发 C1 编译和类加载；再多会把启动时间拉长。

启动测量脚本固定成 10 次：

#!/usr/bin/env bash
set -euo pipefail
JAVA="$HOME/.jdks/jdk-25.0.5+8/Contents/Home/bin/java"
for i in $(seq 1 10); do
  /usr/bin/time -p "$JAVA" -jar libraryd-app/target/libraryd-app.jar --dry-run 2>&1 \
    | awk '/^real/ {print $2}'
done

--dry-run 让应用完成容器初始化、绑定端口、warmup，然后立即退出。没有这个开关，脚本会挂住。测出来的 real 包含进程启动、VM 初始化、应用初始化和 warmup，比只测 main 更接近用户感知。

常见错误与边界

错误一：用 main 前后两个时间戳代表启动。 main 开始时 VM 已经初始化完，main 结束时框架可能还在异步初始化。这样测出来的数字既不含 JVM 启动，也不含首请求，不能用于容量或 SLA。

错误二：把 readiness 当成业务就绪。 /health 只证明进程能响应 HTTP，不证明领域类、序列化器、连接池已经准备好。本机首请求 52 到 87 ms 的差距就是证据。readiness 要么探一个经过 warmup 的业务端点，要么在 readiness 变绿后延迟切流量。

错误三：只跑一次就下结论。 同一台机器上 Hello 的启动在 55 到 116 ms 之间波动，单次数字的误差比大多数优化收益都大。至少 10 次，看中位数和最大值；比较两个配置时交替运行，避免机器状态漂移。

错误四：在长跑服务上加 -XX:TieredStopAtLevel=1。 它能把启动中位数降 20% 左右，但会让 C2 优化缺席，稳态吞吐下降。只有「启动后很快退出」的 CLI、批处理、短命函数才适合。

边界一：-Xlog:init 在本机没有输出。 不要把它写进排查手册当作必看日志。用 -Xlog:startuptime 看 VM 阶段，用 -Xlog:class+load=info 看类加载，用 JFR 看时间线。

边界二：jcmd VM.uptime 不是启动时间。 它从 VM 初始化完成开始算，既不包含操作系统加载，也不包含应用初始化。把它和 RuntimeMXBean.getStartTime()、应用打点混在一起比较，会得到互相矛盾的数字。

小结

• 启动至少分五段：进程启动、VM 初始化、应用初始化、监听就绪、首请求就绪；每段的测量工具不同。
• 本机 Hello 启动中位数 86.8 ms（55.4 到 116.3 ms），最小 HTTP 服务就绪中位数 117.8 ms，单次数字不可用。
• -Xlog:init 在 Temurin 25.0.5+8 上没有输出；-Xlog:startuptime 显示 Create VM 约 31 ms，其中 java.lang 类初始化约 14 ms。
• Hello 启动加载 415 个类，412 个来自默认 CDS；最小服务加载 873 个，834 个来自默认 CDS，应用类只占极少数。
• 首请求比后续请求慢 50 到 80 ms，readiness 通过不等于业务就绪；warmup 和延迟切流量比调 JVM 参数更有效。
• TieredStopAtLevel=1 只适合短命进程；长跑服务不要为十几毫秒的启动收益牺牲 C2。

启动的下一站是「让类加载本身变快」。既然 95% 的类已经来自默认 CDS，下一步就是把应用自己的类也放进共享归档，看看 AppCDS 到底能省多少。

阅读导航：上一节：8.3 虚拟线程的运行时：Continuation、载体与调度 · 下一节：9.2 CDS 与 AppCDS：共享归档的构建与验证 。