4. 使用 Interceptor 监控串行请求耗时：自定义、记录时间、生成时间线

串行请求的每一个环节都可能成为首屏渲染的瓶颈，而 OkHttp 的 Interceptor 拦截器机制，正是定位这些瓶颈最直接的工具。本章将指导你自定义一个 TimingInterceptor，精准记录每一个请求的开始、结束时间，并生成一条清晰的时间线，用以分析首屏加载过程中的网络耗时分布。

4.1 Interceptor 机制回顾

OkHttp 的拦截器分为 Application Interceptor 和 Network Interceptor 两种。对于串行请求监控，我们通常会选择 Application Interceptor，因为它会在请求发出前和响应返回后各调用一次，且能捕获到缓存命中情况，更适合分析业务层的首屏耗时。

4.2 自定义 TimingInterceptor 实现

以下是一个可直接运行的 TimingInterceptor 实现，它会在日志中输出每个请求的名称、开始时间、结束时间和总耗时。我们可以通过同一线程的 ThreadLocal 来安全地保存起始时间戳。

public class TimingInterceptor implements Interceptor {

    private static final String TAG = "Timing";
    // 每个请求线程持有自己的开始时间
    private final ThreadLocal<Long> startTimeLocal = new ThreadLocal<>();

    @NonNull
    @Override
    public Response intercept(@NonNull Chain chain) throws IOException {
        Request request = chain.request();
        long startNanos = System.nanoTime();
        int requestHash = request.hashCode();

        // 记录开始时间（纳秒）
        startTimeLocal.set(startNanos);

        // 打印请求开始时间线
        Log.d(TAG, String.format(
            "[%d] START %s @ %d ms (nano: %d)",
            requestHash,
            request.url(),
            System.currentTimeMillis(),
            startNanos
        ));

        Response response;
        try {
            response = chain.proceed(request);
        } catch (IOException e) {
            long endNanos = System.nanoTime();
            long costMs = (endNanos - startTimeLocal.get()) / 1_000_000L;
            Log.e(TAG, String.format(
                "[%d] FAILED %s | cost %d ms",
                requestHash,
                request.url(),
                costMs
            ));
            startTimeLocal.remove();
            throw e;
        }

        long endNanos = System.nanoTime();
        long costMs = (endNanos - startTimeLocal.get()) / 1_000_000L;

        // 打印请求结束时间线
        Log.d(TAG, String.format(
            "[%d] END   %s @ %d ms | cost %d ms",
            requestHash,
            request.url(),
            System.currentTimeMillis(),
            costMs
        ));

        startTimeLocal.remove();
        return response;
    }
}

4.3 生成时间线：从日志到可视化

拦截器输出的日志并不能直接呈现为时间线，需要按照 请求hash 进行配对筛选。下面是一段典型的时间线日志输出示例：

# 日志片段（使用 TimingInterceptor 输出）
D/Timing: [12543] START https://api.example.com/login @ 1712345678901 ms
D/Timing: [12543] END   https://api.example.com/login @ 1712345679210 ms | cost 309 ms
D/Timing: [12544] START https://api.example.com/user/me @ 1712345679215 ms
D/Timing: [12544] END   https://api.example.com/user/me @ 1712345679430 ms | cost 215 ms
D/Timing: [12545] START https://api.example.com/banners @ 1712345679435 ms
D/Timing: [12545] END   https://api.example.com/banners @ 1712345679600 ms | cost 165 ms

分析这段日志，可以直接提取首屏串行请求的耗时结构：

• login：309 ms
• user/me：215 ms
• banners：165 ms
• 串行总耗时：309 + 215 + 165 = 689 ms
• 串行总时间（含间隙）：从第一个 START 到最后一个 END = 699 ms

4.4 串行请求时间线结构

下面的 SVG 图展示了三个串行请求在时间轴上的排列方式，以及拦截器记录的 START/END 节点。

4.5 调试方法：如何在 Logcat 中快速定位

当项目中同时存在多个拦截器时，建议为监控拦截器单独设置 Tag，并在 Logcat 过滤器中输入 Timing 即可。对于串行请求的时间线分析，你还可以：

1. 使用 Excel 或在线工具：将日志复制出来，按 START/END 用公式计算耗时。
2. 编写一个简单的 Python 脚本：正则提取 START 和 END 的 timestamp，自动生成甘特图。
3. 在拦截器中直接写入内存队列：将 startNanos 与 endNanos 存入 ArrayList，通过 UI 模块展示。

4.6 性能优化策略：从时间线反推优化点

拿到时间线后，可以针对不同耗时特征采取不同的策略：

4.7 常见错误与避坑

• ❌ 误用 System.currentTimeMillis() 计算耗时：系统时间可能被用户手动修改，导致耗时计算错误。建议始终使用 System.nanoTime() 做差值，仅在输出时间点时使用毫秒值。
• ❌ 未处理异常情况：请求可能抛出 IOException，如果在 intercept 中未捕获，会导致 startTimeLocal 残留，造成内存泄漏。上述实现已通过 try-catch-finally 处理。
• ❌ 忘记移除 ThreadLocal：即使正常结束，也要调用 remove() 清理，避免后续复用线程时读取到上一轮的开始时间。
• ❌ 在 Network Interceptor 中记录串行耗时：网络拦截器会在重定向、重试时被多次调用，导致单个请求出现多条 start 记录，破坏时间线的纯度。

4.8 实际案例复盘：定位网络模块卡顿

问题现象：用户反馈首屏加载时间从平均 800 ms 飙升到 1800 ms。 排查过程：

1. 添加 TimingInterceptor，记录所有请求耗时。
2. Logcat 分析发现：getHomePage 耗时正常（200 ms），但 getRecommendList 耗时异常（1200 ms）。
3. 进一步抓包发现，getRecommendList 的 TCP 三次握手耗时 600 ms，SSL 握手耗时 400 ms，而实际数据传输仅 200 ms。
4. 原因：该接口使用了独立域名，未启用 DoH（DNS over HTTPS），且客户端的连接池配置为 keep-alive 60s 而非 300s。

优化方案：

• 提升连接池 keep-alive 存活时间为 300s。
• 合并接口域名到主域，减少 DNS 解析次数。
• 如果必须使用独立域名，开启 OkHttp 的 EventListener 监控 DNS 耗时并进行预取。

通过上述调整，首屏加载时间恢复到 900 ms 以内，拦截器的时间线数据成为本次优化的关键证据。

结语