|
背景 公司某个规则引擎系统，主要用来做一些费用计算和业务逻辑核验的功用。不外由于一些 不可描画的历史缘由，招致该系统 没有文档也没有源码，就连配置方式都是靠口口相传。
固然这个系统比较老，但究竟是商业产品，功用上还是比较完善好用的。该系统在接入业务系统的算费和核验规则后，很快就上线了。 不外上线后，会偶发的呈现接口耗时过长的问题。正常状况下，该效劳响应耗时也就 20ms 以下。但呈现问题时，效劳的耗时会增加到几十秒，每次呈现长耗时的时间点也不固定。而且在长耗时期间，一切抵达该效劳的央求都会呈现长耗时，并不只是个别央求才会受影响。 理论上这种问题测试之类的环境应该也有；但由于测试环境重启很频繁，偶发的长耗时可能以为是在重启，就不时没人留意。 固然啥都没有，但问题还是得处置啊，时不时的几十秒长耗时……这谁顶得住。抱着试试看的心态，还是先研讨一下。 排查经过 这种偶发长耗时的问题，排查起来是比较省事的。无法稳定复现，也没有规律，就算弄个其他环境模仿也不是很好办；再加上这个系统没文档没源码，更没人懂它的结构和流程，查起来就更费力了。 看监控 在查看了监控历史之后，发现每次呈现长耗时的时分，CPU & 磁盘 IO 的应用率会升高，但也没高的很离谱。CPU 高的时分不外也才 五六十，而磁盘就更低了，只是稍微有一点动摇而已，这点动摇会带来几十秒的耗时，可有点说不外去。 看日志 CPU 那块只是稍微有点高，但也不能阐明什么问题，还是得找到基本缘由。于是我又翻了下那个系统的日志，看看能不能找到什么线索。
卡时间，看日志，折腾了半小时，终于在日志上看到一个关键线索： 2020-04-08 10:12:35.897 INFO [com.马赛克.rules.res.execution] (default-threads - 65) 规则集 /ansNcreckonRuleApp/1.0/ansncreckonrule/61.0 已在 58 秒后解析终了。 58 秒……这行日志的时间点，和我们实践发作耗时的时间点是能够匹配上的，在这个58 秒范围内，的确有大量的央求耗时，而且都是小于 58 秒或略大于 58 秒的。
除了这个耗时的打印之外，GC 日志也有点可疑。 每次呈现这个耗时日志之前，都会有一次 GC 活动日志，不外暂停时间并不长： 2021-06-07T17:36:44.755+0800: [GC2021-06-07T17:36:44.756+0800: [DefNew: 879616K->17034K(3531079K), 0.0472190 secs] 3549012K->2686430K(10467840K), 0.0473160 secs] [Times: user=0.05 sys=0.00, real=0.2 secs] 更奇特的是……不是每次 GC 之后，都会有耗时日志 GC 问题 认真查看 gc 日志后发现，每次慢响应之前不久，都会有一次 GC，不外不是 FULL GC，而且每次暂停时间也不长，远不迭央求的耗时时间。而且 GC 过程中的 CPU 应用率并不高，从数据上看还是比较正常的。 好往常有（一丁点）线索了：
从以上几个线索来看，GC 活动之后呈现 CPU 应用率增加，然后打印了一行加载日志，时间还能够和该系统的长耗时央求对应上。 而且每次耗时日志之前不久的中央，都会有一次 GC 活动，那么阐明这个资源加载的机遇和 GC 有关系，GC 会影响资源加载…… 想到这里，也大约猜到缘由了。很可能是用弱援用(Weak Reference)来维护了这个资源缓存，当 GC 后弱援用的资源被回收，所以需求重新加载（弱援用的细致解释以及测试结果能够参考《Java 中的强援用/软援用/弱援用/虚援用以及 GC 战略》）。 那既然可能是这个缘由，假如我找到这个弱援用维护资源缓存的中央，给他改成强援用就能处置问题了！固然没有源码，但还是能够反编译啊，反编译之后改一下缓存那块的代码，问题不大。
定位资源加载点 终于找到了可能的缘由，可是有一个问题……我怎样知道这行耗时日志在哪打印的？在哪个类里？我连这个效劳是用的什么 Web 容器都不知道。 没措施，上 Arthas 吧，不外肯定不能在消费环境直接测。于是我又新整了一套暂时测试环境，用于排查这个问题。 幸而日志里有个 loggerName 前缀 com.马赛克.rules.res.execution ，经过 Arthas 的 trace 功用，能够用通配符的方式来 trace 这个包名下的一切类： # trace 该包名下的一切类，一切措施，只显现耗时大于 1000ms 的措施 # 由于这个输出结果可能会比较多，所以 > 输出到文件，并且后台运转 trace com.马赛克.rules.res.* * '#cost > 1000' > /app/slow_trace.log & trace 命令执行了十几秒才返回，一共影响了 169 个类和 1617 个措施，可见通配符匹配多风险……要是消费这样玩我可能会被拉进来祭天。
分离前面描画的状况，GC 后会有这个耗时问题，那往常来手动触发一次 GC， 应用 Arthas 的 vmtool 能够直接 forceGC（应用 jmap 或者其他的伎俩也能够）： vmtool --action forceGc forceGC 后，重新测试该系统接口 和上面的状况一样，果真又呈现了长耗时，央求返回后打印了相同的耗时日志，只是和消费环境的相比时间更长了（由于我用了 arthas trace 增强） 2020-04-08 12:30:35.897 INFO [com.马赛克.rules.res.execution] (default-threads - 65) 规则集 /ansNcreckonRuleApp/1.0/ansncreckonrule/61.0 已在 70 秒后解析终了。 同时 Arthas trace 日志写入的那个文件中，也有了内容（链路真实太长，没法贴代码，只能截图了）：
这个 trace 日志一千多行，此处删减了部分内容。 Arthas 的 trace 命令不会中止全链路跟踪，所以这里的 一次 trace 结果只是当出路径。但曾经不错了，问题范围又再一次减少。 从上图能够看到 IlrRulesetProvider:getRuleset 这个措施是主要耗时点，那就先来看看这个措施里是个什么玩法。 为了简单，这里暂时用 Arthas 的 jad 命令，直接反编译这个类，看看里面的逻辑： jad ilog.rules.res.xu.ruleset.internal.IlrRulesetProvider 代码有点多，这里删减一些，只保存关键部分： public final XURulesetImpl getRuleset(IlrXURulesetArchiveInformation archive, IlrXUContext xuCtx, boolean waitParsing, Listener listener) throws IlrRulesetArchiveInformationNotFoundException, IlrRulesetCreationException, IlrRulesetAlreadyParsingException, IlrRulesetCacheException, XUException { String canonicalPath = archive.getCanonicalPath.toString; this.logger.finest("IlrRulesetProvider.getRuleset " + canonicalPath + " " + waitParsing); if (!archive.getProperties.isShareable) { return this.factory.createRuleset(archive, xuCtx); } else { ClassLoader cl = archive.getXOMClassLoader; XURulesetImpl ruleset; while(true) { synchronized(this.parsingRulesets) { // 字面意义是，从缓存中获取规则集，有的话直接 return 了 ruleset = (XURulesetImpl)this.getCache.getRuleset(canonicalPath, cl); if (ruleset != null) { return ruleset; } // 第一个加载的线程，将当前资源添加到 parsingRulesets 同时跳出 while if (!this.parsingRulesets.contains(archive)) { this.parsingRulesets.add(archive); break; } if (!waitParsing) { throw new IlrRulesetAlreadyParsingException("XU.ERROR.10406", (String[])null); } // 这里的 wait……应该是避免并发访问，当其他线程也进入该代码块时 wait 等候第一个线程加载完成唤醒 try { this.parsingRulesets.wait; } catch (InterruptedException var20) { throw new IlrRulesetCreationException("XU.ERROR.10009", (String[])null, var20); } } } if (!this.useWorkManager(archive)) { this.logger.finest("IlrRulesetProvider.getRuleset doesn't use the workmanager " + this.workManager, (Object[])null, xuCtx); XURulesetImpl var9; try { // 创建资源 ruleset = this.factory.createRuleset(archive, xuCtx); // 创建完成，添加到缓存 this.getCache.addRuleset(ruleset); var9 = ruleset; } finally { this.parsingStopped(archive); } return var9; } } } 固然删减了很多，但看代码还是有点不明晰，究竟反编译的代码阅读干扰有点大，这里简单解释下上面的代码逻辑：
再分离我们上面的猜测：
那问题就在这个缓存容器上了！只需看看这个 cache 就能知道，肯定有弱援用的代码！
反编译找代码 jad 反编译在终端里看代码还是太折腾了，不如在 IDE 里直观，所以还是得把代码拉下来剖析，不然找个关联类都费力。 这个系统下有很多 Jar 包，得先找到这些相关的类在哪个 Jar 里，应用 Arthas 的 sc 命令，也十分简单： sc -d ilog.rules.res.xu.ruleset.internal.IlrRulesetProvider class-info ilog.rules.res.xu.ruleset.internal.IlrRulesetProvider # 这里是我们关怀的信息，该 class 所在的 jar code-source /content/jrules-res-xu-JBOSS61EAP.rar/ra.jar name ilog.rules.res.xu.ruleset.internal.IlrRulesetProvider isInterface false isEnum false isAnonymousClass false isArray false isLocalClass false isMemberClass false isPrimitive false isSynthetic false simple-name IlrRulesetProvider modifier final,public annotation interfaces com.ibm.rules.res.xu.ruleset.internal.RulesetParsingWork$Listener super-class +-java.lang.Object class-loader +-ModuleClassLoader for Module "deployment.jrules-res-xu-JBOSS61EAP.rar:main" from Service Module Loader +-sun.misc.Launcher$AppClassLoader@2d74e4b3 +-sun.misc.Launcher$ExtClassLoader@5552bb15 classLoaderHash 2d022d73 Affect(row-cnt:1) cost in 79 ms. 找到这个 ra.jar 后，把这个 jar 拖到 IDE 里反编译，不外这个 class 还有些关联的 class 不在这个 ra.jar 中。还是同样的措施，找到关联的 class，然后 sc -d 找到所在的 jar 位置，复制到本地 ide 反编译 重复折腾了几次后，终于把有关联的 4 个 jar 包都弄回本地了，往常能够在 IDE 里开开心心的看代码了。 剖析缓存容器的机制 首先是上面那个 createCache 措施，经过剖析后得知，cache 的完成类为 IlrRulesetCacheImpl ，这个类需求关怀的只需两个措施，getRuleset 和 addRuleset： public void addRuleset(IlrXURuleset executableRuleset) { synchronized(this.syncObject) { //... this.entries.add(new IlrRulesetCacheEntry(executableRuleset, this.maxIdleTimeOutSupport)); //... } } public IlrXURuleset getRuleset(String canonicalRulesetPath, ClassLoader xomClassLoader) { // ... List<IlrRulesetCacheEntry> cache = this.entries; synchronized(this.syncObject) { Iterator iterator = cache.iterator; while(iterator.hasNext) { IlrRulesetCacheEntry entry = (IlrRulesetCacheEntry)iterator.next; IlrXURuleset ruleset = (IlrXURuleset)entry.rulesetReference.get; if (ruleset == null) { iterator.remove; } else if (entry.canonicalRulesetPath.equals(canonicalRulesetPath) && (entry.xomClassLoader == xomClassLoader || entry.xomClassLoader != null && entry.xomClassLoader.getParent == xomClassLoader)) { return ruleset; } } } // ... return null; } 看完这两个措施之后，很明显了， entries 才是关键的数据存储汇合，看看它是怎样个玩法： protected transient List<IlrRulesetCacheEntry> entries = new ArrayList; 居然只是个 ArrayList，继续看看 IlrRulesetCacheEntry 这个类： public class IlrRulesetCacheEntry { protected String canonicalRulesetPath = null; protected ClassLoader xomClassLoader = null; protected IlrReference<IlrXURuleset> rulesetReference = null; public IlrRulesetCacheEntry(IlrXURuleset executableRuleset, boolean maxIdleTimeOutSupport) { this.canonicalRulesetPath = executableRuleset.getCanonicalRulesetPath; this.xomClassLoader = executableRuleset.getXOMClassLoader; long maxIdleTime = executableRuleset.getRulesetArchiveProperties.getMaxIdleTime; // 留意这里是关键，依据 maxIdleTime 的值选择强援用和弱援用 if (maxIdleTime != 0L && (!maxIdleTimeOutSupport || maxIdleTime == -1L)) { this.rulesetReference = new IlrWeakReference(executableRuleset); } else { this.rulesetReference = new IlrStrongReference(executableRuleset); } } } 代码曾经很直白了，依据 maxIdleTime 的不同运用不同的援用战略，不等于 0 就弱援用，等于 0 就强援用；不外还是得看下这俩 Reference 类的代码： // 弱援用，继承 WeakReference public class IlrWeakReference<T> extends WeakReference<T> implements IlrReference<T> { public IlrWeakReference(T t) { super(t); } } // 强援用 public class IlrStrongReference<T> implements IlrReference<T> { private T target; IlrStrongReference(T target) { this.target = target; } public T get { return this.target; } } 这俩类并没有什么特别的中央，和类名的意义相同；IlrWeakReference 继承于 WeakReference，那就是弱援用，当发作 GC 时，援用的对象会被删除。 固然找到了这个弱援用的中央，但还是需求考证一下，是不是真的运用了这个弱援用 考证能否运用了弱援用 这里运用 Arthas 的 vmtool 命令，来看看缓存中的实时对象： vmtool --action getInstances --className ilog.rules.res.xu.ruleset.cache.internal.IlrRulesetCacheImpl --express 'instances[0].entries.get(0)' @IlrRulesetCacheEntry[ canonicalRulesetPath=@String[/ansNcreckonRuleApp/1.0/ansncreckonrule/1.0], xomClassLoader=@XOMClassLoader[com.ibm.rules.res.persistence.internal.XOMClassLoader@18794875], # 这里能够看到，rulesetRef 的实例是 IlrWeakReference rulesetReference=@IlrWeakReference[ilog.rules.res.xu.ruleset.cache.internal.IlrWeakReference@dbd2972], ] 从结果上看，石锤了就是弱援用。
但惹起弱援用的究竟是 maxIdleTime，还是需求找到 maxIdleTime 的源头…… 寻觅 maxIdleTime 在 IlrRulesetCacheEntry 的结构措施里能够看到，maxIdleTime 是从 IlrRulesetArchiveProperties 里获取的： long maxIdleTime = executableRuleset.getRulesetArchiveProperties.getMaxIdleTime; 那就继续看看 IlrRulesetArchiveProperties 这个类： public long getMaxIdleTime { // 从 properties 里获取 key 为 ruleset.maxIdleTime 的 value String result = this.get("ruleset.maxIdleTime"); return result == null ? -1L : Long.valueOf(result); } public String get(Object key) { String result = (String)this.properties.get(key); return result == null && this.defaults != null ? (String)this.defaults.get(key) : result; } getMaxIdleTime 返回的默许值是 -1，也就是说假如没配置这个 maxIdleTime 值，默许也会运用弱援用战略。 到目前为止，问题算是曾经精确的定位到了，弱援用的缓存战略招致被 GC 时资源缓存被清空，重新加载资源招致了长耗时。 可是这系统没源码没文档，我上哪改这个 maxIdleTime 去…… 不外来都来了，都曾经看到 IlrRulesetArchiveProperties 这个类了，不如先看看这个类里到底配置了哪些值，有没有 maxIdleTime vmtool --action getInstances --className com.ibm.rules.res.xu.ruleset.internal.CRERulesetImpl --express 'instances[0].getRulesetArchiveProperties' @IlrRulesetArchivePropertiesImpl[ @String[ruleset.engine]:@String[cre], @String[ruleset.status]:@String[enabled], @String[ruleset.bom.enabled]:@String[true], @String[ruleset.managedxom.uris]:@String[resuri://ans-nc-xom.zip/54.0,resuri://ruleapp-core-model-1.5.2.jar/2.0], ] 从结果上能够看到，properties 里并没有 maxIdleTime 属性，和我们上面的结论是能够匹配的。没有配置 maxIdleTime 属性，默许 -1，所以运用弱援用 寻觅 maxIdleTime 的配置措施 反编译的代码固然看不到注释，但从类名还是能够猜一下的，IlrRulesetArchiveProperties 这个类名应该是“规则集归档属性”的意义。 固然我不懂这个系统的业务规则，但有人懂啊！于是我找来了担任这个系统配置的老哥，找他给我解释了下这个系统的各种概念。
老哥也很友好，直接给我画了一张图
这个规则引擎系统，有一个 App 的概念，就是 saas 平台里常说的那个应用的意义；每个 App 下面能够创建多个规则集，就是图上这个 RuleSet，每个 RuleSet 就是我们的业务规则，好比费用计算公式或者逻辑核验规则，同时每个 RuleSet 还会记载多个每次变更的历史版本。 看到这张图，我也明白了个七七八八，上面定位的 IlrRulesetArchiveProperties 不就是规则集的属性？这个产品有个控制台，应该有这个属性配置的中央吧，不然弄这么个类干啥？规则集都是控制台创建的，那规则集属性应该也能够配置！
如我所料，控制台的规则集上果真有个属性的概念，而且还能够添加属性。 最重要的是，控制台上 ruleset.bom.enabled 这个属性，我上面用 arthas vmtool 看的时分也有，那就能够证明这里的配置，应该就是配置 IlrRulesetArchiveProperties 这个类的；只需是给这个规则集加上 maxIdleTime 是不是就能够运用强援用了？ 然后我当心翼翼的点击了那个添加属性的按钮……
果真有 maxIdleTime 这个选项，选择 maxIdleTime 之后，给它配置为 0。 考证结果 配置完了，还是重启考证一下是不是生效，谁知道这个系统支不支持热刷新呢，改动之后还是重启考证比较稳妥。 先考证该规则集的 properties： vmtool --action getInstances --className com.ibm.rules.res.xu.ruleset.internal.CRERulesetImpl --express 'instances[0].getRulesetArchiveProperties' @IlrRulesetArchivePropertiesImpl[ # 新增配置 @String[ruleset.maxIdleTime]:@String[0], @String[ruleset.engine]:@String[cre], @String[ruleset.status]:@String[enabled], @String[ruleset.bom.enabled]:@String[true], @String[ruleset.managedxom.uris]:@String[resuri://ans-nc-xom.zip/54.0,resuri://ruleapp-core-model-1.5.2.jar/2.0], ] 从上面能够看到，我们新增的配置，曾经生效了，规则集上曾经有了这个 maxIdleTime。 再来看看缓存里的援用，是不是曾经变成了强援用： vmtool --action getInstances --className ilog.rules.res.xu.ruleset.cache.internal.IlrRulesetCacheImpl --express 'instances[0].entries.get(0).rulesetReference' # 这里是强援用 @IlrStrongReference[ target=@CRERulesetImpl[com.ibm.rules.res.xu.ruleset.internal.CRERulesetImpl@28160472], ] 在增加了 maxIdleTime 之后，规则集的缓存就变成了强援用，强援用下就不会再呈现由于 GC 被回收的状况了！ 用 vmtool 来一遍 fullgc，试试看还会不会重新加载： vmtool --action forceGc 执行了十几遍，也没出呈现长耗时问题，问题应该是处置了。 接着把这个配置同步到测试环境，跑了三天，我时不时还上去手动 forceGc 一下，没有再呈现过这个长耗时的问题了。 为什么不是每次 GC 后都会呈现耗时 本文开头就提到，每次长耗时之前不久都会有一次 GC 活动，但并不是每次 GC 后都会有一次长耗时。 弱援用维护的对象，并不是说在 GC 时就会被清空；只是在 GC 时， 假如弱援用的对象曾经没有其他援用了，才会被回收，好比下面这个例子里： Map<String,Object> dataMap = new HashMap<>; WeakReference ref = new WeakReference(dataMap); System.gc; System.out.println(ref.get); dataMap = null; System.gc; System.out.println(ref.get); //output {} null 第一次 gc 时，ref 里的数据不会被清空，而第二次 gc 前弱援用的数据，曾经没有其他任何援用了，此时会被清空。 分离这个系统的问题来看，固然规则集那里运用弱援用缓存，但假如在 GC 时，调用方还持有规则集对象没有释放，那么这个弱援用的规则集缓存也一样不会清空；所以才会呈现这个 不是每次 GC 都会招致重新加载， 但每次重新加载却都是由于 GC 的问题 但我以为没有必要继续跟下去了，持有规则集对象的中央在哪，和这个耗时问题关系并不是很大；修正为强援用之后，就不会再有 GC 回收该对象的状况，那还在意谁持有干嘛呢（其实是我懒，没文档还没源码，找问题找的我头都要秃了）
写在后面 原本以为需求先反编译，然后修正代码重新打包才干搞定的问题，最后居然一行代码都没改就处置了，有点小惊喜…… 不外这个规则引擎的设计思绪还是挺好的，为了俭省内存，运用可配置的缓存战略，只是默许运用弱援用来维护规则集太激进了。于大多数效劳端场景来说，不差它这点释放的内存，给多少用多少就行，释放了反而会引发更大的问题，重新加载招致的耗时才是最不能接受的。 |
