吉林网站建设哪家有,厦门中小企业网站制作,wordpress 加载陌生,湘潭找工作网站作者#xff1a;IKNOW本尊问题背景收到频繁的告警邮件#xff0c;定时任务调度失败#xff0c;查看xxl-job的执行器列表是空的#xff0c;但是服务又显示健康#xff0c;查看历史任务执行记录发现执行器是依次递减#xff0c;由于是线上服务#xff0c;只能先重启#…作者IKNOW本尊问题背景收到频繁的告警邮件定时任务调度失败查看xxl-job的执行器列表是空的但是服务又显示健康查看历史任务执行记录发现执行器是依次递减由于是线上服务只能先重启然后线程日志也没有同时尝试访问服务的健康检查接口发现健康检查接口访问不通应该是服务已经挂了但是因为服务配置的TCP健康检查没鲸云没有检测出来服务异常(血淋淋的教训)。总结问题现象xxl-job的执行器列表为空TCP检测正常服务显示正常但是http健康检查接口访问不了服务其实处于挂掉状态。初步排查过程:1.查看线上的APM发现两个异常: 堆内存会定期处于打满的状态 (被打满的都是 Eden Space----校长的定时任务计算任务很大打满也是正常的而且看了GC次数young GC 和 old GC也没有太大异常)-----挂掉的时刻和正常情况的堆内存几乎是相同的规律dump出现上的内存后查看也没有什么问题暂时排除是内存问题导致发现重启的服务线程池一直在缓慢的增长不是很理解正常的线程池不会一直处于增长的状态而且增长的数量也很大2.进入终端用arthas查看服务器线程状态 arthas 进入终端执行thread命令 确实发现很多的线程处于WATING状态dump出线程堆栈发现有200多个线程处于WATING状态。3.arthas 查看WATING状态的线程堆栈, 发现所有线程都处于下面的堆栈看不出什么太多的线索代码中查看是不是有什么地方设置了无限线程的线程池发现也没有这么挫的操作。4.张师傅注入线程的init方法, 发现是xxl-job的线程 [arthas1]$ stack java.lang.Thread 5.当时是怀疑xxl-job的线程泄露想着如果是这个原因应该线程增长到一定数量之后就会挂掉等了等发现线程增长一定数量(接近400)后就不在增长了尴尬...., 又看了下线上之前跑的比较正常的服务发现线上的线程数也是在接近400的数量级上一直很平稳服务也很健康应该也不会是这样原因没有思路暂时先将TCP的健康检查换成HTTP的保证服务挂掉的时候能够第一时间重启(后边分析了下xxl-job的线程增长会这么快是因为xxl-job内置的jetty服务器的默认线程池为256个线程)。再次排查过程1.东杰发现测试环境定时任务也挂了查看了下测试环境的内存和线程池发现基本和线上环境的是一样的没有什么太大的异常不过好在测试环境的是挂掉的现场应该线索更多一点。2.既然内存和线程没有发现什么太大的问题那就从挂的服务的CPU看下能不能找到线索进入终端top命令查看CPU果然有问题CPU已经跑满进入arthas终端thread -n 3 查看CPU占用率最高的3个线程一直处于下面的两个堆栈1. 第一个是业务代码2. 其他两个都是log4j2 打日志相关的3.查看业务代码 1. 线程卡住的地方是等待Callable任务结果如果没有结果返回就会一直空转。 2. 既然有任务没有结果那么肯定 executorService 线程池有线程被一直hold住。 3. 查看executorService 线程池的定义, 线程池的线程名都是 school-thread开头4.arthas查看线程池中的线程堆栈 [arthas1]$ thread 525发现是卡在 logger.error而且最后的堆栈和占用CPU最高的3个堆栈中的两个完全一样5.查看com.lmax.disruptor.MultiProducerSequencer.next 的源码看起来应该do while循环是在136行(LockSupport.parkNanos(1);)一直在空转。如果要确定确实是死循环的话。那么我们尝试通过arthas watch命令找出下面几个变量的值就知道是不是这样的ex.[arthas1]$ watch com.lmax.disruptor.Sequence get {returnObj} current获取事件发布者需要发布的序列值cachedGatingSequence获取事件处理者处理到的序列值[arthas24631]$ watch com.lmax.disruptor.util.Util getMinimumSequence {returnObj}gatingSequence当前事件处理者的最小的序列值(可能有多个事件处理者)bufferSize 128n: 1通过这几个值我们很容易就判断出来程序确实一直在空转其实就是当log4j2 异步打日志时需要往disruptor 的ringbuffer存储事件时ringbuffer满了但是消费者处理不过来导致获取下一个存储事件的位置一直拿不到而空转/** * see Sequencer#next() */ Override public long next() { return next(1); } /** * see Sequencer#next(int) */ Override public long next(int n) { if (n 1) { throw new IllegalArgumentException(n must be 0); } long current; long next; do { //获取事件发布者需要发布的序列值 current cursor.get(); next current n; //wrapPoint 代表申请的序列绕RingBuffer一圈以后的位置 long wrapPoint next - bufferSize; //获取事件处理者处理到的序列值 long cachedGatingSequence gatingSequenceCache.get(); /** * 1.事件发布者要申请的序列值大于事件处理者当前的序列值且事件发布者要申请的序列值减去环的长度要小于事件处理 * 者的序列值。 * 2.满足(1)可以申请给定的序列。 * 3.不满足(1)就需要查看一下当前事件处理者的最小的序列值(可能有多个事件处理者)。如果最小序列值大于等于 * 当前事件处理者的最小序列值大了一圈那就不能申请了序列(申请了就会被覆盖) * 针对以上值举例400米跑道(bufferSize)小明跑了599米(nextSequence)小红(最慢消费者)跑了200米 * (cachedGatingSequence)。小红不动小明再跑一米就撞翻小红的那个点叫做绕环点wrapPoint。 * */ if (wrapPoint cachedGatingSequence || cachedGatingSequence current) { long gatingSequence Util.getMinimumSequence(gatingSequences, current); if (wrapPoint gatingSequence) { LockSupport.parkNanos(1); // TODO, should we spin based on the wait strategy? continue; } gatingSequenceCache.set(gatingSequence); } else if (cursor.compareAndSet(current, next)) { break; } } while (true); return next; }6.看堆栈和我们确认源码之后发现应该是log4j2 通过disruptor异步打日志时产生了死循环导致服务CPU被打爆进而导致服务挂掉。7.本地验证( 复现问题 ) 验证思路我们也用一个线程池然后疯狂打印日志为了尽可能快的产生死循环的结果我们尽可能的将disruptor 的RingbufferSize设置的尽可能小线上的是通过环境变量设置的 -DAsyncLogger.RingBufferSize32768本机同样不过设置为RingBufferSize的最小值 128 验证代码fun testLog(){ var i 0 while(i 250000){ executorService.submit { LOGGER.debug(test $i) } i } LOGGER.debug(commit finish)}多触发调用几次这个函数(不是必现的可能需要多次才会出现)果然出现了和线上相同堆栈和结果8.那为什么会产生死循环呢既然确认不是业务代码问题感觉应该是log4j2和disruptor的bug找github的issue确实发现了有一些类似的情况但又不完全一样大半天的时间都在找issue(结果其实是个误区)........ 对这个方向太执着了,在这个误区瞎找了好久好久最后搞到头大。9.就去找幸斌讨论了下讨论真的有用从不同的思路方向发现了其他的问题(感谢幸斌提供的思路和疑点)重新arthas进入已挂掉的服务 1. 查看所有的线程状态, 发现了一个blocked状态的id为36 的线程2. 查看36的线程堆栈, 是被35的线程blocked住了3. 查看35线程的堆栈看起来和前面的堆栈是一样的都是卡在了 com.lmax.disruptor.MultiProducerSequencer.next4. 再仔细看下其实卡住的应该是 kafka.clients.Metadata.update 270行 和Objects.requireNonNull(topic, topic cannot be null);kafka.clients.Metadata.add 117 行log.debug(Updated cluster metadata version {} to {}, this.version, this.cluster);add和update都是加 synchronized锁的, 其实就是MetaData自己的update把自己add锁住10.那么为什么MetaData自己的update会把自己的add锁住呢还要看下我们的log4j2的日志配置 127.0.0.1:9092我们log4j2中配置了Async打印log同时引用了4个appender其中有一个是发送到kafka的整个的日志打印和发送简单的流程如下如所示为什么会锁住呢1. 当Ringbuffer刚好被打满的时候2. kafka的定时更新元数据update同步方法会log.debug 打印一条日志3. 当log4j2 尝试把这个日志写入到disruptor的时候会MultiProducerSequencer.next获取下一个可以插入存储的位置时发现没有位置可以存入就会进行LockSupport.parkNanos暂时阻塞1ns等待disruptor的消费者消费掉日志事件之后删除掉事件空出一个位置4. 问题就发生在这个了当kafka的KafkaProducer的waitOnMetadata方法尝试消费这个这个消息时会先进行MetaData的元数据add这个topic但是add的时候发现没有办法拿到锁因为已经被第2步的update 获取到了这个时候就发生了死锁然后disruptor的MultiProducerSequencer.next一直在空转。然后空转的线程一直持续耗住CPU进而导致服务挂掉11.问题到这里有些熟悉log4j2的同学可能会问到log4j2 的异步有2种方式Log4j2中的异步日志实现方式有AsyncAppender和AsyncLogger两种。其中 AsyncAppender采用了ArrayBlockingQueue来保存需要异步输出的日志事件 AsyncLogger则使用了Disruptor框架来实现高吞吐。我们下面的配置是异步AsyncAppender的方式但是为什么会用到Disruptor其实是因为我们全局配置了-DLog4jContextSelectororg.apache.logging.log4j.core.async.AsyncLoggerContextSelector这个会让应用使用Disruptor来实现异步。 更多AsyncAppender和AsyncLogger的区别可参考这两个博客https://bryantchang.github.io/2019/01/15/log4j2-asyncLogger/https://bryantchang.github.io/2018/11/18/log4j-async/12.其实还有一个问题没太想明白为什么xxl-job的线程数会一直增长然后处于wait状态其实这个和xxl-job内置的jetty服务有关, 我们本地启动xxl-job执行器随便执行一个定时任务然后debug断点到Thread.init()方法就可以看到是jetty服务器启动的线程而这个线程池corePoolSize 和corePoolSize是256个这个也就印证了为什么我们的定时任务服务启动之后会线程会一直增加然后到一定数量之后就不太变了其实就是因为这个线程池的原因。总结解决问题 总结问题: log4j2 异步打日志时队列满而且我们有使用kafka进行打印日志kafka刚好在队列满时触发了死锁导致distuptor死循环了 那么这个问题如何解决呢其实就是设置队列满的时候的处理策略 设置队列满了时的处理策略丢弃否则默认blocking异步就与同步无异了 1. AsyncLogger 设置 -Dlog4j2.AsyncQueueFullPolicyDiscard 2. AsyncAppender 如果设置丢弃策略时还需要设置丢弃日志的等级根据项目情况按需配置-Dlog4j2.DiscardThresholdINFO 复制代码总结 这个问题的解决确实花了比较多的时间从一开始的各种怀疑点到最后的一步步接近真相其实还是比较艰难的在 很多误区搞了很久花了很多的时间但是最后到解决的那个时刻还是很开心的不过中间自己对log4j2的不了解 的以及容易忽略细节的问题还是暴露了出来其实慢慢的一条线下来也有了一套解决方法的流程和思路这个是感觉 最欣慰的最后还是要感谢张师傅和幸斌的帮助和他们讨论其实很多时候会把自己从误区拉回来也会学到很多的 解决问题的思路和方法。来源掘金 链接https://juejin.im/post/5edcf10451882543345e9899
