一行代码引发的集群服务宕掉的血案分析
本文禁止转载！
紧急处理过程
11.05号晚上接近20点，有同事反应其它服务调用XXX服务出现少量超时，看了下Cat监控，发现些许机器当时处于fullgc，因为我们的XXX服务本身在高峰期就有较为频繁的fullgc，并且当天我还灰度了一台调过JVM参的XXX机器（本意是解决之前fullgc问题）。 所以当时误以为是像往常一样的fullgc引发的上游超时，同时从Cat gc指标来看，我灰度的一台XXX机器都优于其它机器，同时查看超时报警消息都不涉及灰度的机器，从而也排除了本次灰度的因素。大家持续观察后，报警越来越频繁，fullgc也越来越频繁，频次已远远高于之前的高峰期，就在想有哪些因素的变动把之前的fullgc问题给放大了，询问相关业务并没有数据量级变动。
随着fullgc越来越频繁，观察到今天的fullgc后old区内存回收较少，居高不下，立刻猜测是因为下午的XXX服务业务上线的代码很可能有内存泄露的问题，立马告知上线同学回滚代码，此时XXX集群服务已不可用同时大家商讨紧急预案，评估XXX服务哪些场景的请求可做最坏降级，毕竟XX服务只关注排序体验，幸好客户端调用超时时间是1s，上游业务没有被拖垮，没有影响到商城召回。登陆高内存机器通过jmap查看实例情况：
查看灰度的一台机器的gc日志，可以看到新生代每次gc，对象都会因为晋升担保到老年代，new threshold 已被动态调整为1，甚至：
427819 class space used 9908K, capacity 10491K, committed 10624K, reserved 1048576K
427820 2019-11-05T20:12:56.043+0800: 17269.148: [GC (Allocation Failure) 17269.148: [ParNew
427821 Desired survivor size 100191432 bytes, new threshold 1 (max 15)
427822 - age 1: 142964632 bytes, 142964632 total
427823 : 1258304K->139776K(1258304K), 0.2134974 secs] 3853016K->2923653K(4054528K), 0.2140106 secs] [Times: user=1.32 sys=0.05, real=0.21 secs]
427824 Heap after GC invocations=12249 (full 57):
之后观察到回滚后机器指标趋于正常了，所以确定了case和此次上线有关，开始diff代码查找内存泄露的地方
事后排查
首先跟上线同学进行了代码走读，重点关注有没有引入HashMap相关逻辑导致内存泄漏，然而并没有定位出原因。在Cat上查看当时的线程堆栈，发现JVM线程数打到1.5k+，并且观察到大量业务线程block到某个同步代码块上。
此时猜测死锁？或者同步块内有耗时任务？转而询问上线同学均排除了这两种可能。带着为什么会大量block的疑问，赶紧观察了Cat上cpu相关指标，load飙升和cpu buzy持续100%，意味着CPU某核心被打满。
那么问题来了，还有7个core来跑业务线程啊，也不至于block业务线程的。当时模模糊糊怀疑是业务失控创建了大量线程，内存资源大量消耗，并大量阻塞在syncrhonized 的wait_list，同时从Cat能看到整个服务端请求处理耗时飙升到几十秒了，大量线程持有的内存因gc年龄大量晋升到老年代，进而导致了频繁fullgc，（这里的猜测后来证明并不正确，事实上有点“鸡生蛋，蛋生鸡”的味道）。接着上线的同学果真排查到有行代码存在bug： 在进行特征加载的时候，会导致每个请求可能创建上千的子任务投递到线程池，newCachedThreadPool！线程创建无上限。。。排查到这里，似乎觉得找到了内存打满fullgc的原因。但到这里其实还解释不了为什么CPU buzy 100%的现象。
我们在凌晨对上线的代码进行了压测，复现线上问题。在压测时，可以通过jstack命看到Java进程下一个很突兀的高消耗CPU的线程，CPU%指标逼近100%。打印该线程栈看它在做一些什么事情。
Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
340 at java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
341 at java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
342 at java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
343 at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:512)
344 at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:502)
345 at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
346 at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
347 at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
348 at com.xxx.service.feature.logger.PrintUnit.countState(PrintUnit.java:69)
349 at com.xxx.service.feature.logger.PrintJob.lambda$printFeatureCountNow$59(PrintJob.java:151)
可以看到占用CPU%的线程在执行我们业务里特征日志打印的逻辑，迅速让同事定位到某行代码，看为什么会那么消耗CPU，review一遍这块代码（本次新上线的一条日志打印），看起来逻辑只是循环拼接了一些要打印的日志，看起来并没有复杂的业务逻辑，同时review到 日志打印线程是单线程，所以不存在用到的HashMap跑飞。那只能是循环次数很大很大？同事说确实比较大，较大的能达到上万次，那关键问题是上万次规模的循环也不至于CPU100%啊！我们加了关键逻辑的代码耗时，看看到底每个业务请求在特征打印阶段会导致多少次遍历，耗时多少，重新压测后，惊人的发现日志打印耗时很多能达到上百ms！正常情况下server端业务线程耗时才几十ms。去掉本次上线的日志打印逻辑，重新压测，指标正常。至此基本锁定到是这块代码问题，但看起来并没有哪行代码那么耗时，但隐隐约约听过String.format底层有坑？问题定位后，下半夜就回家了。
11.06号上午，在网上看了String.format和StringBuilder性能评测，并亲测String.format耗时相比StringBuilder高20倍左右。
所以得出初步结论： 直接原因是日志打印单线程逻辑耗时较长（大循环+String.format），在高峰期导致消息积压在线程池的任务队列里，而任务全都是计算型，并没有任何IO阻塞或睡眠操作，很难释放CPU资源，进而导致类似于在run()写了个死循环！由于消息堆积导致内存激增，fullgc频次激增，多个GC线程CPU消耗激增，业务线程hang住，客户端请求无响应超时，断开连接，服务端close_wait飙升至几k。
验证结论：
在本地模拟了业务代码的线程模型，每1s提交到队列50个任务，单线程处理队列任务。run()方法里模拟了日志打印的循环规模和耗时的String.format代码。运行后，发现打印的队列大小是持续增加的。如果放开循环里的字符串拼接注释，消息队列就没有了堆积。其实本质原因还是线程池参数设置不合理，导致生产者消费者失衡。
public static void main(String[] args) throws InterruptedException {
BlockingQueue<Runnable> blockingQueue = new LinkedBlockingQueue<>(99200);
ThreadPoolExecutor threadPool = new ThreadPoolExecutor(1, 1,
0L, TimeUnit.MILLISECONDS, blockingQueue
))
new Thread(new Runnable() {
@Override
public void run() {
while (true) {
System.out.println("queueSize:" + blockingQueue.size());
for (int i = 0; i < 100; i++) {
threadPool.execute(new Runnable() {
@Override
public void run() {
long start2 = System.currentTimeMillis();
for (int j = 0; j < 10000; j++) {
//String s = "asdsdsdsaa" + new Random().nextLong() + "bbbbbfbfdsfb" + new Random().nextLong() + "kkksdskkkkk";
String.format("[%s] $ [%s] : [%s]", new Random().nextLong(), new Random().nextLong(), new Random().nextLong());
}
try {
Thread.sleep(50);
} catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println(Thread.currentThread().getName());
//System.out.println("time:" + (System.currentTimeMillis() - start2));
}
});
}
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}).start();
问题解决
稍微改改就解决了
相关知识
String.format()原理
String.format使用正则来拆分我们的String，再使用StringBuild来append串起来。
ExecutorService线程池原理
自行读源码即可
Reactor响应式编程中的背压
响应式编程是一种数据流编程，关注于数据流而不是控制流。
背压是指在数据流从上游生产者向下游消费者传输的过程中，上游生产速度大于下游消费速度，导致下游的 Buffer 溢出，这种现象就叫做 Backpressure 出现。当上游向下游推送数据时，可能下游承受能力不足导致问题，一个经典的比喻是就像用消防水龙头解渴。因此下游需要向上游声明每次只能接受大约多少量的数据，当接受完毕再次向上游申请数据传输。这便转换成是下游向上游申请数据，而不是上游向下游推送数据。无阻塞是通过no-blocking IO提供更高的多线程切换效率。
总结
- 线程池参数的修改应该非常非常谨慎！ 因为可能好多业务在用
- 敬畏每一行代码的修改，因为往往就因为“多打了一行日志”的类似问题整个服务挂掉
- 重视领域顶层设计，往往决定了后续服务的扩展性，灵活性，健壮性，可维护性。
- 要做“正确的事”，而不是做各种事，正确的事 往往是具备长远价值的事
- 禁止使用Executors提供的工具方法，手动创建ThreadPoolExecutor，设置好重要参数。 像案例中两处使用线程池均导致bug，如newCachedThreadPool万一线程hang住，线程数就会不可控。
- 注意“雪崩效应”。 系统如果希望别的系统问题尽量减少对自身的影响，建议定期对自身系统的依赖做梳理，尽量自治。对依赖系统进行：消除依赖、弱化依赖和控制依赖。
-
消除依赖： 梳理去除、隔离。
比如系统尽量减少第三方依赖；核心与非核心业务服务化拆分；服务内各场景线程池级别隔离 -
弱化依赖： 旁路、缓存。
-
控制依赖： 熔断降级、服务限流、设置合理的超时重试。
本次就因为超时时间设置合理，才基本没有将风险向上传递
通过以上角度来治理我们的服务，实现高可用
