Arthas 是Alibaba开源的Java诊断工具，我们可以通过 Arthas 查看内存状态，线程状态，类加载，dump ，基于字节码增强的性能追踪等。

1.9.1 准备

这次分析我们采用最常用等 Divide 插件进行追踪，我们先下载和启动 arthas ，它的使用非常简单。

curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar

执行完成后我们需要选择 attach 的进程，我们因为需要分析转发的性能需要 attach soulBootstrap

arthas

start

web

1.9.2 Divide 处理流程

我们通过 Divide 来查看一个最简单的插件进行分析，我们先回忆一下 Http 类请求的整体处理流程，如图

pluginChain

1.9.3 Trace 分析

我们需要分析整体的耗时，我们先要知道它究竟调用了哪些地方，我们知道 WebFlux 的处理入口是 WebHandler 的 handle 方法，而 Soul 对应的就是 SoulWebHandler 类的 Excute 方法，如下：

    @Override
    public Mono<Void> handle(@NonNull final ServerWebExchange exchange) {
        MetricsTrackerFacade.getInstance().counterInc(MetricsLabelEnum.REQUEST_TOTAL.getName());
        Optional<HistogramMetricsTrackerDelegate> startTimer = MetricsTrackerFacade.getInstance().histogramStartTimer(MetricsLabelEnum.REQUEST_LATENCY.getName());
        return new DefaultSoulPluginChain(plugins).execute(exchange).subscribeOn(scheduler)
                .doOnSuccess(t -> startTimer.ifPresent(time -> MetricsTrackerFacade.getInstance().histogramObserveDuration(time)));
    }

我们其实只需要分析其中的 DefaultSoulPluginChain 的 excute 方法。
我们在 arthas 执行以下命令

stack org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain execute

然后调用以下我们 Divide 的接口 http://localhost:9195/http/order/findById?id=1。我们得到以下信息，这里包括了 18个被调用的方法，如下(结果过长，就不一一展示了)

ts=2021-01-28 23:31:46;thread_name=soul-netty-nio-3;id=5e;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    @org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain.execute()
        at org.dromara.soul.web.handler.SoulWebHandler.handle(SoulWebHandler.java:73)
        at ...

接着我们调用如下命令进行查看 具体耗时：

trace org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain execute

同样我们也得到响应的18结果：

        `---ts=2021-01-28 23:50:01;thread_name=soul-netty-nio-5;id=63;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[2.362646ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.063881ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=soul-work-threads-6;id=64;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.250804ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.046692ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=soul-work-threads-6;id=64;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.179434ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.043039ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=soul-work-threads-6;id=64;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.088269ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.021674ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=soul-work-threads-6;id=64;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.502399ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.212013ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=soul-work-threads-6;id=64;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.083462ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.02719ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=reactor-http-kqueue-1;id=47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.257032ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.072841ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=reactor-http-kqueue-1;id=47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.155038ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.034733ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=reactor-http-kqueue-1;id=47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.19631ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.031338ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=reactor-http-kqueue-1;id=47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.116982ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.02991ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=reactor-http-kqueue-1;id=47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.149141ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.033718ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=reactor-http-kqueue-1;id=47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.07365ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.023911ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:01;thread_name=reactor-http-kqueue-1;id=47;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.102299ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.049757ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:02;thread_name=soul-netty-nio-5;id=63;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.158643ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.052743ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:02;thread_name=soul-work-threads-8;id=66;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.335321ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.093027ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:02;thread_name=soul-work-threads-8;id=66;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.096204ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.031532ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:02;thread_name=soul-work-threads-8;id=66;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.125593ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.028946ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-28 23:50:02;thread_name=soul-work-threads-8;id=66;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.13457ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.031757ms] reactor.core.publisher.Mono:defer() #100

这里需要注意，一定不能进行预热，因为预热可能导致方法内联，不清楚的同学可以学一下关于即时编译的内容，我进行预热后得到只有13个调用点，如下：

`---ts=2021-01-29 00:01:15;thread_name=soul-netty-nio-3;id=5e;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[5.596314ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.063764ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=soul-work-threads-16;id=70;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.06677ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.015098ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=soul-work-threads-16;id=70;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.129881ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.03706ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=soul-work-threads-16;id=70;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.128426ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.026094ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=soul-work-threads-16;id=70;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.073032ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.016173ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=soul-work-threads-16;id=70;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.040023ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.010086ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=reactor-http-kqueue-2;id=48;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.049372ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.011385ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=reactor-http-kqueue-2;id=48;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.105459ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.022664ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=reactor-http-kqueue-2;id=48;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.060692ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.017015ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=reactor-http-kqueue-2;id=48;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.07752ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.022005ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=reactor-http-kqueue-2;id=48;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.426749ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.123571ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=reactor-http-kqueue-2;id=48;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.136333ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.036481ms] reactor.core.publisher.Mono:defer() #100

`---ts=2021-01-29 00:01:15;thread_name=reactor-http-kqueue-2;id=48;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.132235ms] org.dromara.soul.web.handler.SoulWebHandler$DefaultSoulPluginChain:execute()
        `---[0.035674ms] reactor.core.publisher.Mono:defer() #100

但是显然我们从上面的信息并不能分析出这写消耗和那个Plugin 相对应，我们可以改变一下思路，可以对上面经过的所有插件进行拦截，对于直接实现 SoulPlugin 的插件拦截对应的 excute 方法，而对应 AbstractSoulPlugin 的 doExecute 方法，具体命令如下：

trace -E org.dromara.soul.plugin.global.GlobalPlugin|org.dromara.soul.plugin.sign.SignPlugin|org.dromara.soul.plugin.waf.WafPlugin|org.dromara.soul.plugin.ratelimiter.RateLimiterPlugin|org.dromara.soul.plugin.divide.DividePlugin|org.dromara.soul.plugin.httpclient.WebClientPlugin|org.dromara.soul.plugin.apache.dubbo.param.BodyParamPlugin|org.dromara.soul.plugin.monitor.MonitorPlugin|org.dromara.soul.plugin.httpclient.response.WebClientResponsePlugin execute|doExecute|execute|doExecute|doExecute|execute|execute|doExecute|execute

结果如下：

`---ts=2021-01-29 16:53:43;thread_name=soul-work-threads-13;id=53;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[1.287732ms] org.dromara.soul.plugin.global.GlobalPlugin:execute()
        +---[0.026801ms] org.springframework.web.server.ServerWebExchange:getRequest() #50
        +---[0.01792ms] org.springframework.http.server.reactive.ServerHttpRequest:getHeaders() #51
        +---[0.033966ms] org.springframework.http.HttpHeaders:getFirst() #52
        +---[0.008321ms] org.apache.commons.lang3.StringUtils:isBlank() #54
        +---[0.703468ms] org.dromara.soul.plugin.api.context.SoulContextBuilder:build() #55
        +---[0.032348ms] org.springframework.web.server.ServerWebExchange:getAttributes() #60
        `---[0.054001ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #61

`---ts=2021-01-29 16:53:43;thread_name=soul-work-threads-13;id=53;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[1.32451ms] org.dromara.soul.plugin.divide.DividePlugin:doExecute()
        +---[0.041803ms] org.springframework.web.server.ServerWebExchange:getAttribute() #57
        +---[0.032523ms] org.dromara.soul.common.utils.GsonUtils:getInstance() #59
        +---[0.011972ms] org.dromara.soul.common.dto.RuleData:getHandle() #95
        +---[0.221807ms] org.dromara.soul.common.utils.GsonUtils:fromJson() #95
        +---[0.036743ms] org.dromara.soul.plugin.divide.cache.UpstreamCacheManager:getInstance() #61
        +---[0.097811ms] org.dromara.soul.common.dto.SelectorData:getId() #95
        +---[0.031696ms] org.dromara.soul.plugin.divide.cache.UpstreamCacheManager:findUpstreamListBySelectorId() #95
        +---[0.014219ms] org.apache.commons.collections4.CollectionUtils:isEmpty() #62
        +---[0.032081ms] org.springframework.web.server.ServerWebExchange:getRequest() #67
        +---[0.031732ms] org.springframework.http.server.reactive.ServerHttpRequest:getRemoteAddress() #95
        +---[0.012427ms] org.dromara.soul.common.dto.convert.rule.impl.DivideRuleHandle:getLoadBalance() #69
        +---[0.04315ms] org.dromara.soul.plugin.divide.balance.utils.LoadBalanceUtils:selector() #95
        +---[0.020375ms] org.dromara.soul.plugin.divide.DividePlugin:buildDomain() #76
        +---[0.052958ms] org.dromara.soul.plugin.divide.DividePlugin:buildRealURL() #77
        +---[0.021649ms] org.springframework.web.server.ServerWebExchange:getAttributes() #78
        +---[0.020268ms] org.springframework.web.server.ServerWebExchange:getAttributes() #80
        +---[0.01475ms] org.dromara.soul.common.dto.convert.rule.impl.DivideRuleHandle:getTimeout() #95
        +---[0.005848ms] org.springframework.web.server.ServerWebExchange:getAttributes() #81
        +---[0.014963ms] org.dromara.soul.common.dto.convert.rule.impl.DivideRuleHandle:getRetry() #95
        `---[0.02937ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #82

`---ts=2021-01-29 16:53:43;thread_name=soul-work-threads-13;id=53;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[1.86804ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:execute()
        +---[0.016306ms] org.springframework.web.server.ServerWebExchange:getAttribute() #68
        +---[0.006429ms] org.springframework.web.server.ServerWebExchange:getAttribute() #70
        +---[0.014942ms] org.apache.commons.lang3.StringUtils:isEmpty() #71
        +---[0.01347ms] org.springframework.web.server.ServerWebExchange:getAttribute() #75
        +---[0.014052ms] org.springframework.web.server.ServerWebExchange:getAttribute() #76
        +---[0.189128ms] org.slf4j.Logger:info() #77
        +---[0.016133ms] org.springframework.web.server.ServerWebExchange:getRequest() #78
        +---[0.011232ms] org.springframework.http.server.reactive.ServerHttpRequest:getMethodValue() #95
        +---[0.011049ms] org.springframework.http.HttpMethod:valueOf() #95
        +---[0.021123ms] org.springframework.web.reactive.function.client.WebClient:method() #79
        +---[0.394069ms] org.springframework.web.reactive.function.client.WebClient$RequestBodyUriSpec:uri() #95
        `---[0.933125ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:handleRequestBody() #80

`---ts=2021-01-29 16:53:43;thread_name=reactor-http-kqueue-2;id=43;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.118771ms] org.dromara.soul.plugin.httpclient.response.WebClientResponsePlugin:execute()
        +---[0.020119ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #55
        +---[0.012962ms] reactor.core.publisher.Mono:defer() #95
        `---[0.009777ms] reactor.core.publisher.Mono:then() #95

我们发现这里只有4个方法被 trace 了，后面根据堆栈信息可以看出来，我们调用关系是 AbstractSoulPlugin 的 excute 方法调用了具体插件的 doExcute 方法，但是并不是所有的插件会进入 doExcute 方法，其简化代码如下：

    @Override
    public Mono<Void> execute(final ServerWebExchange exchange, final SoulPluginChain chain) {
        String pluginName = named();
        // 获取数据
        final PluginData pluginData = BaseDataCache.getInstance().obtainPluginData(pluginName);
        // 判断是否开启插件
        if (pluginData != null && pluginData.getEnabled()) {
            // 获取选择器
            final Collection<SelectorData> selectors = BaseDataCache.getInstance().obtainSelectorData(pluginName);
            //查看是否匹配
            final SelectorData selectorData = matchSelector(exchange, selectors);
            selectorLog(selectorData, pluginName);
            // 获取规则
            final List<RuleData> rules = BaseDataCache.getInstance().obtainRuleData(selectorData.getId());
            RuleData rule;
            // 查找规则，假如是全局匹配则直接取最后一个规则
            if (selectorData.getType() == SelectorTypeEnum.FULL_FLOW.getCode()) {
                //get last
                rule = rules.get(rules.size() - 1);
            } else {
                rule = matchRule(exchange, rules);
            }
            ruleLog(rule, pluginName);
            // 真正执行规则
            return doExecute(exchange, chain, selectorData, rule);
        }
        return chain.execute(exchange);
    }

这里会有个问题就是对于继承了 AbstractSoulPlugin 的插件，我们只能观察其内部的 doExcute 耗时，并不能分析 excute 的整体耗时，因为还需要做规则匹配这些耗时比较高的动作。有很多人会有疑问，那为什么不直接观察各个插件的 execute 方法呢，我们可以先通过 sm 命令查看加载到内存中到类，如 DividePlugin：

[arthas@10916]$ sm org.dromara.soul.plugin.divide.DividePlugin
org.dromara.soul.plugin.divide.DividePlugin <init>()V
org.dromara.soul.plugin.divide.DividePlugin getOrder()I
org.dromara.soul.plugin.divide.DividePlugin named()Ljava/lang/String;
org.dromara.soul.plugin.divide.DividePlugin skip(Lorg/springframework/web/server/ServerWebExchange;)Ljava/lang/Boolean;
org.dromara.soul.plugin.divide.DividePlugin doExecute(Lorg/springframework/web/server/ServerWebExchange;Lorg/dromara/soul/plugin/api/SoulPluginChain;Lorg/dromara/soul/common/dto/SelectorData;Lorg/dromara/soul/common/dto/RuleData;)Lreactor/core/publisher/Mono;
org.dromara.soul.plugin.divide.DividePlugin handleSelectorIsNull(Ljava/lang/String;Lorg/springframework/web/server/ServerWebExchange;Lorg/dromara/soul/plugin/api/SoulPluginChain;)Lreactor/core/publisher/Mono;
org.dromara.soul.plugin.divide.DividePlugin handleRuleIsNull(Ljava/lang/String;Lorg/springframework/web/server/ServerWebExchange;Lorg/dromara/soul/plugin/api/SoulPluginChain;)Lreactor/core/publisher/Mono;
org.dromara.soul.plugin.divide.DividePlugin buildDomain(Lorg/dromara/soul/common/dto/convert/DivideUpstream;)Ljava/lang/String;
org.dromara.soul.plugin.divide.DividePlugin buildRealURL(Ljava/lang/String;Lorg/dromara/soul/plugin/api/context/SoulContext;Lorg/springframework/web/server/ServerWebExchange;)Ljava/lang/String;
Affect(row-cnt:9) cost in 44 ms.

这里并不能通过 trace org.dromara.soul.plugin.divide.DividePlugin 的 excute 方法，因为这个是它父类实现的。所以聪明的同学肯定会想到了，我们直接 trace SoulPlugin 的 excute 方法不就可以了嘛，这样根据整个调用链的插件就可以推断出现在处于那个Plugin上了，我们改一下命令如下：

trace org.dromara.soul.plugin.api.SoulPlugin execute -n 1000

这里指定 -n 是因为默认 trace 次数是有限制的，需要指定大点，因为每次调用一个转发请求就会调用到 9 个插件。调用结果如图：

[arthas@10916]$ trace org.dromara.soul.plugin.api.SoulPlugin execute -n 1000
Press Q or Ctrl+C to abort.
Affect(class count: 14 , method count: 6) cost in 457 ms, listenerId: 15
`---ts=2021-01-29 23:12:51;thread_name=soul-work-threads-10;id=50;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[1.904918ms] org.dromara.soul.plugin.global.GlobalPlugin:execute()
        +---[0.086831ms] org.springframework.web.server.ServerWebExchange:getRequest() #50
        +---[0.036841ms] org.springframework.http.server.reactive.ServerHttpRequest:getHeaders() #51
        +---[0.021279ms] org.springframework.http.HttpHeaders:getFirst() #52
        +---[0.020595ms] org.apache.commons.lang3.StringUtils:isBlank() #54
        +---[0.826158ms] org.dromara.soul.plugin.api.context.SoulContextBuilder:build() #55
        +---[0.017089ms] org.springframework.web.server.ServerWebExchange:getAttributes() #60
        `---[0.04356ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #61

`---ts=2021-01-29 23:12:51;thread_name=soul-work-threads-10;id=50;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.444971ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:execute()
        +---[0.092571ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68
        +---[0.017967ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #70
        +---[0.033778ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainPluginData() #95
        +---[0.036787ms] org.dromara.soul.common.dto.PluginData:getEnabled() #72
        `---[0.028727ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #104

`---ts=2021-01-29 23:12:51;thread_name=soul-work-threads-10;id=50;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.170834ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:execute()
        +---[0.04165ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68
        +---[0.01403ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #70
        +---[0.012828ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainPluginData() #95
        +---[0.007491ms] org.dromara.soul.common.dto.PluginData:getEnabled() #72
        `---[0.014301ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #104

`---ts=2021-01-29 23:12:51;thread_name=soul-work-threads-10;id=50;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.144436ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:execute()
        +---[0.031362ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68
        +---[0.008203ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #70
        +---[0.008267ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainPluginData() #95
        +---[0.011744ms] org.dromara.soul.common.dto.PluginData:getEnabled() #72
        `---[0.012916ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #104

`---ts=2021-01-29 23:12:51;thread_name=soul-work-threads-10;id=50;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[11.965658ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:execute()
        +---[0.018464ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68
        +---[0.011979ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #70
        +---[0.015838ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainPluginData() #95
        +---[0.014444ms] org.dromara.soul.common.dto.PluginData:getEnabled() #72
        +---[0.006679ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #74
        +---[0.730685ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainSelectorData() #95
        +---[0.092864ms] org.apache.commons.collections4.CollectionUtils:isEmpty() #75
        +---[5.86884ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:matchSelector() #79
        +---[1.253869ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:selectorLog() #83
        +---[0.007722ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #85
        +---[0.012988ms] org.dromara.soul.common.dto.SelectorData:getId() #95
        +---[0.052313ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainRuleData() #95
        +---[0.023638ms] org.apache.commons.collections4.CollectionUtils:isEmpty() #86
        +---[0.030749ms] org.dromara.soul.common.dto.SelectorData:getType() #91
        +---[0.006429ms] org.dromara.soul.common.enums.SelectorTypeEnum:getCode() #95
        +---[1.655154ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:matchRule() #95
        +---[0.197479ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:ruleLog() #100
        `---[1.496909ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:doExecute() #102

`---ts=2021-01-29 23:12:51;thread_name=soul-work-threads-10;id=50;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[14.326327ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:execute()
        +---[0.021344ms] org.springframework.web.server.ServerWebExchange:getAttribute() #68
        +---[0.010795ms] org.springframework.web.server.ServerWebExchange:getAttribute() #70
        +---[0.042346ms] org.apache.commons.lang3.StringUtils:isEmpty() #71
        +---[0.007385ms] org.springframework.web.server.ServerWebExchange:getAttribute() #75
        +---[0.012286ms] org.springframework.web.server.ServerWebExchange:getAttribute() #76
        +---[0.201008ms] org.slf4j.Logger:info() #77
        +---[0.057991ms] org.springframework.web.server.ServerWebExchange:getRequest() #78
        +---[0.027218ms] org.springframework.http.server.reactive.ServerHttpRequest:getMethodValue() #95
        +---[0.057937ms] org.springframework.http.HttpMethod:valueOf() #95
        +---[0.703145ms] org.springframework.web.reactive.function.client.WebClient:method() #79
        +---[0.953734ms] org.springframework.web.reactive.function.client.WebClient$RequestBodyUriSpec:uri() #95
        `---[11.056015ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:handleRequestBody() #80

`---ts=2021-01-29 23:12:51;thread_name=reactor-http-kqueue-3;id=44;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[1.966105ms] org.dromara.soul.plugin.sofa.param.BodyParamPlugin:execute()
        +---[0.025663ms] org.springframework.web.server.ServerWebExchange:getRequest() #57
        +---[0.019747ms] org.springframework.web.server.ServerWebExchange:getAttribute() #59
        +---[0.015248ms] org.dromara.soul.common.enums.RpcTypeEnum:getName() #60
        +---[0.01464ms] org.dromara.soul.plugin.api.context.SoulContext:getRpcType() #95
        `---[0.012746ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #73

`---ts=2021-01-29 23:12:51;thread_name=reactor-http-kqueue-3;id=44;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.240885ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:execute()
        +---[0.02733ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68
        +---[0.0576ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #70
        +---[0.039405ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainPluginData() #95
        +---[0.00739ms] org.dromara.soul.common.dto.PluginData:getEnabled() #72
        `---[0.018135ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #104

`---ts=2021-01-29 23:12:51;thread_name=reactor-http-kqueue-3;id=44;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@14dad5dc
    `---[0.884873ms] org.dromara.soul.plugin.httpclient.response.WebClientResponsePlugin:execute()
        +---[0.025427ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #55
        +---[0.027265ms] reactor.core.publisher.Mono:defer() #95
        `---[0.025478ms] reactor.core.publisher.Mono:then() #95

这里刚好 9 个调用点，和我们上面梳理的流程相吻合。下面是我执行多次实验后得出的结果：

1.9.4 总结

从上面数据可以看出，Soul 只有在初次加载对应 URL 的时候会比较慢，主要发生在 matchSelector 上，但是重试多次后耗时明显减少。