关于java:没源码也没文档但我还是解决了线上偶发的长耗时问题

29次阅读

共计 12166 个字符,预计需要花费 31 分钟才能阅读完成。

先点赞再看,养成好习惯

背景

公司某个规定引擎零碎,次要用来做一些费用计算和业务逻辑核验的性能。不过因为一些 不可形容的历史起因 ,导致该零碎 没有文档也没有源码,就连配置形式都是靠口口相传。


尽管这个零碎比拟老,但毕竟是商业产品,性能上还是比较完善好用的。该零碎在接入业务零碎的算费和核验规定后,很快就上线了。

不过上线后,会偶发的呈现服务耗时过长的问题。失常状况下,该服务响应耗时也就 20ms 以下。但呈现问题时,服务的耗时会 减少到几十秒,每次呈现长耗时的工夫点也不固定。而且在长耗时期间,所有达到该服务的申请都会呈现长耗时,并不只是个别申请才会受影响。

实践上这种问题测试之类的环境应该也有;但因为测试环境重启很频繁,偶发的长耗时可能认为是在重启,就始终没人注意。

尽管啥材料都没有,但问题还是得解决啊,时不时的几十秒耗时谁能顶得住。对接这规定引擎的还是业务的外围零碎,超时一分钟得少挣多少保费……

抱着试试看的心态,先钻研一下。

排查通过

这种偶发长耗时的问题,排查起来是比拟麻烦的。无奈稳固复现,也没有法则,就算弄个其余环境模拟也不是很好办;再加上这个零碎没文档没源码,更没人懂它的构造和流程,查起来就更吃力了。

看监控

在查看了监控历史之后,发现每次呈现长耗时的时候,CPU & 磁盘 IO 的利用率会升高,但也没高的很离谱。CPU 高的时候不过也才 五六十,而磁盘就更低了,只是略微有一点稳定而已,这点稳定会带来几十秒的耗时,可有点说不过去。

看日志

CPU 那块只是略微有点高,但也不能阐明什么问题,还是得找到根本原因。于是我又翻了下那个零碎的日志,看看能不能找到什么线索。

卡工夫,看日志,折腾了半小时,终于在日志上看到一个要害线索:

2021-05-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 利用率并不高,从数据上看还是比拟失常的。

好当初有(一丁点)线索了:

  1. 长耗时期间,CPU 利用率有减少
  2. 长耗时期间有日志打印,在加载某个货色,时长是能够匹配的
  3. 每次长耗时之前,有 GC 流动

    猜想可能的起因

    毕竟没有源码,也没人懂,想手撕代码都没机会,只能靠猜了……

从以上几个线索来看,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;
            } 
        }
    }

尽管删减了很多,但看代码还是有点不清晰,毕竟反编译的代码浏览烦扰有点大,这里简略解释下下面的代码逻辑:

  1. 先从缓存容器中获取资源
  2. 如果取不到就执行创立逻辑
  3. 创立实现,再次增加到缓存
  4. 在加载时若已有其余线程也执行加载,会被动 wait 期待第一个创立实现的线程唤醒

再联合咱们下面的猜想:

很可能是该零碎用弱援用 (Weak Reference) 来保护了这个资源缓存,当 GC 后该资源被回收,所以须要从新加载

那问题就在这个缓存容器上了!只有看看这个 cache 就能晓得,必定有弱援用的代码!

反编译找代码

jad 反编译在终端里看代码还是太折腾了,不如在 IDE 里直观,所以还是得把代码拉下来剖析,不然找个关联类都吃力。

这个零碎下有很多 Jar 包,得先找到这些相干的类在哪个 Jar 里,利用 Arthas 的 sc 命令,也非常简单:

sc 查看 JVM 已加载的类信息

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 命令,来看看缓存中的实时对象:

watch – 办法执行数据观测

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 回收该对象的状况,那还在意谁持有干嘛呢(其实是我懒,没文档还没源码,找问题找的我头都要秃了)

写在前面

原本认为须要先反编译,而后批改代码从新打包能力搞定的问题,最初居然一行代码都没改就解决了,有点小惊喜……

不过这个规定引擎的设计思路还是挺好的,为了节俭内存,应用可配置的缓存策略,只是默认应用弱援用来保护规定集太激进了点。对于大多数服务端场景来说,不差它这点开释的内存,给多少用多少就行,开释了反而会引发更大的问题,从新加载导致的耗时才是最不能承受的。

原创不易,禁止未受权的转载。如果我的文章对您有帮忙,就请点赞 / 珍藏 / 关注激励反对一下吧❤❤❤❤❤❤

正文完
 0