search

apache / dubbo

The java implementation of Apache Dubbo. An RPC and microservice framework.
https://dubbo.apache.org/
Apache License 2.0
40.5k stars 26.43k forks source link

Performance issue of NetUtils in Apple M2 #13743

Open dianjifzm opened 9 months ago

dianjifzm commented 9 months ago

Environment

Reproduction method 1

public static void main(String[] args) throws Exception {
         NetUtils.getLocalHost();
         long l = System.currentTimeMillis();
         NetUtils.getLocalHost();
         System.out.println("use " + (System.currentTimeMillis() - l) + "ms");
         System.out.println();
}

In most cases, the second call to NetUtils.getLocalHost() will take a very short time because HOST_ADDRESS has cached the results of the previous call. However, in the Apple M2 chip macOS 14.2.1 environment, non-root users will always return false when executing InetAddress.isReachable, which causes the HOST_ADDRESS assignment to fail.

Reproduction method 2

Because almost every line of logs uses NetUtils.getLocalHost(), this ultimately leads to a significant increase in dubbo's overall startup time.

The following log is the difference between the root user and ordinary users calling FrameworkModel.defaultModel() (pay attention to the timestamp of the log)

Java code

import org.apache.dubbo.rpc.model.FrameworkModel;

public class FrameworkModelDemo {

public static void main(String[] args) throws Exception {
long l = System.currentTimeMillis();
FrameworkModel.defaultModel();
System.out.println("use " + (System.currentTimeMillis() - l) + "ms");
}

}

general user

java -cp .:build:./target/dependency/* FrameworkModelDemo
2024-02-05 21:19:34.661 INFO org.apache.dubbo.rpc.model.FrameworkModel [<init>:86] [main] - [DUBBO] Dubbo Framework[1] is created, dubbo version: 3.2.11 , current host: 127.0.0.1
2024-02-05 21:19:35.098 INFO org.apache.dubbo.common.resource.GlobalResourcesRepository [getExecutorService:96] [main] - [DUBBO] Creating global shared handler ..., dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:35.569 INFO org.apache.dubbo.rpc.model.ApplicationModel [<init>:107] [main] - [DUBBO] Dubbo Application[1.0](unknown) is created, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:35.980 INFO org.apache.dubbo.rpc.model.ScopeModel [<init>:63] [main] - [DUBBO] Dubbo Module[1.0.0] is created, dubbo version: 3.2 .11, current host: 127.0.0.1
2024-02-05 21:19:36.416 INFO org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] - [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config. ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:36.828 INFO org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] - [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config. ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:37.248 INFO org.apache.dubbo.common.utils.SerializeSecurityManager [setCheckSerializable:107] [main] - [DUBBO] Serialize check serializable: true, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:37.660 INFO org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadAllow:135] [main] - [DUBBO] Read serialize allow list from jar:file:/Users/fzming/workspace/ demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.allowlist, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:38.118 INFO org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadBlocked:159] [main] - [DUBBO] Read serialize blocked list from jar:file:/Users/fzming/workspace/ demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.blockedlist, dubbo version: 3.2.11, current host: 127.0.0.1
use 4077ms

root user

sudo java -cp .:build:./target/dependency/* FrameworkModelDemo
2024-02-05 21:20:36.077 INFO org.apache.dubbo.rpc.model.FrameworkModel [<init>:86] [main] - [DUBBO] Dubbo Framework[1] is created, dubbo version: 3.2.11 , current host: 100.85.129.227
2024-02-05 21:20:36.087 INFO org.apache.dubbo.common.resource.GlobalResourcesRepository [getExecutorService:96] [main] - [DUBBO] Creating global shared handler ..., dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.127 INFO org.apache.dubbo.rpc.model.ApplicationModel [<init>:107] [main] - [DUBBO] Dubbo Application[1.0](unknown) is created, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.128 INFO org.apache.dubbo.rpc.model.ScopeModel [<init>:63] [main] - [DUBBO] Dubbo Module[1.0.0] is created, dubbo version: 3.2 .11, current host: 100.85.129.227
2024-02-05 21:20:36.139 INFO org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] - [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config. ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.139 INFO org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] - [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config. ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.144 INFO org.apache.dubbo.common.utils.SerializeSecurityManager [setCheckSerializable:107] [main] -  [DUBBO] Serialize check serializable: true, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.144 INFO  org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadAllow:135] [main] -  [DUBBO] Read serialize allow list from jar:file:/Users/fzming/workspace/demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.allowlist, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.166 INFO  org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadBlocked:159] [main] -  [DUBBO] Read serialize blocked list from jar:file:/Users/fzming/workspace/demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.blockedlist, dubbo version: 3.2.11, current host: 100.85.129.227
use 284ms

Environment

复现方式1

public static void main(String[] args) throws Exception {
        NetUtils.getLocalHost();
        long l = System.currentTimeMillis();
        NetUtils.getLocalHost();
        System.out.println("use " + (System.currentTimeMillis() - l) + "ms");
        System.out.println();
}

多数情况下，第二次调用NetUtils.getLocalHost() 会使用极短时间，因为HOST_ADDRESS已经缓存了上次调用的结果 但是在Apple M2芯片 macOS 14.2.1 环境下，非root用户执行 InetAddress.isReachable 会一直返回false，这导致了HOST_ADDRESS赋值失败。

复现方式2

因为几乎每行日志都使用了NetUtils.getLocalHost()，这最终导致了dubbo整体启动时间的大幅度上涨

下面日志是 root用户和普通用户调用FrameworkModel.defaultModel() 的区别（注意观察日志的时间戳）

Java代码

import org.apache.dubbo.rpc.model.FrameworkModel;

public class FrameworkModelDemo {

    public static void main(String[] args) throws Exception {
        long l = System.currentTimeMillis();
        FrameworkModel.defaultModel();
        System.out.println("use " + (System.currentTimeMillis() - l) + "ms");
    }

}

普通用户

java -cp .:build:./target/dependency/* FrameworkModelDemo
2024-02-05 21:19:34.661 INFO  org.apache.dubbo.rpc.model.FrameworkModel [<init>:86] [main] -  [DUBBO] Dubbo Framework[1] is created, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:35.098 INFO  org.apache.dubbo.common.resource.GlobalResourcesRepository [getExecutorService:96] [main] -  [DUBBO] Creating global shared handler ..., dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:35.569 INFO  org.apache.dubbo.rpc.model.ApplicationModel [<init>:107] [main] -  [DUBBO] Dubbo Application[1.0](unknown) is created, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:35.980 INFO  org.apache.dubbo.rpc.model.ScopeModel [<init>:63] [main] -  [DUBBO] Dubbo Module[1.0.0] is created, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:36.416 INFO  org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] -  [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config.ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:36.828 INFO  org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] -  [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config.ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:37.248 INFO  org.apache.dubbo.common.utils.SerializeSecurityManager [setCheckSerializable:107] [main] -  [DUBBO] Serialize check serializable: true, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:37.660 INFO  org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadAllow:135] [main] -  [DUBBO] Read serialize allow list from jar:file:/Users/fzming/workspace/demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.allowlist, dubbo version: 3.2.11, current host: 127.0.0.1
2024-02-05 21:19:38.118 INFO  org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadBlocked:159] [main] -  [DUBBO] Read serialize blocked list from jar:file:/Users/fzming/workspace/demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.blockedlist, dubbo version: 3.2.11, current host: 127.0.0.1
use 4077ms

root用户

sudo java -cp .:build:./target/dependency/* FrameworkModelDemo
2024-02-05 21:20:36.077 INFO  org.apache.dubbo.rpc.model.FrameworkModel [<init>:86] [main] -  [DUBBO] Dubbo Framework[1] is created, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.087 INFO  org.apache.dubbo.common.resource.GlobalResourcesRepository [getExecutorService:96] [main] -  [DUBBO] Creating global shared handler ..., dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.127 INFO  org.apache.dubbo.rpc.model.ApplicationModel [<init>:107] [main] -  [DUBBO] Dubbo Application[1.0](unknown) is created, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.128 INFO  org.apache.dubbo.rpc.model.ScopeModel [<init>:63] [main] -  [DUBBO] Dubbo Module[1.0.0] is created, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.139 INFO  org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] -  [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config.ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.139 INFO  org.apache.dubbo.config.context.AbstractConfigManager [initialize:143] [main] -  [DUBBO] Config settings: {dubbo.config.mode=STRICT, dubbo.config.ignore-duplicated-interface=false}, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.144 INFO  org.apache.dubbo.common.utils.SerializeSecurityManager [setCheckSerializable:107] [main] -  [DUBBO] Serialize check serializable: true, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.144 INFO  org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadAllow:135] [main] -  [DUBBO] Read serialize allow list from jar:file:/Users/fzming/workspace/demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.allowlist, dubbo version: 3.2.11, current host: 100.85.129.227
2024-02-05 21:20:36.166 INFO  org.apache.dubbo.common.utils.SerializeSecurityConfigurator [loadBlocked:159] [main] -  [DUBBO] Read serialize blocked list from jar:file:/Users/fzming/workspace/demos/alibaba.com/dubbo3/performance_init_test/target/dependency/dubbo-3.2.11.jar!/security/serialize.blockedlist, dubbo version: 3.2.11, current host: 100.85.129.227
use 284ms
AlbumenJ commented 9 months ago

Will InetAddress.getLocalHost() return null in your environment?

dianjifzm commented 9 months ago

Will InetAddress.getLocalHost() return null in your environment?

不是 InetAddress.getLocalHost() ,是NetUtils.getLocalAddress() 返回null 这会导致每次调用NetUtils.getLocalHost() 都会再次调用getLocalAddress() 并且触发完整的计算过程

我做了一些尝试。 仅在M2芯片，macOS 14.2.1 (mac mini) 会复现。 普通用户权限会一直返回false，root用户可以正常返回。

在Linux，inter 芯片的Mac，以及windows 11 上，都没有复现。

根本原因是InetAddress.isReachable的native实现有缺陷。 NetUtils中使用了InetAddress.isReachable做了有效性校验,导致了NetUtils.getLocalAddress() 返回null

其实网上吐槽InetAddress.isReachable的帖子有很多，很多人还建议用JNI调用ping的方式，在业务逻辑修复此缺陷

可以用如下代码验证

public static void main(String[] args) throws Exception {
    InetAddress address = InetAddress.getByName("192.168.2.4"); // 这你需要改成自己的IP地址
    System.out.println(address.getHostName() + " " + address.isReachable(1000));
}

普通用户发送ICMP报文需要一些特殊操作 参考macOS ping的源码

if (getuid())
    s = socket(AF_INET, SOCK_DGRAM, IPPROTO_ICMP);
else
    s = socket(AF_INET, SOCK_RAW, IPPROTO_ICMP);

jdk 中只是如下方式实现，所以有的环境就会出错。

socket(AF_INET, SOCK_DGRAM, IPPROTO_ICMP);
dianjifzm commented 9 months ago

InetAddress.isReachable 的问题虽然一直存在，但是在 dubbo 3.1.0 之前,NetUtils.getLocalAddress0() 并不会返回null

因为即使InetAddress.isReachable校验不通过,仍然会返回默认值 localAddress = InetAddress.getLocalHost();

后来代码中加入了IPv6支持 localAddress = getLocalAddressV6(); 导致 默认值逻辑发生变化，默认值不再是InetAddress.getLocalHost() 而是 getLocalAddressV6() 因此性能问题才出现。

我已经提交了修复方案，希望尽快CR https://github.com/apache/dubbo/pull/13745