阅读 380

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

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

紧急处理过程

11.05号晚上接近20点,有同事反应其它服务调用XXX服务出现少量超时,看了下Cat监控,发现些许机器当时处于fullgc,因为我们的XXX服务本身在高峰期就有较为频繁的fullgc,并且当天我还灰度了一台调过JVM参的XXX机器(本意是解决之前fullgc问题)。 所以当时误以为是像往常一样的fullgc引发的上游超时,同时从Cat gc指标来看,我灰度的一台XXX机器都优于其它机器,同时查看超时报警消息都不涉及灰度的机器,从而也排除了本次灰度的因素。大家持续观察后,报警越来越频繁,fullgc也越来越频繁,频次已远远高于之前的高峰期,就在想有哪些因素的变动把之前的fullgc问题给放大了,询问相关业务并没有数据量级变动。

73d910d029c24799b866bab80ea52393-image.png

随着fullgc越来越频繁,观察到今天的fullgc后old区内存回收较少,居高不下,立刻猜测是因为下午的XXX服务业务上线的代码很可能有内存泄露的问题,立马告知上线同学回滚代码,此时XXX集群服务已不可用同时大家商讨紧急预案,评估XXX服务哪些场景的请求可做最坏降级,毕竟XX服务只关注排序体验,幸好客户端调用超时时间是1s,上游业务没有被拖垮,没有影响到商城召回。登陆高内存机器通过jmap查看实例情况:

a4f56e4a6be84e2e8f309767ce420145-image.png
查看灰度的一台机器的gc日志,可以看到新生代每次gc,对象都会因为晋升担保到老年代,new threshold 已被动态调整为1,甚至:
42a9b5a8bc8f4dd5b1174d296c91002d-image.png

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到某个同步代码块上。

fe21a63031e341618a4137adcda1f04a-image.png
此时猜测死锁?或者同步块内有耗时任务?转而询问上线同学均排除了这两种可能。带着为什么会大量block的疑问,赶紧观察了Cat上cpu相关指标,load飙升和cpu buzy持续100%,意味着CPU某核心被打满。
ffb0e4b6598e46bab18f2bbb5ec914c7-image.png

那么问题来了,还有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.formatStringBuilder性能评测,并亲测String.format耗时相比StringBuilder高20倍左右。 所以得出初步结论: 直接原因是日志打印单线程逻辑耗时较长(大循环+String.format),在高峰期导致消息积压在线程池的任务队列里,而任务全都是计算型,并没有任何IO阻塞或睡眠操作,很难释放CPU资源,进而导致类似于在run()写了个死循环!由于消息堆积导致内存激增,fullgc频次激增,多个GC线程CPU消耗激增,业务线程hang住,客户端请求无响应超时,断开连接,服务端close_wait飙升至几k。

803160ef24f44413907666af2b028f07-image.png

验证结论:

在本地模拟了业务代码的线程模型,每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. 注意“雪崩效应”。 系统如果希望别的系统问题尽量减少对自身的影响,建议定期对自身系统的依赖做梳理,尽量自治。对依赖系统进行:消除依赖、弱化依赖和控制依赖。
  • 消除依赖: 梳理去除、隔离。 比如系统尽量减少第三方依赖;核心与非核心业务服务化拆分;服务内各场景线程池级别隔离

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

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

通过以上角度来治理我们的服务,实现高可用

文章分类
后端
文章标签