记一次Java调优，性能提高20倍

谁借莪１个温暖的怀抱￠ 2022-02-27 16:40 300阅读 0赞

# 记一次Java调优，性能提高20倍 #

## 背景 ##

最近我们接入网关OpenAccess服务增加了流量监控（阿里的Sentinel），进入测试环境，用20个线程并发测试后发现性能问题很严重，响应时间到达了1000+ms，这是完全不可以接受的数据。![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70]

## 解决过程 ##

**添加挡板机**  
由于OpenAccess项目是一个接入网关，实际会调用后端服务来提供具体服务，因此初步怀疑是后端服务问题，  
**日志分析**  
经过检查日志发现“果然如此”。  
在vim中通过正则表达式查找 **耗时\\d\\d\\d**  
查找到 **调用用服务/utils/cert,耗时308**

2019-03-27 09:19:05,240 [d90caafa9da696a5] [015e13ba96ca1fe9] [0a884e66a831ab40] [http-nio-8898-exec-138] [INFO ] [c.j.c.t.r.t.r.service.BaseRpcService] [getTTransport] [120] => 创建/auth/auth_server服务链接，服务地址为172.20.21.40:7000
    2019-03-27 09:19:05,241 [94150341f8c2698e] [5ccc543994b1551a] [863f92af67bfc01a] [http-nio-8898-exec-150] [INFO ] [c.j.c.t.r.t.r.service.BaseRpcService] [invoke] [88] => 调用用服务/utils/cert,耗时308,返回内容为{"orgCode": "100024","merchNo": "JQ1000245100061","transId": "737848292845705","transTime": "2018-12-27 15:34:22","phoneNo": "13517198483","name": "关耳","certType": "01","certNo": "476da936e995408f99","sign": "GwWOFLfsBtj5oxfd/DsRdwnW3YkBUeiXyVfURuKEqF+rKkFTISnbNWBHUnbxc8SW1lp+p4CnPwXzgNi21Mg9UBZoduWhIXcjV1S12ZwUpAMZLnYFaZroRBttaAfThe9sCfV30bN3szG8okgyrRp7PB2kXvkg/38HYiMMllhUbG3rri5cUWT9m/n4btD6CAH/LWxKaHMDYeD1mbYSjru/QT/6qQ654fDtySvNpiWJPBpXlNceB4vfuIvpZmTkS8a6x8nJrSBIBlYy6m3sCtxdjZermuo/qhyrmfIr76/kskl6DCtRJkgNd+qSiXOr3+DqoaxGux8BD9rmupXsTHCG7w==","ret_code":"00","ret_msg":"验签成功"}

然后增加了挡板机，注册到rpc服务节点，当OpenAccess调用时直接返回，这样就可以直接测到OpenAccess自己的性能。

然而发现性能问题依然存在

**替换挡板机**  
由于挡板机出现过几次宕机问题，加上日志分析就是rpc调用耗时过多，因此决定自己写了个挡板机来测试。  
结果发现依然没有改善。

## Java VisualVM性能分析 ##

猜测宣告破产后决定还是稳扎稳打，用VisualVM性能分析工具。

### 应用开启jmx ###

首先应用启动的时候增加 jmx 参数 ，这样就会开启应用远程jmx，监听-Dcom.sun.management.jmxremote.port=1099 参数对应的端口了  
start.sh脚本里面有如下内容

JAVA_JMX_OPTS=""
    if [ "$1" = "jmx" ]; then
        JAVA_JMX_OPTS=" -Dcom.sun.management.jmxremote.port=1099 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false "
    fi

### VisualVM远程连接到应用 ###

这里配置需要监控应用的ip port即可连接成功  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 1]

### 查看热点方法 ###

连接成功后通过查找热点方法 ， 用**jlpay** 来搜索，发现时间主要是卡在com.jlpay.commons.tools.rpc.thrift.referer.service.BaseRpcService.getTTransport() 0.0 0.000 ms (0%) 0.000 ms 12,217 ms 209 ms  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 2]

### 查看代码 ###

查看上面getTTransport方法，看看里面都有些什么处理步骤。  
每次调用rpc invoke的时候都会获取环境变量里面的连接超时参数，如为空则取默认值。设置到socket上面

String connectTimeoutStr = SpringContextUtil.getPropertiesValue("thrift.connectTimeout","50000");
    		socket.setConnectTimeout(Integer.parseInt(connectTimeoutStr));
    		String socketTimeoutStr = SpringContextUtil.getPropertiesValue("thrift.socketTimeout","50000");
    		socket.setSocketTimeout(Integer.parseInt(socketTimeoutStr));
    		String timeoutStr = SpringContextUtil.getPropertiesValue("thrift.timeout","");

再到VisualVM里面查看SpringContextUtil.getPropertiesValue调用耗时200多ms  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 3]

![在这里插入图片描述][20190328105422498.png]

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 4]

### 构造异常代价昂贵 ###

然而这里取默认值的方式是抛异常，异常构造的话需要遍历当前线程的所有堆栈信息（类，方法，行号等），堆栈多的时候有几十个，这可是相当耗时的。  
因为应用没有赋值，所有每次调用都会构造这三个异常。在高并发的时候就验证影响性能了。

public static String getPropertiesValue(String name,String defaultVal){
        if(!name.startsWith("${")){
            name = "${" + name + "}";
        }
        String val = null;
        try{
            val = STRINGVALUERESOLVER.resolveStringValue(name);
        }catch(Throwable e){
            logger.info("没有配置{" + name + "}属性，取默认值" + defaultVal);
        }
    
        return StringUtils.isNotEmpty(val)?val:defaultVal;
    }

## 解决方案 ##

问题是因为每次rpc调用去获取环境变量导致的。  
因此我们可以事先将环境变量赋值给一个静态变量，这样就不需要每次都去Spring容器里面找环境变量而带来的开销了。  
最后性能如图：（阿里的Sentinel监控性能）  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 5]  
**优化后从1000+ms降到50ms 性能提升了20多倍**

## 总结 ##

当碰到性能问题是，一定要稳住。  
通过日志，VisualVM，源码，测试等多维度分析问题。  
一个个排除，验证。  
剩下的就只是时间问题了。

## 感谢 ##

感谢钟勇，刘明星给予测试支持，感谢陆建源提供帮助。

## 参考 ##

[Java虚拟机性能管理神器 - VisualVM][Java_ - VisualVM]

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70]: /images/20220227/be11950a79134f2d81d242477dde9c8f.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 1]: /images/20220227/50ef86ef8be0400f94df8d7a81bbcdaa.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 2]: /images/20220227/b7fda379907e453ea1c45421126d17f0.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 3]: /images/20220227/4297875ac1194fbf9e9ebb71562fe3b8.png
[20190328105422498.png]: /images/20220227/85896e1e80254151b39c44befaadfcd4.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 4]: /images/20220227/84f1fd2e80ff46eabe0a0a0ba46a4d93.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzE1Mjg4MDIz_size_16_color_FFFFFF_t_70 5]: /images/20220227/d416a979566a466681fbeea35ffd9cb7.png
[Java_ - VisualVM]: https://blog.csdn.net/chwshuang/article/details/44203471