作者 | 秋天
【Arthas 官网社区正在举办征文活动,加入即有奖品拿~ 点击投稿】
前段时间发现,在应用 RockerMQ console 时,查问音讯的时候呈现很慢,查问耗时大于 10 秒,少则 5、6 秒,多则 14+ 秒。
如下图:
这到底是为什么?查问音讯为啥会呈现这么大的耗时?
以后应用的开发环境:操作系统是 Windows10,JDK8,RocketMQ 为 4.5.2。
在其它机器上则没有此问题,也在本机器上的虚拟机 VMware 上装置的 Linux 部署了 RocketMQ 和 console,并且验证是没问题的。
那么到底我的机器是怎么了???
因为以后是接口的耗时问题,咱们并不知道耗时次要在哪个中央,所以应用 Arthas 来跟踪下调用链的耗时。
应用 trace 命令:
trace 命令
办法外部调用门路,并输入办法门路上的每个节点上耗时。
trace 命令能被动搜寻 class-pattern/method-pattern 对应的办法调用门路,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
trace org.apache.rocketmq.console.service.impl.MessageServiceImpl queryMessageByTopic
从以后调用门路失去次要耗时在于:DefaultMQPullConsumer 结构器初始化 + DefaultMQPullConsumer 启动耗时。那么接下来咱们持续往外部跟进。
此时咱们关注下 DefaultMQPullConsumer 结构器初始化:
trace org.apache.rocketmq.client.consumer.DefaultMQPullConsumer <init>
从结构器初始化入口看,耗时并不大。
那么接下来再看下 DefaultMQPullConsumer 的启动办法:
[E] 开启正则表达式匹配,默认为通配符匹配
trace -E org.apache.rocketmq.client.consumer.DefaultMQPullConsumer start
trace -E org.apache.rocketmq.client.consumer.DefaultMQPullConsumer <init>|start
接着发现耗时次要是在获取 MQClientInstance 实例。
trace org.apache.rocketmq.client.impl.MQClientManager getAndCreateMQClientInstance
trace org.apache.rocketmq.client.ClientConfig cloneClientConfig
接着看 ClientConfig#cloneClientConfig 办法:
public ClientConfig cloneClientConfig() {ClientConfig cc = new ClientConfig();
cc.namesrvAddr = namesrvAddr;
cc.clientIP = clientIP;
cc.instanceName = instanceName;
cc.clientCallbackExecutorThreads = clientCallbackExecutorThreads;
cc.pollNameServerInterval = pollNameServerInterval;
cc.heartbeatBrokerInterval = heartbeatBrokerInterval;
cc.persistConsumerOffsetInterval = persistConsumerOffsetInterval;
cc.unitMode = unitMode;
cc.unitName = unitName;
cc.vipChannelEnabled = vipChannelEnabled;
cc.useTLS = useTLS;
cc.namespace = namespace;
cc.language = language;
return cc;
}
能够看到很多赋值操作,这些能够不关注,只有关注 new ClientConfig():
trace org.apache.rocketmq.client.ClientConfig <init>
能够看到次要耗时在 3~4 秒,并且耗时次要是这个工具类办法:
RemotingUtil#getLocalAddress
“
trace org.apache.rocketmq.remoting.common.RemotingUtil getLocalAddress
到当初,曾经跟踪到 JDK 办法调用了:NetworkInterface#getNetworkInterfaces。
接着想查看 JDK 函数调用:
trace --skipJDKMethod false java.net.NetworkInterface getNetworkInterfaces
skipJDKMethod <value> skip jdk method trace, default value true.
默认状况下,trace 不会蕴含 jdk 里的函数调用,如果心愿 trace jdk 里的函数,须要显式设置 –skipJDKMethod false。
此时不能跟踪,那么依据 4 点提醒排查和 issue:
https://github.com/alibaba/arthas/issues/47
https://github.com/alibaba/arthas/issues/807
最初确定须要开启 unsafe。
options unsafe true
开启实现。
再次执行,即可看到 jdk 的调用链了。
到这里,算是把 RocketMQ console 查问慢的 罪魁祸首 找到了:在获取本机网卡接口时,呈现耗时工夫长。这其实也算是 jdk 跟操作系统层面的意思了,与中间件 RocketMQ 无关,一开始我是狐疑是不是长久化存储在加载时慢的可能(根本排除)。
那么为什么会调用以后操作系统的网卡接口时会呈现耗时重大呢?
此时关注到了 java.net.NetworkInterface#getNetworkInterfaces
public static Enumeration<NetworkInterface> getNetworkInterfaces()
throws SocketException {final NetworkInterface[] netifs = getAll();
// specified to return null if no network interfaces
if (netifs == null)
return null;
return new Enumeration<NetworkInterface>() {
private int i = 0;
public NetworkInterface nextElement() {if (netifs != null && i < netifs.length) {NetworkInterface netif = netifs[i++];
return netif;
} else {throw new NoSuchElementException();
}
}
public boolean hasMoreElements() {return (netifs != null && i < netifs.length);
}
};
}
private native static NetworkInterface[] getAll() throws SocketException;
能够看到 jdk 函数曾经调用到了 native 办法,也就是 jdk 底层的实现 (c/c++) 了,跟操作系统十分严密。
接着 debug 进 getNetworkInterfaces 办法查看到底有哪些网卡接口:
一查发现居然有 81 个!接着查看本机的网络适配器:
本机 Windows 上有 Wlan、VPN、VMware 等网络适配器。
最初事实就是跟他们无关,我把相应的适配器禁用之后,从新调用 NetworkInterface#getNetworkInterfaces,此时耗时从 3+ 秒降到几百毫秒。
最初,很遗憾还是没能分析出为什么 Windows 下调用网卡接口 native 办法会呈现那么大耗时。并且必定跟我的机器无关,因为其余机器验证没有问题。
如果要分析起因,就得须要有 c/c++ 更加底层的功底能力搞定吧?
总结:
- Windows 下可能容易呈现一些非正常问题,居然也能给我遇到这个 ^@^。幸好个别应用 Windows 还是比拟少,除非是开发机器较多,Linux(unix) 部署 RocketMQ 等中间件还是很稳的。
- 应用 Arthas trace 能够跟踪办法的调用门路,并且追踪每一步的耗时,能够不便的排查瓶颈问题。
- -E 参数反对正则表达式匹配;–skipJDKMethod false 反对蕴含 JDK 的函数调用;跟踪 jdk 函数等,如果找不到对应类或者办法,可能须要开启 unsafe。
作者 | 秋天,关注 Java 后端,分布式,微服务,零碎架构等。集体公众号《搬运工来架构》。