竹笋

首页 » 问答 » 灌水 » 虽然是我遇到的一个棘手生产问题,但是我写
TUhjnbcbe - 2023/3/7 18:42:00
曾任全国白癜风专家 http://m.39.net/pf/a_5941786.html

早上好呀,前几天,就在大家还沉浸在等待春节到来的喜悦氛围的时候,在一个核心链路上的核心系统中,我踩到一个坑的一比的坑,要不是我沉着冷静,解决思路忙中有序,处理手段雷厉风行,把它给扼杀在萌芽阶段了,那这玩意肯定得引发一个比较严重的生产问题。

从问题出现到定位到这个问题的根本原因,我大概是花了两天半的时间。

所以写篇文章给大家复盘一下啊,这个案例就是一个纯技术的问题导致的,和业务的相关度其实并不大,所以你拿过去直接添油加醋,稍微改改,往自己的服务上套一下,那就是你的了。

我再说一次:虽然现在不是你的,但是你看完之后就是你的了,你明白我意思吧?

表象

事情是这样的,我这边有一个服务,你可以把这个服务粗暴的理解为是一个商城一样的服务。有商城肯定就有下单嘛。

然后接到上游服务反馈,说调用下单接口偶尔有调用超时的情况出现,断断续续的出现好几次了,给了几笔流水号,让我看一下啥情况。当时我的第一反应是不可能是我这边服务的问题,因为这个服务上次上线都至少是一个多月前的事情了,所以不可能是由于近期服务投产导致的。

但是下单接口,你听名字就知道了,核心链接上的核心功能,不能有一点麻痹大意。

每一个请求都很重要,客户下单体验不好,可能就不买了,造成交易损失。

交易上不去营业额就上不去,营业额上不去利润就上不去,利润上不去年终就上不去。

想到这一层关系之后,我立马就登陆到服务器上,开始定位问题。

一看日志,确实是我这边接口请求处理慢了,导致的调用方超时。

为什么会慢呢?

于是按照常规思路先根据日志判断了一下下单接口中调用其他服务的接口相应是否正常,从数据库获取数据的时间是否正常。

这些判断没问题之后,我转而把目光放到了gc上,通过监控发现那个时间点触发了一次耗时接近1s的fullgc,导致响应慢了。

由于我们监控只采集服务近一周的gc数据,所以我把时间拉长后发现fullgc在这一周的时间内出现的频率还有点高,虽然我还没定位到问题的根本原因,但是我定位到了问题的表面原因,就是触发了fullgc。

因为是核心链路,核心流程,所以此时不应该急着去定位根本原因,而是先缓解问题。

好在我们提前准备了各种原因的应急预案,其中就包含这个场景。预案的内容就是扩大应用堆内存,延缓fullgc的出现。

所以我当即进行操作报备并联系运维,按照紧急预案执行,把服务的堆内存由8G扩大一倍,提升到16G。

虽然这个方法简单粗暴,但是既解决了当前的调用超时的问题,也给了我足够的排查问题的时间。

定位原因

当时我其实一点都不慌的,因为问题在萌芽阶段的时候我就把它给干掉了。

不就是fullgc吗,哦,我的老朋友。

先大胆假设一波:程序里面某个逻辑不小心搞出了大对象,触发了fullgc。

所以我先是双手插兜,带着监控图和日志请求,闲庭信步的走进项目代码里面,想要凭借肉眼找出一点蛛丝马迹......

没有任何收获,因为下单服务涉及到的逻辑真的是太多了,服务里面List和Map随处可见,我很难找到到底哪里是大对象。

但是我还是一点都不慌,因为这半天都没有再次发生FullGC,说明此时留给我的时间还是比较充足的,

所以我请求了场外援助,让DBA帮我导出一下服务的慢查询SQL,因为我想可能是从数据库里面一次性取的数据太多了,而程序里面也没有做控制导致的。

我之前就踩过类似的坑。

一个根据客户号查询客户有多少订单的内部使用接口,接口的返回是List订单,看起来没啥毛病,对不对?

一般来说一个个人客户就几十上百,多一点的上千,顶天了的上万个订单,一次性拿出来也不是不可以。

但是有一个客户不知道咋回事,特别钟爱我们的平台,也是我们平台的老客户了,一个人居然有接近10w的订单。

然后这么多订单对象搞到到项目里面,本来响应就有点慢,上游再发起几次重试,直接触发Fullgc,降低了服务响应时间。

所以,经过这个事件,我们定了一个规矩:用List、Map来作为返回对象的时候,必须要考虑一下极端情况下会返回多少数据回去。即使是内部使用,也最好是进行分页查询。

好了,话说回来,我拿到慢查询SQL之后,根据几个Fullgc时间点,对比之后提取出了几条看起来有点问题的SQL。

然后拿到数据库执行了一下,发现返回的数据量其实也都不大。

此刻我还是一点都不慌,反正内存够用,而且针对这类问题,我还有一个场外援助没有使用呢。

第二天我开始找运维同事帮我每隔8小时Dump一次内存文件,然后第三天我开始拿着内存文件慢慢分析。

但是第二天我也没闲着,根据现有的线索反复分析、推理可能的原因。

然后在观看GC回收内存大小监控的时候,发现了一点点端倪。因为触发FullGC之后,发现被回收的堆内存也不是特别多。

当时就想到了除了大对象之外,还有一个现象有可能会导致这个现象:内存泄露。

巧的是在第二天又发生了一次Fullgc,这样我拿到的Dump文件就更有分析的价值了。基于前面的猜想,我分析的时候直接就冲着内存泄漏的方向去查了。

我拿着5个Dump文件,分析了在5个Dump文件中对象数量一直在增加的对象,这样的对象也不少,但是最终定位到了FutureTask对象,就是它:

找到这玩意了再回去定位对应部分的代码就比较容易。

但是你以为定位了代码就完事了吗?

不是的,到这里才刚刚开始,朋友。

因为我发现这个代码对应的Bug隐藏的还是比较深的,而且也不是我最开始假象的内存泄露,就是一个纯粹的内存溢出。

所以值得拿出来仔细嗦一嗦。

示例代码

为了让你沉浸式体验找BUG的过程,我高低得给你整一个可复现的Demo出来,你拿过去就可以跑的那种。

首先,我们得搞一个线程池:

需要说明一下的是,上面这个线程池的核心线程数、最大线程数和队列长度我都取的1,只是为了方便演示问题,在实际项目中是一个比较合理的值。

然后重点看一下线程池里面有一个自定义的叫做MyThreadFactory的线程工厂类和一个自定义的叫做MyRejectedPolicy的拒绝策略。

在我的服务里面就是有这样一个叫做product的线程池,用的也是这个自定义拒绝策略。

其中MyThreadFactory的代码是这样的:

它和默认的线程工厂之间唯一的区别就是我加了一个threadFactoryName字段,方便给线程池里面的线程取一个合适的名字。

更直观的表示一下区别就是下面这个玩意:

原生:pool-1-thread-1自定义:product-pool-1-thread-1

接下来看自定义的拒绝策略:

这里的逻辑很简单,就是当product线程池满了,触发了拒绝策略的时候打印一行日志,方便后续定位。

然后接着看其他部分的代码:

标号为①的地方是线程池里面运行的任务,我这里只是一个示意,所以逻辑非常简单,就是把i扩大10倍。实际项目中运行的任务业务逻辑,会复杂一点,但是也是有一个Future返回。

标号为②的地方就是把返回的Future放到list集合中,在标号为③的地方循环处理这个list对象里面的Future。

需要注意的是因为实例中的线程池最多容纳两个任务,但是这里却有五个任务。我这样写的目的就是为了方便触发拒绝策略。

然后在实际的项目里面刚刚提到的这一坨逻辑是通过定时任务触发的,所以我这里用一个死循环加手动开启线程来示意:

整个完整的代码就是这样的,你直接粘过去就可以跑,这个案例就可以完全复现我在生产上遇到的问题:

publicclassMainTest{publicstaticvoidmain(String[]args)throwsException{ThreadPoolExecutorproductThreadPoolExecutor=newThreadPoolExecutor(1,1,1,TimeUnit.SECONDS,newLinkedBlockingQueue(1),newMyThreadFactory("product"),newMyRejectedPolicy());while(true){TimeUnit.SECONDS.sleep(1);newThread(()-{ArrayListFutureIntegerfutureList=newArrayList();//从数据库获取产品信息intproductNum=5;for(inti=0;iproductNum;i++){try{intfinalI=i;FutureIntegerfuture=productThreadPoolExecutor.submit(()-{System.out.println("Thread.currentThread().getName()="+Thread.currentThread().getName());returnfinalI*10;});futureList.add(future);}catch(Exceptione){e.printStackTrace();}}for(FutureIntegerintegerFuture:futureList){try{Integerinteger=integerFuture.get();System.out.println(integer);System.out.println("future.get()="+integer);}catch(Exceptione){e.printStackTrace();}}}).start();}}staticclassMyThreadFactoryimplementsThreadFactory{privatestaticfinalAtomicIntegerpoolNumber=newAtomicInteger(1);privatefinalThreadGroupgroup;privatefinalAtomicIntegerthreadNumber=newAtomicInteger(1);privatefinalStringnamePrefix;privatefinalStringthreadFactoryName;publicStringgetThreadFactoryName(){returnthreadFactoryName;}MyThreadFactory(StringthreadStartName){SecurityManagers=System.getSecurityManager();group=(s!=null)?s.getThreadGroup():Thread.currentThread().getThreadGroup();namePrefix=threadStartName+"-pool-"+poolNumber.getAndIncrement()+"-thread-";threadFactoryName=threadStartName;}publicThreadnewThread(Runnabler){Threadt=newThread(group,r,namePrefix+threadNumber.getAndIncrement(),0);if(t.isDaemon())t.setDaemon(false);if(t.getPriority()!=Thread.NORM_PRIORITY)t.setPriority(Thread.NORM_PRIORITY);returnt;}}publicstaticclassMyRejectedPolicyimplementsRejectedExecutionHandler{

OverridepublicvoidrejectedExecution(Runnabler,ThreadPoolExecutore){if(e.getThreadFactory()instanceofMyThreadFactory){MyThreadFactorymyThreadFactory=(MyThreadFactory)e.getThreadFactory();if("product".equals(myThreadFactory.getThreadFactoryName())){System.out.println(THREAD_FACTORY_NAME_PRODUCT+"线程池有任务被拒绝了,请
1
查看完整版本: 虽然是我遇到的一个棘手生产问题,但是我写