来源:juejin.cn/post/7259320326898876477 背景 Helios 系统要处理的数据量比较大,尤其是查询所有服务一天的评分数据时要返回每日 1440 分钟的所有应用的评分,总计有几十万个数据点,接口有时延迟会达到数秒。本文记录如何利用 Arthas ,将接口从几百几千 ms,优化到几十 ms。 从链路上看,线上获取一整天的数据时大概 300 多 ms,而查询数据库只有 11ms,说明大部分时间都是程序组装数据时消耗的,于是动起了优化代码的念头。 优化过程 代码业务可以不用去理解,最主要的是看利用trace优化的过程 初始未优化版本 代码private HeliosGetScoreResponse queryScores (HeliosGetScoreRequest request) { HeliosGetScoreResponse response = new HeliosGetScoreResponse(); List<HeliosScore> heliosScores = heliosService.queryScoresTimeBetween(request.getStartTime(), request.getEndTime(), request.getFilterByAppId()); if (CollectionUtils.isEmpty(heliosScores)) { return response; } Set<String> dateSet = new HashSet<>(); Map<String, List<HeliosScore>> groupByAppIdHeliosScores = heliosScores.stream().collect(Collectors.groupingBy(HeliosScore::getAppId)); for (List<HeliosScore> value : groupByAppIdHeliosScores.values()) { value.sort(Comparator.comparing(HeliosScore::getTimeFrom)); HeliosGetScoreResponse.Score score = new HeliosGetScoreResponse.Score(); score.setNamespace(value.get(0 ).getNamespace()); score.setAppId(value.get(0 ).getAppId()); for (HeliosScore heliosScore : value) { List<HeliosScore> splitHeliosScores = heliosScore.split(); for (HeliosScore splitHeliosScore : splitHeliosScores) { if (splitHeliosScore.getTimeFrom().compareTo(request.getStartTime()) < 0 ) { continue ; } if (splitHeliosScore.getTimeFrom().compareTo(request.getEndTime()) > 0 ) { break ; } dateSet.add(DateUtils.yyyyMMddHHmm.formatDate(splitHeliosScore.getTimeFrom())); if (splitHeliosScore.getScores() == null ) { splitHeliosScore.setScores("100" ); log.error("查询时发现数据缺失: {}" , heliosScore); } score.add(Math.max(0 , Integer.parseInt(splitHeliosScore.getScores())), null ); } } response.getValues().add(score); } response.setDates(new ArrayList<>(dateSet).stream().sorted().collect(Collectors.toList())); return response; } Arthas Trace`---ts=2021 -08 -17 16 :28 :00 ;thread_name=http-nio-8080 -exec-10 ;id=81 ;is_daemon=true ;priority=5 ;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@20864 cd1 `---[4046.398447 ms] xxxService.controller.HeliosController:queryScores() +---[0.022259 ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #147 +---[0.007132 ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #149 +---[0.006985 ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #149 +---[0.008704 ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #149 +---[19.284658 ms] xxxService.service.HeliosService:queryScoresTimeBetween() #149 +---[0.017468 ms] org.apache.commons.collections.CollectionUtils:isEmpty() #150 +---[0.008054 ms] java.util.HashSet:<init>() #154 +---[0.027591 ms] java.util.List:stream() #156 +---[0.044229 ms] java.util.stream.Collectors:groupingBy() #156 +---[0.155582 ms] java.util.stream.Stream:collect() #156 +---[0.018318 ms] java.util.Map:values() #157 +---[0.019199 ms] java.util.Collection:iterator() #157 +---[min=3.51E-4 ms,max=0.014266 ms,total=0.125003 ms,count=123 ] java.util.Iterator:hasNext() #157 +---[min=5.11E-4 ms,max=0.010188 ms,total=0.145693 ms,count=122 ] java.util.Iterator:next() #157 +---[min=4.89E-4 ms,max=0.045356 ms,total=0.321978 ms,count=122 ] java.util.Comparator:comparing() #158 +---[min=0.003637 ms,max=0.033049 ms,total=0.928795 ms,count=122 ] java.util.List:sort() #158 +---[min=5.94E-4 ms,max=0.010442 ms,total=0.1485 ms,count=122 ] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #159 +---[min=4.5E-4 ms,max=0.010857 ms,total=0.12773 ms,count=122 ] java.util.List:get() #160 +---[min=5.01E-4 ms,max=0.007849 ms,total=0.123696 ms,count=122 ] xxxService.helios.entity.HeliosScore:getNamespace() #160 +---[min=6.5E-4 ms,max=0.007324 ms,total=0.135906 ms,count=122 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #160 +---[min=3.72E-4 ms,max=0.010288 ms,total=0.086703 ms,count=122 ] java.util.List:get() #161 +---[min=5.1E-4 ms,max=0.00627 ms,total=0.103871 ms,count=122 ] xxxService.helios.entity.HeliosScore:getAppId() #161 +---[min=5.97E-4 ms,max=0.006531 ms,total=0.126184 ms,count=122 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #161 +---[min=4.45E-4 ms,max=0.020198 ms,total=0.138299 ms,count=122 ] java.util.List:iterator() #162 +---[min=3.42E-4 ms,max=0.014615 ms,total=0.256056 ms,count=366 ] java.util.Iterator:hasNext() #162 +---[min=3.59E-4 ms,max=0.014974 ms,total=0.174396 ms,count=244 ] java.util.Iterator:next() #162 +---[min=0.071035 ms,max=0.148132 ms,total=19.444179 ms,count=244 ] xxxService.helios.entity.HeliosScore:split() #163 +---[min=4.06E-4 ms,max=0.022364 ms,total=0.210152 ms,count=244 ] java.util.List:iterator() #164 +---[min=3.07E-4 ms,max=0.199649 ms,total=143.267893 ms,count=351604 ] java.util.Iterator:hasNext() #164 +---[min=3.25E-4 ms,max=24.863976 ms,total=177.15363 ms,count=351360 ] java.util.Iterator:next() #164 +---[min=3.93E-4 ms,max=0.096771 ms,total=176.843018 ms,count=351360 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #165 +---[min=4.07E-4 ms,max=18.772715 ms,total=205.632183 ms,count=351360 ] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #165 +---[min=3.33E-4 ms,max=0.045589 ms,total=149.24486 ms,count=351360 ] java.util.Date:compareTo() #165 +---[min=3.93E-4 ms,max=0.032972 ms,total=86.466793 ms,count=175680 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #168 +---[min=4.12E-4 ms,max=0.061003 ms,total=94.294061 ms,count=175680 ] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #168 +---[min=3.37E-4 ms,max=0.038792 ms,total=74.505056 ms,count=175680 ] java.util.Date:compareTo() #168 +---[min=3.97E-4 ms,max=0.036548 ms,total=87.693935 ms,count=175680 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #171 1 +---[min=0.001952 ms,max=0.068413 ms,total=391.739063 ms,count=175680 ] xxxService.utils.DateUtils$yyyyMMddHHmm:formatDate() #171 +---[min=4.07E-4 ms,max=0.037904 ms,total=108.107714 ms,count=175680 ] java.util.Set:add() #171 +---[min=3.95E-4 ms,max=0.031555 ms,total=88.173857 ms,count=175680 ] xxxService.helios.entity.HeliosScore:getScores() #172 +---[min=3.88E-4 ms,max=0.033584 ms,total=84.689466 ms,count=175680 ] xxxService.helios.entity.HeliosScore:getScores() #176 +---[min=3.11E-4 ms,max=0.038121 ms,total=69.708752 ms,count=175680 ] java.lang.Math:max() #176 +---[min=4.66E-4 ms,max=0.03391 ms,total=104.476576 ms,count=175680 ] xxxService.model.helios.HeliosGetScoreResponse$Score:add() #176 +---[min=6.17E-4 ms,max=0.01503 ms,total=0.159826 ms,count=122 ] xxxService.model.helios.HeliosGetScoreResponse:getValues() #179 +---[min=6.44E-4 ms,max=0.03742 ms,total=0.21068 ms,count=122 ] java.util.List:add() #179 +---[0.108961 ms] java.util.ArrayList:<init>() #182 +---[0.017455 ms] java.util.ArrayList:stream() #182 +---[0.011099 ms] java.util.stream.Stream:sorted() #182 +---[0.013699 ms] java.util.stream.Collectors:toList() #182 +---[0.38178 ms] java.util.stream.Stream:collect() #182 `---[0.004627 ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #182 分析Arthas 显示总共花了 4 秒,但实际上在链路上看大概是 350~450ms 左右。其他多出来的时间是 Arthas 每一次执行统计的消耗,因为方法里的循环比较多。这也告诉我们,不要用 trace 去看循环很多的方法。会对性能有非常严重的影响。 可以看出整个函数有 3 个循环,第一层循环的数量为 appId 的数量约为 140,第二层是查出来的数据条数,一天的数据已经归并了所以这里应该是 1,第三层是时间区间的分钟数,一天的话就是 1440 个。 Trace 中可以看到消耗最多的是封装的一个 SimpleDateFormat.formatDate()
。 第一次优化 优化方向遍历每个时间点的思路改变,把合并过的大对象拆分成一个个小对象直接遍历,改成先合并起来,通过时间点逻辑上遍历。这样会减少创建几十万个对象。 将时间点集合 Set<String> dateSet
改为 Set<Date>
,这样减少反复 formatDate() 的开销。 优化字符串转数字的过程,减少 Integer.parseInt
方法调用,改为用 Map<String, Integer>
提前创建出 0~100 的字符串数字字典。(后来经过 JMH 测试,还是 Integer.parseInt
最快) 代码private HeliosGetScoreResponse queryScores(HeliosGetScoreRequest request) { HeliosGetScoreResponse response = new HeliosGetScoreResponse();
List<HeliosScore> heliosScoresRecord = heliosService.queryScoresTimeBetween(request.getStartTime(), request.getEndTime(), request.getFilterByAppId());if (CollectionUtils.isEmpty(heliosScoresRecord)) { return response; } Set<Date> dateSet = new HashSet<>(); List<HeliosScore> heliosScores = HeliosDataMergeJob.mergeData(heliosScoresRecord); Map<String, List<HeliosScore>> groupByAppIdHeliosScores = heliosScores.stream().collect(Collectors.groupingBy(HeliosScore::getAppId));for (List<HeliosScore> scores : groupByAppIdHeliosScores.values()) { HeliosScore heliosScore = scores.get(0 ); HeliosGetScoreResponse.Score score = new HeliosGetScoreResponse.Score(); score.setNamespace(heliosScore.getNamespace()); score.setAppId(heliosScore.getAppId()); score.setScores(new ArrayList<>()); response.getValues().add(score); List<Integer> scoreIntList = HeliosHelper.splitScores(heliosScore); // 以 requestTime 为准 Calendar indexDate = DateUtils.roundDownMinute(request.getStartTime().getTime()); int index = 0 ; // 如果 timeFrom < requestTime,则增加 timeFrom 到 requestTime while (indexDate.getTime().compareTo(heliosScore.getTimeFrom()) > 0 ) { heliosScore.getTimeFrom().setTime(heliosScore.getTimeFrom().getTime() + 60_000 ); index++; } while (indexDate.getTime().compareTo(request.getEndTime()) <= 0 && indexDate.getTime().compareTo(heliosScore.getTimeTo()) <= 0 && index < scoreIntList.size()) { Integer scoreInt = scoreIntList.get(index++); score.getScores().add(scoreInt); dateSet.add(indexDate.getTime()); indexDate.add(Calendar.MINUTE, 1 ); } } response.setDates(new ArrayList<>(dateSet).stream().sorted().map(DateUtils.yyyyMMddHHmm::formatDate).collect(Collectors.toList())); return response; } Arthas Trace---ts=2021 -08 -17 14 :44 :11 ;thread_name=http-nio-8080 -exec-10 ;id=ab;is_daemon=true ;priority=5 ;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@16 ea0f22 `---[6997.005629 ms] xxxService.controller.HeliosController:queryScores() +---[0.020032 ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149 +---[0.007451 ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151 +---[min=0.001054 ms,max=7.458198 ms,total=213.19538 ms,count=170754 ] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57 +---[0.007267 ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57 +---[15.255919 ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57 +---[0.020045 ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152 +---[0.015161 ms] java.util.HashSet:<init>() #156 +---[20.06713 ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #158 +---[0.043042 ms] java.util.List:stream() #160 +---[0.028232 ms] java.util.stream.Collectors:groupingBy() #57 +---[min=0.087087 ms,max=1.931641 ms,total=2.018728 ms,count=2 ] java.util.stream.Stream:collect() #57 +---[0.0151 ms] java.util.Map:values() #162 +---[0.019611 ms] java.util.Collection:iterator() #57 +---[min=7.55E-4 ms,max=0.015165 ms,total=0.201221 ms,count=121 ] java.util.Iterator:hasNext() #57 +---[min=0.001178 ms,max=0.02477 ms,total=0.220931 ms,count=120 ] java.util.Iterator:next() #57 +---[min=8.14E-4 ms,max=0.01101 ms,total=0.155044 ms,count=120 ] java.util.List:get() #163 +---[min=0.001049 ms,max=0.009425 ms,total=0.231297 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #164 +---[min=0.001167 ms,max=0.009721 ms,total=0.194502 ms,count=120 ] xxxService.helios.entity.HeliosScore:getNamespace() #165 +---[min=0.001222 ms,max=0.020409 ms,total=0.264791 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57 +---[min=0.001097 ms,max=0.006475 ms,total=0.169987 ms,count=120 ] xxxService.helios.entity.HeliosScore:getAppId() #166 +---[min=0.00121 ms,max=0.007106 ms,total=0.207877 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57 +---[min=8.63E-4 ms,max=0.008981 ms,total=0.176195 ms,count=120 ] java.util.ArrayList:<init>() #167 +---[min=0.001225 ms,max=0.021948 ms,total=0.340375 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57 +---[min=0.00112 ms,max=0.008984 ms,total=0.196212 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse:getValues() #168 +---[min=7.64E-4 ms,max=0.027237 ms,total=154.660479 ms,count=170753 ] java.util.List:add() #57 +---[min=0.028779 ms,max=0.237608 ms,total=20.049731 ms,count=120 ] xxxService.helios.HeliosHelper:splitScores() #170 +---[min=0.001178 ms,max=0.008102 ms,total=0.199087 ms,count=120 ] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #173 +---[min=6.89E-4 ms,max=0.048069 ms,total=140.74298 ms,count=170040 ] java.util.Date:getTime() #57 +---[min=0.004686 ms,max=0.03805 ms,total=0.775394 ms,count=120 ] xxxService.utils.DateUtils:roundDownMinute() #57 +---[min=7.84E-4 ms,max=7.562581 ms,total=162.855553 ms,count=170040 ] java.util.Calendar:getTime() #176 2 +---[min=9.94E-4 ms,max=0.029962 ms,total=385.371864 ms,count=339960 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #57 1 +---[min=7.76E-4 ms,max=7.936578 ms,total=483.361269 ms,count=511428 ] java.util.Date:compareTo() #57 +---[min=9.95E-4 ms,max=0.077109 ms,total=192.749805 ms,count=169920 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #177 +---[min=6.94E-4 ms,max=7.358942 ms,total=151.184751 ms,count=169920 ] java.util.Date:setTime() #57 +---[min=7.67E-4 ms,max=0.029244 ms,total=152.500401 ms,count=170753 ] java.util.Calendar:getTime() #181 +---[min=7.65E-4 ms,max=0.016336 ms,total=151.879643 ms,count=170635 ] java.util.Calendar:getTime() #182 +---[min=0.001011 ms,max=0.028133 ms,total=196.192946 ms,count=170635 ] xxxService.helios.entity.HeliosScore:getTimeTo() #57 +---[min=6.93E-4 ms,max=0.836104 ms,total=141.443001 ms,count=170635 ] java.util.List:size() #57 +---[min=7.63E-4 ms,max=7.940119 ms,total=162.285955 ms,count=170633 ] java.util.List:get() #183 3 +---[min=0.001068 ms,max=0.973964 ms,total=209.721 ms,count=170633 ] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #184 +---[min=7.71E-4 ms,max=0.028856 ms,total=154.918574 ms,count=170633 ] java.util.Calendar:getTime() #185 +---[min=8.07E-4 ms,max=8.030316 ms,total=186.971072 ms,count=170633 ] java.util.Set:add() #57 +---[min=7.82E-4 ms,max=0.034732 ms,total=156.2645 ms,count=170633 ] java.util.Calendar:add() #186 +---[0.050615 ms] java.util.ArrayList:<init>() #190 +---[0.019114 ms] java.util.ArrayList:stream() #57 +---[0.029096 ms] java.util.stream.Stream:sorted() #57 +---[0.018823 ms] java.util.stream.Stream:map() #57 +---[0.009092 ms] java.util.stream.Collectors:toList() #57 `---[0.006768 ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57 分析从 Trace 中看耗时时间最长的是 Date 的 compareTo,也就是代码中的 if (splitHeliosScore.getTimeFrom().compareTo(request.getStartTime()) < 0)
而比较意外的是从对象中 get 属性居然也是有开销的。 第二次优化 优化方向结合上一次 Arthas Trace 的结果,在以下几个方向进行优化: 将 Date
对象的换成 long
型时间戳进行比较 将 Date
对象反复 getTime、setTime,改为 long
型时间戳 += 60_000
实现,得到结果后只 setTime 一次。 每次填充数据都往 Set<String> dateSet
放入数据,改为通过标识判断只放入一次。 存放分数的 ArrayList 在第一次循环之后,可以确认大小,之后循环创建 ArrayList 时直接填入固定的大小,减少内存创建。 代码private HeliosGetScoreResponse queryScores (HeliosGetScoreRequest request) { HeliosGetScoreResponse response = new HeliosGetScoreResponse(); List<HeliosScore> heliosScoresRecord = heliosService.queryScoresTimeBetween(request.getStartTime(), request.getEndTime(), request.getFilterByAppId()); if (CollectionUtils.isEmpty(heliosScoresRecord)) { return response; } Set<Date> dateSet = new HashSet<>(); boolean isDateSetInitial = false ; int scoreSize = 16 ; List<HeliosScore> heliosScores = HeliosDataMergeJob.mergeData(heliosScoresRecord); Map<String, List<HeliosScore>> groupByAppIdHeliosScores = heliosScores.stream().collect(Collectors.groupingBy(HeliosScore::getAppId)); for (List<HeliosScore> scores : groupByAppIdHeliosScores.values()) { HeliosScore heliosScore = scores.get(0 ); HeliosGetScoreResponse.Score score = new HeliosGetScoreResponse.Score(); score.setNamespace(heliosScore.getNamespace()); score.setAppId(heliosScore.getAppId()); score.setScores(new ArrayList<>(scoreSize)); response.getValues().add(score); List<Integer> scoreIntList = HeliosHelper.splitScores(heliosScore); // 以 requestTime 为准 long indexDateMills = request.getStartTime().getTime(); int index = 0 ; // 如果 timeFrom < requestTime,则增加 timeFrom 到 requestTime long heliosScoreTimeFromMills = heliosScore.getTimeFrom().getTime(); while (indexDateMills > heliosScoreTimeFromMills) { heliosScoreTimeFromMills += 60_000 ; index++; } heliosScore.getTimeFrom().setTime(heliosScoreTimeFromMills); long requestEndTimeMills = request.getEndTime().getTime(); long heliosScoreTimeToMills = heliosScore.getTimeTo().getTime(); // 循环条件为 (当前时间 <= 请求最大时间) && (当前时间 <= 数据最大时间) && (index < 数据条数) while (indexDateMills <= requestEndTimeMills && indexDateMills <= heliosScoreTimeToMills && index < scoreIntList.size()) { score.getScores().add(scoreIntList.get(index++)); if (!isDateSetInitial) { dateSet.add(new Date(indexDateMills)); } indexDateMills += 60_000 ; } // 性能优化,减少重复放入的次数 isDateSetInitial = true ; // 性能优化,初始化足够的 size 减少扩容次数。 x1.1 为了万一数据数量不一致,留出一点 buffer。 scoreSize = (int ) (score.getScores().size() * 1.1 ); } response.setDates(new ArrayList<>(dateSet).stream().sorted().map(DateUtils.yyyyMMddHHmm::formatDate).collect(Collectors.toList())); return response; } Arthas Trace`---ts=2021 -08 -17 15 :20 :41 ;thread_name=http-nio-8080 -exec-7 ;id=aa;is_daemon=true ;priority=5 ;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@14 be750c `---[1411.395123 ms] xxxService.controller.HeliosController:queryScores() +---[0.016102 ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149 +---[0.019084 ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151 +---[0.007879 ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57 +---[0.006808 ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57 +---[27.494178 ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57 +---[0.02087 ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152 +---[0.007694 ms] java.util.HashSet:<init>() #156 +---[19.990512 ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #160 +---[0.044161 ms] java.util.List:stream() #162 +---[0.025737 ms] java.util.stream.Collectors:groupingBy() #57 +---[min=0.079651 ms,max=2.007048 ms,total=2.086699 ms,count=2 ] java.util.stream.Stream:collect() #57 +---[0.018405 ms] java.util.Map:values() #164 +---[0.021408 ms] java.util.Collection:iterator() #57 +---[min=7.4E-4 ms,max=0.015625 ms,total=0.177657 ms,count=121 ] java.util.Iterator:hasNext() #57 +---[min=0.001193 ms,max=0.026712 ms,total=0.258491 ms,count=120 ] java.util.Iterator:next() #57 +---[min=7.69E-4 ms,max=0.011855 ms,total=0.158671 ms,count=120 ] java.util.List:get() #165 +---[min=0.001045 ms,max=0.019788 ms,total=0.232004 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #166 +---[min=0.001072 ms,max=0.007958 ms,total=0.193652 ms,count=120 ] xxxService.helios.entity.HeliosScore:getNamespace() #167 +---[min=0.001164 ms,max=0.007796 ms,total=0.201584 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57 +---[min=0.001048 ms,max=0.007456 ms,total=0.178323 ms,count=120 ] xxxService.helios.entity.HeliosScore:getAppId() #168 +---[min=0.001137 ms,max=0.010225 ms,total=0.201887 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57 +---[min=0.001627 ms,max=0.010431 ms,total=0.291395 ms,count=120 ] java.util.ArrayList:<init>() #169 +---[min=0.00116 ms,max=0.0088 ms,total=0.20171 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57 +---[min=0.001076 ms,max=0.010293 ms,total=0.199407 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse:getValues() #170 +---[min=7.54E-4 ms,max=0.086952 ms,total=150.86682 ms,count=170753 ] java.util.List:add() #57 +---[min=0.020428 ms,max=0.269554 ms,total=19.477128 ms,count=120 ] xxxService.helios.HeliosHelper:splitScores() #172 +---[min=0.001092 ms,max=0.005258 ms,total=0.202045 ms,count=120 ] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #175 +---[min=7.09E-4 ms,max=0.021027 ms,total=0.630747 ms,count=480 ] java.util.Date:getTime() #57 +---[min=0.00106 ms,max=0.015055 ms,total=0.188439 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #178 +---[min=0.001025 ms,max=0.009712 ms,total=0.171506 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #183 +---[min=7.4E-4 ms,max=0.092253 ms,total=0.251068 ms,count=120 ] java.util.Date:setTime() #57 +---[min=0.001086 ms,max=0.006234 ms,total=0.184256 ms,count=120 ] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #185 +---[min=0.001036 ms,max=0.012332 ms,total=0.176491 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeTo() #186 3 +---[min=6.73E-4 ms,max=0.066785 ms,total=135.009239 ms,count=170635 ] java.util.List:size() #188 1 +---[min=0.001085 ms,max=0.089243 ms,total=208.003309 ms,count=170633 ] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #189 2 +---[min=7.31E-4 ms,max=0.070823 ms,total=145.488732 ms,count=170633 ] java.util.List:get() #57 +---[min=0.001177 ms,max=0.143546 ms,total=2.319379 ms,count=1440 ] java.util.Date:<init>() #191 +---[min=0.001346 ms,max=0.064411 ms,total=2.839878 ms,count=1440 ] java.util.Set:add() #57 +---[min=0.001096 ms,max=0.009059 ms,total=0.190336 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #198 +---[min=6.92E-4 ms,max=0.016223 ms,total=0.141751 ms,count=120 ] java.util.List:size() #57 +---[0.069753 ms] java.util.ArrayList:<init>() #201 +---[0.021066 ms] java.util.ArrayList:stream() #57 +---[0.029498 ms] java.util.stream.Stream:sorted() #57 +---[0.014089 ms] java.util.stream.Stream:map() #57 +---[0.013053 ms] java.util.stream.Collectors:toList() #57 `---[0.009818 ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57 分析这一步将执行时间又优化了 80ms 左右。现在还剩是 160ms 了。 getScores
。直接 get 了属性啥也没干,但是积少成多也就是说虽然这几个函数里也没干什么东西,但是函数调用、指针寻址本身也是有开销的。 第三次优化 优化方向一次次 list.add 方法改成 subList 一次性放入 也就是说循环中不做任何耗时操作,不做任何指针/引用。 代码private HeliosGetScoreResponse queryScores(HeliosGetScoreRequest request) { HeliosGetScoreResponse response = new HeliosGetScoreResponse();
List<HeliosScore> heliosScoresRecord = heliosService.queryScoresTimeBetween(request.getStartTime(), request.getEndTime(), request.getFilterByAppId());if (CollectionUtils.isEmpty(heliosScoresRecord)) { return response; } Set<Date> dateSet = new HashSet<>();boolean isDateSetInitial = false ;int scoreSize = 16 ; List<HeliosScore> heliosScores = HeliosDataMergeJob.mergeData(heliosScoresRecord); Map<String, List<HeliosScore>> groupByAppIdHeliosScores = heliosScores.stream().collect(Collectors.groupingBy(HeliosScore::getAppId));for (List<HeliosScore> scores : groupByAppIdHeliosScores.values()) { HeliosScore heliosScore = scores.get(0 ); HeliosGetScoreResponse.Score score = new HeliosGetScoreResponse.Score(); score.setNamespace(heliosScore.getNamespace()); score.setAppId(heliosScore.getAppId()); score.setScores(new ArrayList<>(scoreSize)); response.getValues().add(score); List<Integer> scoreIntList = HeliosHelper.splitScores(heliosScore); // 以 requestTime 为准 long indexDateMills = request.getStartTime().getTime(); int index = 0 ; // 如果 timeFrom < requestTime,则增加 timeFrom 到 requestTime long heliosScoreTimeFromMills = heliosScore.getTimeFrom().getTime(); while (indexDateMills > heliosScoreTimeFromMills) { heliosScoreTimeFromMills += 60_000 ; index++; } heliosScore.getTimeFrom().setTime(heliosScoreTimeFromMills); long requestEndTimeMills = request.getEndTime().getTime(); long heliosScoreTimeToMills = heliosScore.getTimeTo().getTime(); // 循环条件为 (当前时间 <= 请求最大时间) && (当前时间 <= 数据最大时间) && (index < 数据条数) int scoreIntListSize = scoreIntList.size(); int indexStart = index; while (indexDateMills <= requestEndTimeMills && indexDateMills <= heliosScoreTimeToMills && index++ < scoreIntListSize) { if (!isDateSetInitial) { dateSet.add(new Date(indexDateMills)); } indexDateMills += 60_000 ; } score.getScores().addAll(scoreIntList.subList(indexStart, index - 1 )); // 性能优化,减少重复放入的次数 isDateSetInitial = true ; // 性能优化,初始化足够的 size 减少扩容次数。 x1.1 为了万一数据数量不一致,留出一点 buffer。 scoreSize = (int ) (score.getScores().size() * 1.1 ); } response.setDates(new ArrayList<>(dateSet).stream().sorted().map(DateUtils.yyyyMMddHHmm::formatDate).collect(Collectors.toList()));return response; } Arthas Trace`---ts=2021 -08 -17 15 :33 :40 ;thread_name=http-nio-8080 -exec-11 ;id=f1;is_daemon=true ;priority=5 ;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@d 1c5cf2 `---[138.624811 ms] xxxService.controller.HeliosController:queryScores() +---[0.021852 ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149 +---[0.00746 ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151 +---[0.005838 ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57 +---[0.006341 ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57 2 +---[15.227453 ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57 +---[0.02168 ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152 +---[0.008923 ms] java.util.HashSet:<init>() #156 1 +---[22.703926 ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #160 +---[0.047118 ms] java.util.List:stream() #162 +---[0.043183 ms] java.util.stream.Collectors:groupingBy() #57 +---[min=0.095654 ms,max=2.183288 ms,total=2.278942 ms,count=2 ] java.util.stream.Stream:collect() #57 +---[0.022906 ms] java.util.Map:values() #164 +---[0.025777 ms] java.util.Collection:iterator() #57 +---[min=9.28E-4 ms,max=0.017187 ms,total=0.261862 ms,count=121 ] java.util.Iterator:hasNext() #57 +---[min=9.88E-4 ms,max=0.018901 ms,total=0.280889 ms,count=120 ] java.util.Iterator:next() #57 +---[min=9.65E-4 ms,max=0.014741 ms,total=0.262695 ms,count=120 ] java.util.List:get() #165 +---[min=0.001215 ms,max=0.013928 ms,total=0.347762 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #166 +---[min=0.001253 ms,max=0.010855 ms,total=0.328842 ms,count=120 ] xxxService.helios.entity.HeliosScore:getNamespace() #167 +---[min=0.001316 ms,max=0.014714 ms,total=0.372553 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57 +---[min=0.001211 ms,max=0.010511 ms,total=0.322723 ms,count=120 ] xxxService.helios.entity.HeliosScore:getAppId() #168 +---[min=0.00132 ms,max=0.010201 ms,total=0.334627 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57 +---[min=0.00116 ms,max=0.014504 ms,total=0.386879 ms,count=120 ] java.util.ArrayList:<init>() #169 +---[min=0.00131 ms,max=0.014072 ms,total=0.344922 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57 +---[min=0.001261 ms,max=0.017312 ms,total=0.356444 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse:getValues() #170 +---[min=9.73E-4 ms,max=0.016531 ms,total=0.275794 ms,count=120 ] java.util.List:add() #57 3 +---[min=0.023208 ms,max=19.808819 ms,total=47.196601 ms,count=120 ] xxxService.helios.HeliosHelper:splitScores() #172 +---[min=0.001289 ms,max=0.009578 ms,total=0.36878 ms,count=120 ] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #175 +---[min=8.85E-4 ms,max=0.016405 ms,total=0.994157 ms,count=480 ] java.util.Date:getTime() #57 +---[min=0.001238 ms,max=0.016801 ms,total=0.34399 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #178 +---[min=0.001217 ms,max=0.008931 ms,total=0.316197 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #183 +---[min=9.14E-4 ms,max=0.015929 ms,total=0.277078 ms,count=120 ] java.util.Date:setTime() #57 +---[min=0.001238 ms,max=0.01061 ms,total=0.3375 ms,count=120 ] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #185 +---[min=0.001225 ms,max=0.018059 ms,total=0.315198 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeTo() #186 +---[min=8.79E-4 ms,max=0.022669 ms,total=0.272356 ms,count=120 ] java.util.List:size() #189 +---[min=0.002001 ms,max=0.056977 ms,total=4.32853 ms,count=1440 ] java.util.Date:<init>() #193 +---[min=0.002174 ms,max=0.040594 ms,total=4.594415 ms,count=1440 ] java.util.Set:add() #57 +---[min=0.001302 ms,max=0.012925 ms,total=0.353165 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #197 +---[min=0.001004 ms,max=0.033424 ms,total=0.338294 ms,count=120 ] java.util.List:subList() #57 +---[min=0.004871 ms,max=0.051046 ms,total=2.945263 ms,count=120 ] java.util.List:addAll() #57 +---[min=0.001291 ms,max=0.009831 ms,total=0.314292 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #201 +---[min=8.84E-4 ms,max=0.018168 ms,total=0.249321 ms,count=120 ] java.util.List:size() #57 +---[0.054305 ms] java.util.ArrayList:<init>() #204 +---[0.024481 ms] java.util.ArrayList:stream() #57 +---[0.028717 ms] java.util.stream.Stream:sorted() #57 +---[0.013725 ms] java.util.stream.Stream:map() #57 +---[0.0128 ms] java.util.stream.Collectors:toList() #57 `---[0.007166 ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57 分析这一步又优化了 100ms 左右,现在还剩 60ms。 拆分得分字符串 "100,100,100" 为 int 数组 [100,100,100] 第四次优化 优化方向查数据库发现由于 SQL 判断不准确,每次会多查出来一条数据,在后边循环的时候会多循环一倍 合并数据时发现可以针对单条数据的情况直接过滤,减少开销。 代码 Arthas Trace---ts=2021 -08 -17 16 :03 :24 ;thread_name=http-nio-8080 -exec-13 ;id=f1;is_daemon=true ;priority=5 ;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@69e2f e3b `---[38.171379 ms] xxxService.controller.HeliosController:queryScores() +---[0.009463 ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149 +---[0.00348 ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151 +---[0.003233 ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57 +---[0.003395 ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57 1 +---[10.157226 ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57 +---[0.009989 ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152 +---[0.003394 ms] java.util.HashSet:<init>() #156 +---[0.083535 ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #160 +---[0.017819 ms] java.util.List:stream() #162 +---[0.011787 ms] java.util.stream.Collectors:groupingBy() #57 +---[min=0.047561 ms,max=2.02786 ms,total=2.075421 ms,count=2 ] java.util.stream.Stream:collect() #57 +---[0.015525 ms] java.util.Map:values() #164 +---[0.021965 ms] java.util.Collection:iterator() #57 +---[min=7.25E-4 ms,max=0.009733 ms,total=0.115783 ms,count=121 ] java.util.Iterator:hasNext() #57 +---[min=8.43E-4 ms,max=0.011422 ms,total=0.142771 ms,count=120 ] java.util.Iterator:next() #57 +---[min=7.81E-4 ms,max=0.010883 ms,total=0.128809 ms,count=120 ] java.util.List:get() #165 +---[min=0.001023 ms,max=0.004301 ms,total=0.150165 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #166 +---[min=0.001066 ms,max=0.004648 ms,total=0.154698 ms,count=120 ] xxxService.helios.entity.HeliosScore:getNamespace() #167 +---[min=0.001137 ms,max=0.005607 ms,total=0.170279 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57 +---[min=0.001023 ms,max=0.004292 ms,total=0.151767 ms,count=120 ] xxxService.helios.entity.HeliosScore:getAppId() #168 +---[min=0.001105 ms,max=0.004701 ms,total=0.164955 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57 +---[min=0.001359 ms,max=0.007931 ms,total=0.233665 ms,count=120 ] java.util.ArrayList:<init>() #169 +---[min=0.001117 ms,max=0.00785 ms,total=0.168539 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57 +---[min=0.001073 ms,max=0.004488 ms,total=0.156654 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse:getValues() #170 +---[min=7.98E-4 ms,max=0.00977 ms,total=0.125818 ms,count=120 ] java.util.List:add() #57 +---[min=0.022304 ms,max=0.12093 ms,total=8.88628 ms,count=120 ] xxxService.helios.HeliosHelper:splitScores() #172 +---[min=0.001092 ms,max=0.004967 ms,total=0.161288 ms,count=120 ] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #175 +---[min=7.02E-4 ms,max=0.012136 ms,total=0.467786 ms,count=480 ] java.util.Date:getTime() #57 +---[min=0.001022 ms,max=0.004944 ms,total=0.151353 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #178 +---[min=0.001018 ms,max=0.004731 ms,total=0.148025 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeFrom() #183 +---[min=7.3E-4 ms,max=0.009359 ms,total=0.120588 ms,count=120 ] java.util.Date:setTime() #57 +---[min=0.00107 ms,max=0.008948 ms,total=0.162848 ms,count=120 ] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #185 +---[min=0.001034 ms,max=0.014003 ms,total=0.158614 ms,count=120 ] xxxService.helios.entity.HeliosScore:getTimeTo() #186 +---[min=6.99E-4 ms,max=0.009995 ms,total=0.11179 ms,count=120 ] java.util.List:size() #189 +---[min=6.95E-4 ms,max=0.005468 ms,total=1.116308 ms,count=1440 ] java.util.Date:<init>() #193 +---[min=7.79E-4 ms,max=0.029909 ms,total=1.407528 ms,count=1440 ] java.util.Set:add() #57 +---[min=0.001097 ms,max=0.008616 ms,total=0.160597 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #197 +---[min=8.23E-4 ms,max=0.0294 ms,total=0.153353 ms,count=120 ] java.util.List:subList() #57 +---[min=0.005771 ms,max=0.04465 ms,total=1.992151 ms,count=120 ] java.util.List:addAll() #57 +---[min=0.001098 ms,max=0.007013 ms,total=0.169555 ms,count=120 ] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #201 +---[min=7.04E-4 ms,max=0.01315 ms,total=0.120998 ms,count=120 ] java.util.List:size() #57 +---[0.197732 ms] java.util.ArrayList:<init>() #204 +---[0.018589 ms] java.util.ArrayList:stream() #57 +---[0.025192 ms] java.util.stream.Stream:sorted() #57 +---[0.012544 ms] java.util.stream.Stream:map() #57 +---[0.012188 ms] java.util.stream.Collectors:toList() #57 `---[0.0067 ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57 分析可以看到现在最大耗时的地方终于是数据库查询了。现在查询一整天的数据,也只需要 25~40ms 左右。 结果 链路上看程序代码还是要处理个十几 ms,主要是字符串转 int[] 时的开销,这一步可以再想办法继续优化。 结论 哪怕最简单的操作如 list.size()
list.add
次数多了开销也很可观 对于性能分析和优化一定要有合适工具,才能得出有用的结论并针对性优化。一开始我以为减少对象创建就万事大吉,但实际上性能消耗的大头并不在这里。还是得借助 Arthas 的 Trace 才能真正针对性地优化