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
选择完成后就会看到启动的 banner
start
这时候 arthas 也启动了一个 web 程序,我们也可以通过 web 程序进行查看 http://127.0.0.1:3658/ 如图。
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 个调用点,和我们上面梳理的流程相吻合。下面是我执行多次实验后得出的结果:
插件 | 第一次 | 第二次 | 第 N 次 | 换新的URL |
---|---|---|---|---|
GlobalPlugin | [0.331097ms] org.dromara.soul.plugin.api.context.SoulContextBuilder:build() #55 | [1.502699ms] org.dromara.soul.plugin.api.context.SoulContextBuilder:build() #55 | [0.073924ms] org.dromara.soul.plugin.api.context.SoulContextBuilder:build() #55 | [2.89504ms] org.dromara.soul.plugin.api.context.SoulContextBuilder:build() #55 |
SignPlugin | [0.045042ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 | [0.259986ms] org.dromara.soul.common.dto.PluginData:getEnabled() #72 | [0.062875ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 | [0.673699ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 |
WafPlugin | [0.144881ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 | [0.238023ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 | [0.01466ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #104 | [0.19564ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 |
RateLimiterPlugin | [0.126271ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #70 | [0.096742ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 | [0.438668ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:selectorLog() #83 | [0.143929ms] org.dromara.soul.plugin.base.cache.BaseDataCache:getInstance() #70 |
DividePlugin | [13.579754ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:matchSelector() #79 | [9.051749ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:matchSelector() #79 | [0.438668ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:selectorLog() #83 [0.202057ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:matchSelector() #79 [0.16389ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:ruleLog() #100 | [2.054843ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:matchSelector() #79 [0.184361ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:ruleLog() #100 [1.281806ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:doExecute() #102 |
WebClientPlugin | [1.383439ms] org.springframework.web.reactive.function.client.WebClient$RequestBodyUriSpec:uri() [3.542673ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:handleRequestBody() #80 | [0.741347ms] org.springframework.web.reactive.function.client.WebClient$RequestBodyUriSpec:uri() #95 [5.540562ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:handleRequestBody() #80 | [2.138852ms] org.slf4j.Logger:info() #77 [0.721201ms] org.springframework.web.reactive.function.client.WebClient$RequestBodyUriSpec:uri() #95 [0.76901ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:handleRequestBody() #80 | [2.438417ms] org.springframework.web.reactive.function.client.WebClient$RequestBodyUriSpec:uri() #95 [3.392119ms] org.dromara.soul.plugin.httpclient.WebClientPlugin:handleRequestBody() #80 |
BodyParamPlugin | [0.039856ms] org.springframework.web.server.ServerWebExchange:getRequest() #57 | [0.037076ms] org.springframework.web.server.ServerWebExchange:getRequest() #57 | [0.019498ms] org.dromara.soul.common.enums.RpcTypeEnum:getName() #60 | [0.016459ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #73 |
MoniterPlugin | [0.276765ms] org.dromara.soul.plugin.base.cache.BaseDataCache:obtainPluginData() #95 | [0.037076ms] org.springframework.web.server.ServerWebExchange:getRequest() #57 | [0.018623ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #104 | [0.035214ms] org.dromara.soul.plugin.base.AbstractSoulPlugin:named() #68 |
WebClientResponsePlugin | [0.259639ms] reactor.core.publisher.Mono:then() #95 | [0.036432ms] org.dromara.soul.plugin.api.SoulPluginChain:execute() #55 | [0.137496ms] reactor.core.publisher.Mono:defer() #95 | [0.021621ms] reactor.core.publisher.Mono:then() #95 |
1.9.4 总结
从上面数据可以看出,Soul 只有在初次加载对应 URL 的时候会比较慢,主要发生在 matchSelector 上,但是重试多次后耗时明显减少。
网友评论