一行代码引起的集群服务宕掉的血案分析

本文禁止转载！ 原文地址： blog.csdn.net/lsgqjh/arti…

紧急处理过程

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提供更高的多线程切换效率。

总结

1. 线程池参数的修改应该很是很是谨慎！ 由于可能好多业务在用
2. 敬畏每一行代码的修改，由于每每就由于“多打了一行日志”的相似问题整个服务挂掉
3. 重视领域顶层设计，每每决定了后续服务的扩展性，灵活性，健壮性，可维护性。
4. 要作“正确的事”，而不是作各类事，正确的事 每每是具有长远价值的事
5. 禁止使用Executors提供的工具方法，手动建立ThreadPoolExecutor，设置好重要参数。 像案例中两处使用线程池均致使bug，如newCachedThreadPool万一线程hang住，线程数就会不可控。
6. 注意“雪崩效应”。 系统若是但愿别的系统问题尽可能减小对自身的影响，建议按期对自身系统的依赖作梳理，尽可能自治。对依赖系统进行：消除依赖、弱化依赖和控制依赖。

• 消除依赖： 梳理去除、隔离。 好比系统尽可能减小第三方依赖；核心与非核心业务服务化拆分；服务内各场景线程池级别隔离

• 弱化依赖： 旁路、缓存。

• 控制依赖： 熔断降级、服务限流、设置合理的超时重试。 本次就由于超时时间设置合理，才基本没有将风险向上传递

经过以上角度来治理咱们的服务，实现高可用