日常Bug排查-集群逐步失去响应
前言
日常Bug排查系列都是一些简单Bug排查。笔者将在这里介绍一些排查Bug的简单技巧,同时顺便积累素材
Bug现场
最近碰到一个产线问题,表现为某个应用集群所有的节点全部下线了。导致上游调用全部报错。而且从时间线分析来看。这个应用的节点是逐步失去响应的。因为请求量较小,直到最后一台也失去响应后,才发现这个集群有问题。
线程逐步耗尽
笔者观察了下监控,发现每台机器的BusyThread从上次发布开始就逐步增长,一直到BusyThread线程数达到200才停止,而这个时间和每台机器从注册中心中摘除的时间相同。看了下代码,其配置的最大处理请求线程数就是200。
查看线程栈
很容易的,我们就想到去观察相关机器的线程栈。发现其所有的的请求处理线程全部Block在com.google.common.util.concurrent.SettableFuture的不同实例上。卡住的堆栈如下所示:
at sun.misc.Unsafe.park (Native Method: ) at java.util.concurrent.locks.LockSupport.park (LockSupport.java: 175) at com.google.common.util.concurrent.AbstractFuture.get (AbstractFuture.java: 469) at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get (AbstractFuture.java: 76) at com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly (Uninterruptibles.java: 142) at com.google.common.cache.LocalCache$LoadingValueReference.waitForValue (LocalCache.java: 3661) at com.google.common.cache.LocalCache$Segment.waitForLoadingValue (LocalCache.java: 2315) at com.google.common.cache.LocalCache$Segment.get (LocalCache.java: 2202) at com.google.common.cache.LocalCache.get (LocalCache.java: 4053) at com.google.common.cache.LocalCache.getOrLoad (LocalCache.java: 4057) at com.google.common.cache.LocalCache$LocalLoadingCache.get (LocalCache.java: 4986) at com.google.common.cache.ForwardingLoadingCache.get (ForwardingLoadingCache.java: 45) at com.google.common.cache.ForwardingLoadingCache.get (ForwardingLoadingCache.java: 45) at com.google.common.cache.ForwardingLoadingCache.get ...... at com.XXX.business.getCache ......
从GuavaCache获取缓存为什么会被卡住
GuavaCache是一个非常成熟的组件了,为什么会卡住呢?使用的姿势不对?于是,笔者翻了翻使用GuavaCache的源代码。其简化如下:
private void initCache() { ExecutorService executor = new ThreadPoolExecutor(1, 1, 60, TimeUnit.SECONDS, new ArrayBlockingQueue<>(50), // 注意这个QueueSize new NamedThreadFactory(String.format("cache-reload-%s")), (r, e) -> { log.warn("cache reload rejected by threadpool!"); // 注意这个reject策略 }); this.executorService = MoreExecutors.listeningDecorator(executor); cache = CacheBuilder.newBuilder().maximumSize(100) // 注意这个最大值 .refreshAfterWrite(1, TimeUnit.DAYS).build(new CacheLoader<K, V>() { @Override public V load(K key) throws Exception { return innerLoad(key); } @Override public ListenableFuture<V> reload(K key, V oldValue) throws Exception { ListenableFuture<V> task = executorService.submit(() -> { try { return innerLoad(key); } catch (Exception e) { LogUtils.printErrorLog(e, String.format("重新加载缓存失败,key:%s", key)); return oldValue; } }); return task; } }); }
这段代码事实上写的还是不错的,其通过重载reload方法并在加载后段缓存出问题的时候使用old Value。保证了即使获取缓存的后段存储出问题了,依旧不会影响到我们缓存的获取。逻辑如下所示:
那么为什么会卡住呢?一时间看不出什么问题。那么我们就可以从系统的日志中去寻找蛛丝马迹。
日志
对应时间点日志空空如也
对于这种逐渐失去响应的,我们寻找日志的时候一般去寻找源头。也就是第一次出现卡在SettableFuture的时候发生了什么。由于我们做了定时的线程栈采集,那么很容易的,笔者挑了一台机器找到了3天之前第一次发生线程卡住的时候,grep下对应的线程名,只发现了一个请求过来到了这个线程然后卡住了,后面就什么日志都不输出了。
异步缓存的日志
继续回顾上面的代码,代码中缓存的刷新是异步执行的,很有可能是异步执行的时候出错了。再grep异步执行的相关关键词“重新加载缓存失败”,依旧什么都没有。线索又断了。
继续往前追溯
当所有线索都断了的情况下,我们可以翻看时间点前后的整体日志,看下有没有异常的点以获取灵感。往前多翻了一天的日志,然后一条线程池请求被拒绝的日志进入了笔者的视野。
cache reload rejected by threadpool!
看到这条日志的一瞬间,笔者立马就想明白了。GuavaCache的reload请求不是出错了,而是被线程池给丢了。在reload请求完成之后,GuavaCache会对相应的SettableFuture做done的动作以唤醒等待的线程。而由于我们的Reject策略只打印了日志,并没有做done的动作,导致我们请求Cache的线程一直在卡waitForValue上面。如下图所示,左边的是正常情况,右边的是异常情况。
为什么会触发线程池拒绝策略
注意我们初始化线程池的源代码
ExecutorService executor = new ThreadPoolExecutor(1, 1, 60, TimeUnit.SECONDS, new ArrayBlockingQueue<>(50), // 注意这个QueueSize new NamedThreadFactory(String.format("cache-reload-%s")), (r, e) -> { log.warn("cache reload rejected by threadpool!"); // 注意这个reject策略 });
这个线程池是个单线程线程池,而且Queue只有50,一旦遇到同时过来的请求大于50个,就很容易触发拒绝策略。
源码分析
好了,这时候我们就可以上一下GuavaCache的源代码了。
V get(K key, int hash, CacheLoader<? super K, V> loader) throws ExecutionException { checkNotNull(key); checkNotNull(loader); try { if (count != 0) { // read-volatile // don't call getLiveEntry, which would ignore loading values ReferenceEntry<K, V> e = getEntry(key, hash); if (e != null) { long now = map.ticker.read(); V value = getLiveValue(e, now); if (value != null) { recordRead(e, now); statsCounter.recordHits(1); // scheduleRefresh中一旦Value不为null,就直接返回旧值 return scheduleRefresh(e, key, hash, value, now, loader); } ValueReference<K, V> valueReference = e.getValueReference(); // 如果当前Value还在loading,则等loading完毕 if (valueReference.isLoading()) { // 这次的Bug就一直卡在loadingValue上 return waitForLoadingValue(e, key, valueReference); } } } // at this point e is either null or expired; return lockedGetOrLoad(key, hash, loader); } catch (ExecutionException ee) { ...... }
为什么没有直接返回oldValue而是卡住
等等,在上面的GuavaCache源代码里面。一旦缓存有值之后,肯定是立马返回了。对应这段代码。
if (value != null) { recordRead(e, now); statsCounter.recordHits(1); // scheduleRefresh中一旦Value不为null,就直接返回旧值 return scheduleRefresh(e, key, hash, value, now, loader); }
所以就算异步刷新请求被线程池Reject掉了。它也不会讲原来缓存中的值给删掉。业务线程也不应该卡住。那么这个卡住是什么原因呢?为什么缓存中没值没有触发load而是等待valueReference有没有加载完毕呢。
稍加思索之后,笔者就找到了原因,因为上述那段代码中设置了缓存的maxSize。一旦超过maxSize,一部分数据就被驱逐掉了,而如果这部分数据恰好就是线程池Reject掉请求的数据,那么就会进值为空同时需要等待valueReference loading的代码分支,从而造成卡住的现象。让我们看一下源代码:
localCache.put // |->evictEntries |->removeEntry |->removeValueFromChain ReferenceEntry<K,V> removeValueFromChain(...) { ...... if(valueReference.isLoading()){ // 设置原值为null valueReference.notifyNewValue(null); return first; }else { removeEntryFromChain(first,entry) } }
我们看到,代码中valueReference.isLoading()的判断,一旦当前value还处于加载状态中,那么驱逐的时候只会将对应的entry(key)项设置为null而不会删掉。这样,在下次这个key的缓存被访问的时候自然就走到了value为null的分支,然后就看到当前的valueReference还处于loading状态,最后就会等待那个由于被线程reject而永远不会done的future,最后就会导致这个线程卡住。逻辑如下图所示:
什么是逐渐失去响应
因为业务的实际缓存key的项目是大于maxSize的。而一开始系统启动后加载的时候缓存的cache并没有达到最大值,所以这时候被线程池reject掉相应的刷新请求依旧能够返回旧值。但一旦出现了大于缓存cache最大Size的数据导致一些项被驱逐后,只要是一个请求去访问这些缓存项都会被卡住。但很明显的,能够被驱逐出去的旧缓存肯定是不常用的缓存(默认LRU缓存策略),那么就看这个不常用的数据的流量到底是在哪台机器上最多,那么哪台机器就是最先失去响应的了。
总结
虽然这是个较简单的问题,排查的时候也是需要一定的思路的,尤其是发生问题的时间点并往前追溯到第一个不同寻常的日志这个点,这个往往是我们破局的手段。GuavaCache虽然是个使用非常广泛的缓存工具,但不合理的配置依旧会导致灾难性的后果。
低调大师中文资讯倾力打造互联网数据资讯、行业资源、电子商务、移动互联网、网络营销平台。
持续更新报道IT业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。
转载内容版权归作者及来源网站所有,本站原创内容转载请注明来源。
- 上一篇
OpenAI 自带的检索功能好用吗?定量测评带你深度了解!
向量数据库的劲敌来了?又有一批赛道创业公司要倒下? …… 这是 OpenAI 上线 Assistant 检索功能后,技术圈传出的部分声音。原因在于,此功能可以为用户提供基于知识库问答的 RAG(检索增强生成) 能力。而此前,大家更倾向于将向量数据库作为 RAG 方案的重要组件,以达到减少大模型出现“幻觉”的效果。 那么,问题来了,OpenAI 自带的 Assistant 检索功能 V.S. 基于向量数据库构建的开源 RAG 方案相比,谁更胜一筹? 本着严谨的求证精神,我们对这个问题进行了定量测评,结果很有意思: OpenAI 表现不错!不过,在基于向量数据库的开源 RAG 方案面前仍有差距! 接下来,我将还原整个测评过程。需要强调的是,要完成这些测评并不容易,少量的测试样本根本无法有效衡量 RAG 应用的各方面效果。因此,需要采用一个公平、客观的 RAG 效果测评工具,在一个合适的数据集上进行测评,进行定量的评估和分析,并保证结果的可复现性。 话不多说,上过程! 01.评测工具 Ragas 是一个致力于测评 RAG 应用效果的开源框架。用户只需要提供 RAG 过程中的部分信息,如 qu...
- 下一篇
开源的代名词「GitHub 热点速览」
当开发者谈论开源时,通常会想到 GitHub,它不仅仅是一个代码托管平台,更是一个汇聚了全球开发者的社交中心。过去,开发者发布一款软件后,都是在自己的小圈子里默默努力和交流,现在通过 GitHub 平台可以方便地与全球的开发者分享、交流和协作。贡献者在这里展示自己的才华,追随者在这里寻找强者的脚印,等待着被世人认可的时刻。 更多人在谈到开源时,会提到“免费”,正是上面的这些人用爱发电,才让开源成为免费的宝库,如果理解不了他们的热爱,请不要伤害。 下面,让我们一起看看,过去一周开源领域都发生了什么,关注开源最新动态、品热搜开源项目。 本文目录 1. 开源新闻 1.1 LSPosed 宣布停更 1.2 锤子开源软件 One Step 疑被抄袭 1.3 PyPy 迁移到 GitHub 2. GitHub 热搜项目 2.1 安卓内核级的 root 方案 2.2 神奇的 shell 历史记录工具 2.3 手绘风格的白板 2.4 人人都能用英语 2.5 AI 机器人 3. HelloGitHub 热评 3.1 (no)SQL 数据库桌面管理工具 3.2 一款电脑上的广告拦截器 4. 往期回顾 1....
相关文章
文章评论
共有0条评论来说两句吧...
文章二维码
点击排行
推荐阅读
最新文章
- Docker安装Oracle12C,快速搭建Oracle学习环境
- 2048小游戏-低调大师作品
- SpringBoot2全家桶,快速入门学习开发网站教程
- SpringBoot2初体验,简单认识spring boot2并且搭建基础工程
- SpringBoot2编写第一个Controller,响应你的http请求并返回结果
- CentOS7编译安装Cmake3.16.3,解决mysql等软件编译问题
- Springboot2将连接池hikari替换为druid,体验最强大的数据库连接池
- SpringBoot2整合Redis,开启缓存,提高访问速度
- SpringBoot2配置默认Tomcat设置,开启更多高级功能
- CentOS7编译安装Gcc9.2.0,解决mysql等软件编译问题