excel导出使用arthas动态追踪方法调用耗时后性能优化的过程

一、背景

1、用户反应某个报表导出时等待很久也没有导出来，我F12查看导出接口在1.5min的时间请求被取消，后端服务器的网关（如Nginx、Apache）或后端应用本身可能设置了90秒的超时，用户一直等待也没有导出文件，所以需要优化导出逻辑加快导出时间。

二、发现问题

1、本地调试

1.1安装启动arthas

（1）、下载地址：https://arthas.aliyun.com/arthas-boot.jar
Linux 下载 curl -O https://arthas.aliyun.com/arthas-boot.jar
（2）、启动java -jar arthas-boot.jar
（3）、选择目标应用id回车
（4）、执行tarce命令 -n 5 表示最多捕获5次方法调用，使用–skipJDKMethod false包含基础库调用耗时,还可以添加这个参数’#cost>500’表示只显示超过500毫秒的。

trace 全类名 方法名-n5--skipJDKMethodfalse

mybatis sql 打印：

watchorg.apache.ibatis.executor.SimpleExecutordoQuery '{params[0].resource,params[0].id,params[4].sql,params[4].parameterObject,returnObj,throwExp}' 'params[0].id.contains("namespace.id")'-x3

调用TreadLocal中的remove方法：

watch 全类名*'{params, @全类名@方法名()}'-s-b

关于arthas的命令，可以安装idea插件arthas idea

选中方法名称鼠标右键，Arthas Command中可以选择相应的命令，可以复制出来，直接使用

1.2代码逻辑分析及初步优化

从代码看有三个主要逻辑，第一个使用远程调用的方式获取数据大概12万条，第二个是循环获取数据对某个字段进行国际化如下图，

第三个是把数据写入excel方法。
通过打断点发现，在第二个逻辑国际化方法中阻塞时间很久，所以决定先优化国际化的逻辑，放弃循环结果集，改为改成了sql关联国际化表的形式。

1.3使用arthas追踪耗时情况并进一步优化

解决完字段国际化后，重新看一下耗时情况。

从耗时情况分析远程获取数据方法占用主要时间，所以需要优化查询逻辑，经过查看sql执行计划extra 中useing filesort，没有在排序字段上创建索引导致创建索引后重新看耗时时间，获取数据缩短到50s。数据写入到excel耗时13s左右。总耗时63s左右小于90s本地可以正常导出。

2、服务器调试

本地调试好以后本以为问题就解决了，但是发布到生产服务器后，导出还是1.5min后取消了，没有什么效果，所以在生产服务器上进行了两个测试。
arthas下载命令：curl -O https://arthas.aliyun.com/arthas-boot.jar
然后启动和选择目标服务进入arthas终端

2.1、测试一使用arthas查看修改后的代码是否生效

在arthas终端中执行：

jad 全类名

反编码查看代码是否修改后的逻辑,我发现代码已经是修改后的。

2.2、测试二使用arthas追踪耗时情况

执行trace 全类名 方法名 -n 5 --skipJDKMethod false后在生产上执行导出

2.3、结论

通过上面结果可以发现，73.86%耗时的是把数据写入excel的方法。所以优化重点是数据写入excel。

三、解决问题

1、原来数据写入excel的方法

循环遍历所有的数据，如果数据是实体类对象则使用反射的方式获取对象中的属性值，这里有多少数据量就会使用几次反射，反射开销很大。

2、修改成使用fastexcel

FastExcel 使用了缓存，避免重复使用反射方法获取属性值，提高了性能。还有就是字段国际化，可以使用处理器进行处理（自定义了I18nCellWriteHandler处理器），所以sql中关联表国际化的逻辑去掉了。

这个是优化后的追踪方法调用耗时情况，数据写入excel速度显著提高耗时32秒左右，总耗时54秒左右。

ReflectionBeanMap 核心实现如下，initPropertyDescriptors 初始化属性描述符缓存，getValue时从缓存中获取PropertyDescriptor，反射调用 getter 方法。

publicclassReflectionBeanMap<T>implementsBeanMap<T>{privatefinalClass<T>beanClass;privatefinalMap<String,PropertyDescriptor>propertyDescriptors;privatefinalBeanMapConfigconfig;publicReflectionBeanMap(Class<T>beanClass){this(beanClass,BeanMapConfig.defaultConfig());}publicReflectionBeanMap(Class<T>beanClass,BeanMapConfigconfig){this.beanClass=beanClass;this.config=config;this.propertyDescriptors=initPropertyDescriptors(beanClass);}/** * 初始化属性描述符缓存 */privateMap<String,PropertyDescriptor>initPropertyDescriptors(Class<T>beanClass){try{BeanInfobeanInfo=Introspector.getBeanInfo(beanClass,Object.class);PropertyDescriptor[]descriptors=beanInfo.getPropertyDescriptors();Map<String,PropertyDescriptor>result=newLinkedHashMap<>();for(PropertyDescriptordescriptor:descriptors){// 过滤掉没有 getter 方法的属性if(descriptor.getReadMethod()!=null){result.put(descriptor.getName(),descriptor);}}returnCollections.unmodifiableMap(result);}catch(IntrospectionExceptione){thrownewRuntimeException("Failed to introspect bean: "+beanClass.getName(),e);}}/** * 获取属性值 - 核心反射调用 */@OverridepublicObjectgetValue(Tbean,StringpropertyName){if(bean==null){returnnull;}PropertyDescriptordescriptor=propertyDescriptors.get(propertyName);if(descriptor==null){if(config.isIgnoreMissingProperties()){returnnull;}thrownewIllegalArgumentException("Property '"+propertyName+"' not found in "+beanClass.getName());}MethodreadMethod=descriptor.getReadMethod();if(readMethod==null){if(config.isIgnoreMissingGetters()){returnnull;}thrownewIllegalArgumentException("No getter method for property '"+propertyName+"' in "+beanClass.getName());}try{// 反射调用 getter 方法returnreadMethod.invoke(bean);}catch(IllegalAccessException|InvocationTargetExceptione){thrownewRuntimeException("Failed to get value for property '"+propertyName+"' from "+beanClass.getName(),e);}}/** * 设置属性值 */@OverridepublicvoidsetValue(Tbean,StringpropertyName,Objectvalue){if(bean==null){return;}PropertyDescriptordescriptor=propertyDescriptors.get(propertyName);if(descriptor==null){if(config.isIgnoreMissingProperties()){return;}thrownewIllegalArgumentException("Property '"+propertyName+"' not found in "+beanClass.getName());}MethodwriteMethod=descriptor.getWriteMethod();if(writeMethod==null){if(config.isIgnoreMissingSetters()){return;}thrownewIllegalArgumentException("No setter method for property '"+propertyName+"' in "+beanClass.getName());}try{// 类型转换和反射调用 setter 方法ObjectconvertedValue=convertValue(value,descriptor.getPropertyType());writeMethod.invoke(bean,convertedValue);}catch(IllegalAccessException|InvocationTargetExceptione){thrownewRuntimeException("Failed to set value for property '"+propertyName+"' in "+beanClass.getName(),e);}}/** * 获取所有属性名 */@OverridepublicSet<String>getPropertyNames(){returnpropertyDescriptors.keySet();}/** * 获取属性类型 */@OverridepublicClass<?>getPropertyType(StringpropertyName){PropertyDescriptordescriptor=propertyDescriptors.get(propertyName);returndescriptor!=null?descriptor.getPropertyType():null;}/** * 值类型转换 */privateObjectconvertValue(Objectvalue,Class<?>targetType){if(value==null){returnnull;}// 如果类型匹配，直接返回if(targetType.isInstance(value)){returnvalue;}// 使用配置的转换器进行类型转换returnconfig.getTypeConverter().convert(value,targetType);}}

我写了一个便于理解的例子

publicclassTest{publicstaticvoidmain(String[]args)throwsException{List<BaseUser>list=newArrayList<>();//添加模拟数据for(inti=0;i<=10000000;i++){BaseUserbaseUser1=newBaseUser();baseUser1.setActiveFlag(i+"");list.add(baseUser1);}longstartTime=System.currentTimeMillis();/** * @description 原来的反射方式 */for(BaseUseritem:list){Classcl=item.getClass();FieldnameField=cl.getDeclaredField("activeFlag");nameField.setAccessible(true);nameField.get(item);}//打印耗时时间longendTime=System.currentTimeMillis();longexecutionTime=endTime-startTime;System.out.println("原来的反射方法执行时间："+(executionTime)+"毫秒");longstartTime1=System.currentTimeMillis();/** * @description 优化后的反射方式 */Classcl=BaseUser.class;Methodmethod=cl.getMethod("getActiveFlag");for(BaseUseritem:list){method.invoke(item);}//打印耗时时间longendTime1=System.currentTimeMillis();longexecutionTime1=endTime1-startTime1;System.out.println("修改后的反射方法执行时间："+(executionTime1)+"毫秒");}}

执行结果

原来的反射方法执行时间：1041毫秒 修改后的反射方法执行时间：170毫秒

四、总结

1、本地优化了sql和结果集中字段国际化逻辑，在本地导出速度得到很大的提高，但是发版到生产环境后，数据写入excel逻辑是耗时的主要原因，通过arthas实际的监控了每个方法的耗时情况，方便线上问题解决。
2、对于本地和线上的差异，我猜测是线上和本地jvm版本与启动参数不一样导致差异。