[真实案例]一行代码是如何让系统崩溃的

程序员老周
253 阅读5分钟

背景

新系统上线，一到高峰期系统卡顿明显，几乎完全不可用。通过 APM 监控看出，主要是依赖的 jar 包造成的系统缓慢。该 jar 包被用作拦截器，所有的请求都会过该拦截器。拦截器主要包括操作 Redis 处理用户信息和调用 gRPC 接口获取数据。根据 APM 监控看出，这两个核心操作耗时很短，不是故障的原因。

解决过程

从页面情况看，每个请求响应时间接近 12s。

一、紧急对系统扩容，从 2c4g 提升到 4c8g，并且将 pod 数从 4 提升到了 8。多次刷新后，响应时间降低为 6s，但不稳定，系统仍然不可用。

二、将所有的关联系统重启，仍然没用。

三、改造基础镜像，安装 arthas，通过不断深入 trace 拦截器入口方法，发现日志打印时间占比长，去掉该行日志，同时对系统压测，满足要求。经过下个高峰期，系统平稳运行。

排查与复现过程

复现方式

我将原有代码脱敏后放到了 GitHub 上，地址：github.com/zhouwentong…

通过 ab -n 10000 -c 10 <http://localhost:8080/test/hello> 命令压测，模拟用户请求。

第一次压测

当第一次执行压测时，结果如下

# ab -n 1000 -c 10 <http://localhost:8080/test/hello>

Concurrency Level:      10
Time taken for tests:   20.902 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      137000 bytes
HTML transferred:       5000 bytes
Requests per second:    47.84 [#/sec] (mean)
Time per request:       209.017 [ms] (mean)
Time per request:       20.902 [ms] (mean, across all concurrent requests)
Transfer rate:          6.40 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     3  209 616.8     23    2417
Waiting:        3  209 616.8     23    2417
Total:          3  209 616.8     23    2417

Percentage of the requests served within a certain time (ms)
  50%     23
  66%     32
  75%     40
  80%     46
  90%     76
  95%   2325
  98%   2372
  99%   2388
 100%   2417 (longest request)

根据压测报告可以看出，QPS 仅为 47.84，平均处理时间为 209ms，最大处理时间为 2417ms，方差较大。

性能报告

通过 top 可以看出：此时的平均负载比较低，CPU 占用率为 17.3%（两核的机器），iowait 为 0，说明不存在 IO 的压力。

image.png 既然不是磁盘 IO 导致的 QPS 低，那是因为什么呢？

第一次优化

这里我们通过火焰图来查找代码热点，在 arthas 中执行 profiler start，等到压测结束后，再执行 profiler stop 生成火焰图文件，在浏览器中打开。 火焰图

log.info 操作占据了 72.10% 的 CPU 时间，再往上看，CPU 主要消耗在了java.lang.Throwable.getStackTraceElement 操作上。跟踪 logback 源码可知CallerData.extract 方法主要是为日志提供上下文信息，包括类名、方法名、行号等信息，因为项目中都是通过 MDC 的 traceId 来串联日志，不怎么依赖上下文信息，因此这里将日志配置中的 $$%file{}/%line{}$$%method{}$$%class{} 信息去掉。再次进行压测。

# ab -n 1000 -c 10 <http://localhost:8080/test/hello>

Concurrency Level:      10
Time taken for tests:   15.546 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      137000 bytes
HTML transferred:       5000 bytes
Requests per second:    64.33 [#/sec] (mean)
Time per request:       155.457 [ms] (mean)
Time per request:       15.546 [ms] (mean, across all concurrent requests)
Transfer rate:          8.61 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     0  155 575.7      4    2530
Waiting:        0  155 575.7      4    2530
Total:          0  155 575.7      4    2530

Percentage of the requests served within a certain time (ms)
  50%      4
  66%      7
  75%     10
  80%     13
  90%     30
  95%   2458
  98%   2489
  99%   2498
 100%   2530 (longest request)

可以看到，QPS 由先前的 47.84 上涨为 64.33，QPS 提升了 34%，平均响应时间也降低到 155ms。

第二次优化

虽然 QPS 提升了 34%，但因为这段逻辑非常简单，即使用错了 map，时间复杂度变成了 O(N)，但是因为集合只有几十个，差距不应该这么大。

此时我们再去看压测报告，发现响应时间的方差很大，也就意味着很多请求是被阻塞了，等轮到它执行的时候，已经排队很长时间了。

JFR 分析

这里我们通过 JCMD 来录制 JFR 文件，用来进一步分析请求被阻塞的原因。

jcmd $JPS_ID JFR.start name=MyRecording settings=profile duration=60s filename=myrecording.jfr

将录制的 JFR 文件通过 JProfiler 打开，发现 Tomcat 的执行线程大部分处于等待状态（黄色），真正处于执行状态（绿色）的只占很少一部分。

image.png

这时我们要探究为什么执行线程处于等待状态。

image.png

我们通过 Monitor 历史 页观察，按照持续时间倒序排列，发现 Tomcat 的执行线程的等待时间几乎都在 10s，跟踪代码发现，都是阻塞 org.apache.tomcat.util.threads.ThreadPoolExecutor#getTask 方法上，具体是从 TaskQueue 中获取待执行的任务上。

任务肯定有的是（压测）那为什么没有获取到呢？

image.png

根据上面的截图，这些执行线程都在等待地址为 0xe2a77f40 的锁

image.png

这把锁足足阻塞了 200s。代码如下：

private void writeBytes(byte[] byteArray) throws IOException {
    if (byteArray == null || byteArray.length == 0)
        return;

    streamWriteLock.lock();

    try {
        // guard against appender having been stop() in parallel
        // note that the encoding step is performed outside the protection of the streamWriteLock
        if(isStarted()) {
            writeByteArrayToOutputStreamWithPossibleFlush(byteArray);
            updateByteCount(byteArray);
        }
    } finally {
        streamWriteLock.unlock();
    }
}

这是OutputStreamAppender 的代码，负责输出的准确性，避免乱序。**每次先加锁，然后将数据写入 pageBuffer，然后强制 flush，最后执行解锁操作。**这是个非常重的操作，多个线程串行执行，效率自然就低了很多，这也就可以解释，为什么线程实际执行的时间那么短了。

根据上面的分析，再去看 logback 文件，发现引用了ConsoleAppender 频繁输出控制台，导致性能下降严重。将ConsoleAppender 去掉后再次压测，结果为：

# ab -n 1000 -c 10 <http://localhost:8080/test/hello>

Concurrency Level:      10
Time taken for tests:   0.336 seconds
Complete requests:      1000
Failed requests:        0
Total transferred:      137000 bytes
HTML transferred:       5000 bytes
Requests per second:    2977.13 [#/sec] (mean)
Time per request:       3.359 [ms] (mean)
Time per request:       0.336 [ms] (mean, across all concurrent requests)
Transfer rate:          398.31 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.6      0       4
Processing:     1    3   1.6      2      18
Waiting:        1    3   1.5      2      11
Total:          1    3   1.7      2      18

Percentage of the requests served within a certain time (ms)
  50%      2
  66%      3
  75%      4
  80%      4
  90%      5
  95%      7
  98%      9
  99%      9
 100%     18 (longest request)

此时，QPS 由 70 变为 3000，符合预期。

总结

  • 对于生产环境，永远都是先止损，后分析。止损方案包括重启、回滚、加机器、加配置等。
  • 故障的根因往往都是小疏忽，做根因分析往往需要清醒的头脑和趁手的分析工具。我们要熟悉常用的工具，避免用的时候抓瞎。
  • 解决问题一般都是提出假设，做验证，如此循环多次，才有可能最终解决问题。
avatar
文章
阅读
粉丝