background

The Helios system has to deal with a large amount of data, especially when querying the rating data of all services for a day, it has to return the ratings of all apps for 1440 minutes a day, totaling hundreds of thousands of data points, and the interface delay sometimes reaches several seconds. This article documents how Arthas was used to optimize interfaces from hundreds of thousands of ms to tens of ms.

Link:

From the link, it takes more than 300 ms to obtain the data online for a whole day, but only 11ms to query the database, indicating that most of the time is consumed when the program assembs the data, so the idea of optimizing the code is started.

The optimization process

Tip: you don’t have to look at the code. It’s hard to understand what a function means without context. Arthas Trace results and optimization ideas.

Initial unoptimized version

code

    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("Missing data found during query: {}", 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;
    }
Copy the code

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@20864cd1 `---[4046.398447ms] xxxService.controller.HeliosController:queryScores()
        +---[0.022259ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #147+ -- -- -0.007132ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #149+ -- -- -0.006985ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #149+ -- -- -0.008704ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #149+ -- -- -19.284658ms] xxxService.service.HeliosService:queryScoresTimeBetween() #149+ -- -- -0.017468ms] org.apache.commons.collections.CollectionUtils:isEmpty() #150+ -- -- -0.008054ms] java.util.HashSet:<init>() #154+ -- -- -0.027591ms] java.util.List:stream() #156+ -- -- -0.044229ms] java.util.stream.Collectors:groupingBy() #156+ -- -- -0.155582ms] java.util.stream.Stream:collect() #156+ -- -- -0.018318ms] java.util.Map:values() #157+ -- -- -0.019199ms] java.util.Collection:iterator() #157
        +---[min=3.51E-4ms,max=0.014266ms,total=0.125003ms,count=123] java.util.Iterator:hasNext() #157
        +---[min=5.11E-4ms,max=0.010188ms,total=0.145693ms,count=122] java.util.Iterator:next() #157
        +---[min=4.89E-4ms,max=0.045356ms,total=0.321978ms,count=122] java.util.Comparator:comparing() #158
        +---[min=0.003637ms,max=0.033049ms,total=0.928795ms,count=122] java.util.List:sort() #158
        +---[min=5.94E-4ms,max=0.010442ms,total=0.1485ms,count=122] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #159
        +---[min=4.5E-4ms,max=0.010857ms,total=0.12773ms,count=122] java.util.List:get() #160
        +---[min=5.01E-4ms,max=0.007849ms,total=0.123696ms,count=122] xxxService.helios.entity.HeliosScore:getNamespace() #160
        +---[min=6.5E-4ms,max=0.007324ms,total=0.135906ms,count=122] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #160
        +---[min=3.72E-4ms,max=0.010288ms,total=0.086703ms,count=122] java.util.List:get() #161
        +---[min=5.1E-4ms,max=0.00627ms,total=0.103871ms,count=122] xxxService.helios.entity.HeliosScore:getAppId() #161
        +---[min=5.97E-4ms,max=0.006531ms,total=0.126184ms,count=122] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #161
        +---[min=4.45E-4ms,max=0.020198ms,total=0.138299ms,count=122] java.util.List:iterator() #162
        +---[min=3.42E-4ms,max=0.014615ms,total=0.256056ms,count=366] java.util.Iterator:hasNext() #162
        +---[min=3.59E-4ms,max=0.014974ms,total=0.174396ms,count=244] java.util.Iterator:next() #162
        +---[min=0.071035ms,max=0.148132ms,total=19.444179ms,count=244] xxxService.helios.entity.HeliosScore:split() #163
        +---[min=4.06E-4ms,max=0.022364ms,total=0.210152ms,count=244] java.util.List:iterator() #164
        +---[min=3.07E-4ms,max=0.199649ms,total=143.267893ms,count=351604] java.util.Iterator:hasNext() #164
        +---[min=3.25E-4ms,max=24.863976ms,total=177.15363ms,count=351360] java.util.Iterator:next() #164
        +---[min=3.93E-4ms,max=0.096771ms,total=176.843018ms,count=351360] xxxService.helios.entity.HeliosScore:getTimeFrom() #165
        +---[min=4.07E-4ms,max=18.772715ms,total=205.632183ms,count=351360] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #165
        +---[min=3.33E-4ms,max=0.045589ms,total=149.24486ms,count=351360] java.util.Date:compareTo() #165
        +---[min=3.93E-4ms,max=0.032972ms,total=86.466793ms,count=175680] xxxService.helios.entity.HeliosScore:getTimeFrom() #168
        +---[min=4.12E-4ms,max=0.061003ms,total=94.294061ms,count=175680] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #168
        +---[min=3.37E-4ms,max=0.038792ms,total=74.505056ms,count=175680] java.util.Date:compareTo() #168
        +---[min=3.97E-4ms,max=0.036548ms,total=87.693935ms,count=175680] xxxService.helios.entity.HeliosScore:getTimeFrom() #171
     1  +---[min=0.001952ms,max=0.068413ms,total=391.739063ms,count=175680] xxxService.utils.DateUtils$yyyyMMddHHmm:formatDate() #171
        +---[min=4.07E-4ms,max=0.037904ms,total=108.107714ms,count=175680] java.util.Set:add() #171
        +---[min=3.95E-4ms,max=0.031555ms,total=88.173857ms,count=175680] xxxService.helios.entity.HeliosScore:getScores() #172
        +---[min=3.88E-4ms,max=0.033584ms,total=84.689466ms,count=175680] xxxService.helios.entity.HeliosScore:getScores() #176
        +---[min=3.11E-4ms,max=0.038121ms,total=69.708752ms,count=175680] java.lang.Math:max() #176
        +---[min=4.66E-4ms,max=0.03391ms,total=104.476576ms,count=175680] xxxService.model.helios.HeliosGetScoreResponse$Score:add() #176
        +---[min=6.17E-4ms,max=0.01503ms,total=0.159826ms,count=122] xxxService.model.helios.HeliosGetScoreResponse:getValues() #179
        +---[min=6.44E-4ms,max=0.03742ms,total=0.21068ms,count=122] java.util.List:add() #179+ -- -- -0.108961ms] java.util.ArrayList:<init>() #182+ -- -- -0.017455ms] java.util.ArrayList:stream() #182+ -- -- -0.011099ms] java.util.stream.Stream:sorted() #182+ -- -- -0.013699ms] java.util.stream.Collectors:toList() #182+ -- -- -0.38178ms] java.util.stream.Stream:collect() #182
        `---[0.004627ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #182
Copy the code

Analysis of the

Arthas says it took a total of 4 seconds, but it’s actually about 350~450ms on the link. The additional time is the cost of each Arthas statistics run because of the number of loops in the method. This also tells us not to trace a lot of methods through loops. Can have a serious impact on performance.

It can be seen that the whole function has 3 cycles. The number of cycles in the first layer is about 140 appids. The second layer is the number of detected data items, the data of a day has been merged, so this should be 1.

Trace can see consumed most is encapsulated in a SimpleDateFormat formatDate ().

First optimization

To optimize the direction

1. The idea of traversing each time point is changed. The merged large objects are divided into small objects and traversed directly. Instead, the merged objects are merged first and traversed logically through time points. This reduces the number of objects created by hundreds of thousands.

2. Change the point in time Set
   
   dateSet to Set
   
   to reduce the overhead of repeatedly formatDate().
   
   

3. Optimize String to number conversion process, reduce integer. parseInt method call, use Map
   
   to create String number dictionary 0 to 100 in advance. (Later tested by JMH, integer.parseint is the fastest)
   ,>

code

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);

            // Use requestTime
            Calendar indexDate = DateUtils.roundDownMinute(request.getStartTime().getTime());
            int index = 0;
            // If timeFrom < requestTime, add timeFrom to 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;
    }
Copy the code

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@16ea0f22 `---[6997.005629ms] xxxService.controller.HeliosController:queryScores()
        +---[0.020032ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149+ -- -- -0.007451ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151
        +---[min=0.001054ms,max=7.458198ms,total=213.19538ms,count=170754] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57+ -- -- -0.007267ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57+ -- -- -15.255919ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57+ -- -- -0.020045ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152+ -- -- -0.015161ms] java.util.HashSet:<init>() #156+ -- -- -20.06713ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #158+ -- -- -0.043042ms] java.util.List:stream() #160+ -- -- -0.028232ms] java.util.stream.Collectors:groupingBy() #57
        +---[min=0.087087ms,max=1.931641ms,total=2.018728ms,count=2] java.util.stream.Stream:collect() #57+ -- -- -0.0151ms] java.util.Map:values() #162+ -- -- -0.019611ms] java.util.Collection:iterator() #57
        +---[min=7.55E-4ms,max=0.015165ms,total=0.201221ms,count=121] java.util.Iterator:hasNext() #57
        +---[min=0.001178ms,max=0.02477ms,total=0.220931ms,count=120] java.util.Iterator:next() #57
        +---[min=8.14E-4ms,max=0.01101ms,total=0.155044ms,count=120] java.util.List:get() #163
        +---[min=0.001049ms,max=0.009425ms,total=0.231297ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #164
        +---[min=0.001167ms,max=0.009721ms,total=0.194502ms,count=120] xxxService.helios.entity.HeliosScore:getNamespace() #165
        +---[min=0.001222ms,max=0.020409ms,total=0.264791ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57
        +---[min=0.001097ms,max=0.006475ms,total=0.169987ms,count=120] xxxService.helios.entity.HeliosScore:getAppId() #166
        +---[min=0.00121ms,max=0.007106ms,total=0.207877ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57
        +---[min=8.63E-4ms,max=0.008981ms,total=0.176195ms,count=120] java.util.ArrayList:<init>() #167
        +---[min=0.001225ms,max=0.021948ms,total=0.340375ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57
        +---[min=0.00112ms,max=0.008984ms,total=0.196212ms,count=120] xxxService.model.helios.HeliosGetScoreResponse:getValues() #168
        +---[min=7.64E-4ms,max=0.027237ms,total=154.660479ms,count=170753] java.util.List:add() #57
        +---[min=0.028779ms,max=0.237608ms,total=20.049731ms,count=120] xxxService.helios.HeliosHelper:splitScores() #170
        +---[min=0.001178ms,max=0.008102ms,total=0.199087ms,count=120] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #173
        +---[min=6.89E-4ms,max=0.048069ms,total=140.74298ms,count=170040] java.util.Date:getTime() #57
        +---[min=0.004686ms,max=0.03805ms,total=0.775394ms,count=120] xxxService.utils.DateUtils:roundDownMinute() #57
        +---[min=7.84E-4ms,max=7.562581ms,total=162.855553ms,count=170040] java.util.Calendar:getTime() #176
      2 +---[min=9.94E-4ms,max=0.029962ms,total=385.371864ms,count=339960] xxxService.helios.entity.HeliosScore:getTimeFrom() #57
      1 +---[min=7.76E-4ms,max=7.936578ms,total=483.361269ms,count=511428] java.util.Date:compareTo() #57
        +---[min=9.95E-4ms,max=0.077109ms,total=192.749805ms,count=169920] xxxService.helios.entity.HeliosScore:getTimeFrom() #177
        +---[min=6.94E-4ms,max=7.358942ms,total=151.184751ms,count=169920] java.util.Date:setTime() #57
        +---[min=7.67E-4ms,max=0.029244ms,total=152.500401ms,count=170753] java.util.Calendar:getTime() #181
        +---[min=7.65E-4ms,max=0.016336ms,total=151.879643ms,count=170635] java.util.Calendar:getTime() #182
        +---[min=0.001011ms,max=0.028133ms,total=196.192946ms,count=170635] xxxService.helios.entity.HeliosScore:getTimeTo() #57
        +---[min=6.93E-4ms,max=0.836104ms,total=141.443001ms,count=170635] java.util.List:size() #57
        +---[min=7.63E-4ms,max=7.940119ms,total=162.285955ms,count=170633] java.util.List:get() #183
      3 +---[min=0.001068ms,max=0.973964ms,total=209.721ms,count=170633] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #184
        +---[min=7.71E-4ms,max=0.028856ms,total=154.918574ms,count=170633] java.util.Calendar:getTime() #185
        +---[min=8.07E-4ms,max=8.030316ms,total=186.971072ms,count=170633] java.util.Set:add() #57
        +---[min=7.82E-4ms,max=0.034732ms,total=156.2645ms,count=170633] java.util.Calendar:add() #186+ -- -- -0.050615ms] java.util.ArrayList:<init>() #190+ -- -- -0.019114ms] java.util.ArrayList:stream() #57+ -- -- -0.029096ms] java.util.stream.Stream:sorted() #57+ -- -- -0.018823ms] java.util.stream.Stream:map() #57+ -- -- -0.009092ms] java.util.stream.Collectors:toList() #57
        `---[0.006768ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57
Copy the code

Analysis of the

This step actually optimizes the execution time by about 50ms.

Takes the longest ever seen from the Trace is the compareTo Date, namely in the code the if (splitHeliosScore. GetTimeFrom () compareTo (request) getStartTime ()) < 0)

Surprisingly, the get attribute from an object is also expensive.

Second optimization

To optimize the direction

Combined with the results of the last Arthas Trace, optimizations were made in the following directions:

1. willDateObject substitutionlongType timestamp for comparison
2. willDateObject repeatedly getTime, setTime, changed tolongType the timestamp+ = 60 _000Implementation, only setTime once after the result is obtained.
3. Every time you fill in the data, you goSet<String> dateSetPut data in instead of putting it in once by identifying it.
4. The ArrayList that holds the score can be checked for size after the first loop, and then the loop creates the ArrayList by directly filling in the fixed size, reducing memory creation.

code

    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);

            // Use requestTime
            long indexDateMills = request.getStartTime().getTime();
            int index = 0;
            // If timeFrom < requestTime, add timeFrom to 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();
            // The loop condition is (current time <= maximum request time) && (current time <= maximum data time) && (index < number of data items)
            while (indexDateMills <= requestEndTimeMills && indexDateMills <= heliosScoreTimeToMills && index < scoreIntList.size()) {
                score.getScores().add(scoreIntList.get(index++));
                if(! isDateSetInitial) { dateSet.add(new Date(indexDateMills));
                }
                indexDateMills += 60 _000;
            }
            // Performance optimization, reduce the number of repeated insert
            isDateSetInitial = true;
            // Performance optimization, initialize enough size to reduce capacity expansion times. X1.1 In case the number of data is inconsistent, leave a bit of buffer.
            scoreSize = (int) (score.getScores().size() * 1.1);
        }

        response.setDates(new ArrayList<>(dateSet).stream().sorted().map(DateUtils.yyyyMMddHHmm::formatDate).collect(Collectors.toList()));
        return response;
    }
Copy the code

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@14be750c `---[1411.395123ms] xxxService.controller.HeliosController:queryScores()
        +---[0.016102ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149+ -- -- -0.019084ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151+ -- -- -0.007879ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57+ -- -- -0.006808ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57+ -- -- -27.494178ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57+ -- -- -0.02087ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152+ -- -- -0.007694ms] java.util.HashSet:<init>() #156+ -- -- -19.990512ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #160+ -- -- -0.044161ms] java.util.List:stream() #162+ -- -- -0.025737ms] java.util.stream.Collectors:groupingBy() #57
        +---[min=0.079651ms,max=2.007048ms,total=2.086699ms,count=2] java.util.stream.Stream:collect() #57+ -- -- -0.018405ms] java.util.Map:values() #164+ -- -- -0.021408ms] java.util.Collection:iterator() #57
        +---[min=7.4E-4ms,max=0.015625ms,total=0.177657ms,count=121] java.util.Iterator:hasNext() #57
        +---[min=0.001193ms,max=0.026712ms,total=0.258491ms,count=120] java.util.Iterator:next() #57
        +---[min=7.69E-4ms,max=0.011855ms,total=0.158671ms,count=120] java.util.List:get() #165
        +---[min=0.001045ms,max=0.019788ms,total=0.232004ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #166
        +---[min=0.001072ms,max=0.007958ms,total=0.193652ms,count=120] xxxService.helios.entity.HeliosScore:getNamespace() #167
        +---[min=0.001164ms,max=0.007796ms,total=0.201584ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57
        +---[min=0.001048ms,max=0.007456ms,total=0.178323ms,count=120] xxxService.helios.entity.HeliosScore:getAppId() #168
        +---[min=0.001137ms,max=0.010225ms,total=0.201887ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57
        +---[min=0.001627ms,max=0.010431ms,total=0.291395ms,count=120] java.util.ArrayList:<init>() #169
        +---[min=0.00116ms,max=0.0088ms,total=0.20171ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57
        +---[min=0.001076ms,max=0.010293ms,total=0.199407ms,count=120] xxxService.model.helios.HeliosGetScoreResponse:getValues() #170
        +---[min=7.54E-4ms,max=0.086952ms,total=150.86682ms,count=170753] java.util.List:add() #57
        +---[min=0.020428ms,max=0.269554ms,total=19.477128ms,count=120] xxxService.helios.HeliosHelper:splitScores() #172
        +---[min=0.001092ms,max=0.005258ms,total=0.202045ms,count=120] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #175
        +---[min=7.09E-4ms,max=0.021027ms,total=0.630747ms,count=480] java.util.Date:getTime() #57
        +---[min=0.00106ms,max=0.015055ms,total=0.188439ms,count=120] xxxService.helios.entity.HeliosScore:getTimeFrom() #178
        +---[min=0.001025ms,max=0.009712ms,total=0.171506ms,count=120] xxxService.helios.entity.HeliosScore:getTimeFrom() #183
        +---[min=7.4E-4ms,max=0.092253ms,total=0.251068ms,count=120] java.util.Date:setTime() #57
        +---[min=0.001086ms,max=0.006234ms,total=0.184256ms,count=120] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #185
        +---[min=0.001036ms,max=0.012332ms,total=0.176491ms,count=120] xxxService.helios.entity.HeliosScore:getTimeTo() #186
      3 +---[min=6.73E-4ms,max=0.066785ms,total=135.009239ms,count=170635] java.util.List:size() #188
      1 +---[min=0.001085ms,max=0.089243ms,total=208.003309ms,count=170633] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #189
      2 +---[min=7.31E-4ms,max=0.070823ms,total=145.488732ms,count=170633] java.util.List:get() #57
        +---[min=0.001177ms,max=0.143546ms,total=2.319379ms,count=1440] java.util.Date:<init>() #191
        +---[min=0.001346ms,max=0.064411ms,total=2.839878ms,count=1440] java.util.Set:add() #57
        +---[min=0.001096ms,max=0.009059ms,total=0.190336ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #198
        +---[min=6.92E-4ms,max=0.016223ms,total=0.141751ms,count=120] java.util.List:size() #57+ -- -- -0.069753ms] java.util.ArrayList:<init>() #201+ -- -- -0.021066ms] java.util.ArrayList:stream() #57+ -- -- -0.029498ms] java.util.stream.Stream:sorted() #57+ -- -- -0.014089ms] java.util.stream.Stream:map() #57+ -- -- -0.013053ms] java.util.stream.Collectors:toList() #57
        `---[0.009818ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57
Copy the code

Analysis of the

This step optimizes the execution time by another 80ms or so. And now I have 160 milliseconds left.

The three methods that take the longest time to Trace are:

• getScores. I just get the property and it doesn’t do anything, but it adds up
• list.size()
• list.get(index)

That is, although there is nothing going on in these functions, function calls and pointer addressing are themselves expensive.

Third optimization

To optimize the direction

1. Reduce calls to the list attribute
2. Change the list.add method to subList for once

That is, no time-consuming operations are done, no Pointers/references are made.

code

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);

            // Use requestTime
            long indexDateMills = request.getStartTime().getTime();
            int index = 0;
            // If timeFrom < requestTime, add timeFrom to 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();

            // The loop condition is (current time <= maximum request time) && (current time <= maximum data time) && (index < number of data items)
            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));
            // Performance optimization, reduce the number of repeated insert
            isDateSetInitial = true;
            // Performance optimization, initialize enough size to reduce capacity expansion times. X1.1 In case the number of data is inconsistent, leave a bit of buffer.
            scoreSize = (int) (score.getScores().size() * 1.1);
        }

        response.setDates(new ArrayList<>(dateSet).stream().sorted().map(DateUtils.yyyyMMddHHmm::formatDate).collect(Collectors.toList()));
        return response;
    }
Copy the code

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@d1c5cf2
    `---[138.624811ms] xxxService.controller.HeliosController:queryScores()
        +---[0.021852ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149+ -- -- -0.00746ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151+ -- -- -0.005838ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57+ -- -- -0.006341ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57
    2+ -- -- -15.227453ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57+ -- -- -0.02168ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152+ -- -- -0.008923ms] java.util.HashSet:<init>() #156
    1+ -- -- -22.703926ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #160+ -- -- -0.047118ms] java.util.List:stream() #162+ -- -- -0.043183ms] java.util.stream.Collectors:groupingBy() #57
        +---[min=0.095654ms,max=2.183288ms,total=2.278942ms,count=2] java.util.stream.Stream:collect() #57+ -- -- -0.022906ms] java.util.Map:values() #164+ -- -- -0.025777ms] java.util.Collection:iterator() #57
        +---[min=9.28E-4ms,max=0.017187ms,total=0.261862ms,count=121] java.util.Iterator:hasNext() #57
        +---[min=9.88E-4ms,max=0.018901ms,total=0.280889ms,count=120] java.util.Iterator:next() #57
        +---[min=9.65E-4ms,max=0.014741ms,total=0.262695ms,count=120] java.util.List:get() #165
        +---[min=0.001215ms,max=0.013928ms,total=0.347762ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #166
        +---[min=0.001253ms,max=0.010855ms,total=0.328842ms,count=120] xxxService.helios.entity.HeliosScore:getNamespace() #167
        +---[min=0.001316ms,max=0.014714ms,total=0.372553ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57
        +---[min=0.001211ms,max=0.010511ms,total=0.322723ms,count=120] xxxService.helios.entity.HeliosScore:getAppId() #168
        +---[min=0.00132ms,max=0.010201ms,total=0.334627ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57
        +---[min=0.00116ms,max=0.014504ms,total=0.386879ms,count=120] java.util.ArrayList:<init>() #169
        +---[min=0.00131ms,max=0.014072ms,total=0.344922ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57
        +---[min=0.001261ms,max=0.017312ms,total=0.356444ms,count=120] xxxService.model.helios.HeliosGetScoreResponse:getValues() #170
        +---[min=9.73E-4ms,max=0.016531ms,total=0.275794ms,count=120] java.util.List:add() #57
     3  +---[min=0.023208ms,max=19.808819ms,total=47.196601ms,count=120] xxxService.helios.HeliosHelper:splitScores() #172
        +---[min=0.001289ms,max=0.009578ms,total=0.36878ms,count=120] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #175
        +---[min=8.85E-4ms,max=0.016405ms,total=0.994157ms,count=480] java.util.Date:getTime() #57
        +---[min=0.001238ms,max=0.016801ms,total=0.34399ms,count=120] xxxService.helios.entity.HeliosScore:getTimeFrom() #178
        +---[min=0.001217ms,max=0.008931ms,total=0.316197ms,count=120] xxxService.helios.entity.HeliosScore:getTimeFrom() #183
        +---[min=9.14E-4ms,max=0.015929ms,total=0.277078ms,count=120] java.util.Date:setTime() #57
        +---[min=0.001238ms,max=0.01061ms,total=0.3375ms,count=120] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #185
        +---[min=0.001225ms,max=0.018059ms,total=0.315198ms,count=120] xxxService.helios.entity.HeliosScore:getTimeTo() #186
        +---[min=8.79E-4ms,max=0.022669ms,total=0.272356ms,count=120] java.util.List:size() #189
        +---[min=0.002001ms,max=0.056977ms,total=4.32853ms,count=1440] java.util.Date:<init>() #193
        +---[min=0.002174ms,max=0.040594ms,total=4.594415ms,count=1440] java.util.Set:add() #57
        +---[min=0.001302ms,max=0.012925ms,total=0.353165ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #197
        +---[min=0.001004ms,max=0.033424ms,total=0.338294ms,count=120] java.util.List:subList() #57
        +---[min=0.004871ms,max=0.051046ms,total=2.945263ms,count=120] java.util.List:addAll() #57
        +---[min=0.001291ms,max=0.009831ms,total=0.314292ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #201
        +---[min=8.84E-4ms,max=0.018168ms,total=0.249321ms,count=120] java.util.List:size() #57+ -- -- -0.054305ms] java.util.ArrayList:<init>() #204+ -- -- -0.024481ms] java.util.ArrayList:stream() #57+ -- -- -0.028717ms] java.util.stream.Stream:sorted() #57+ -- -- -0.013725ms] java.util.stream.Stream:map() #57+ -- -- -0.0128ms] java.util.stream.Collectors:toList() #57
        `---[0.007166ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57
Copy the code

Analysis of the

This step optimized for another 100ms or so, and now has 60ms left.

There are now only three time-consuming operations on trace:

• Check the database
• Merge data
• Split score string “100,100,100” into int array [100,100,100]

Fourth optimization

To optimize the direction

1. Check the database found that because the SQL judgment is not accurate, each time will find out a data, in the back of the cycle will be more than twice
2. When merging data, you can directly filter a single piece of data to reduce overhead.

code

1. Changed SQL and validation, reduce the amount of data out of the query
2. Merge logic is no longer processed for single data

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@69e2fe3b `---[38.171379ms] xxxService.controller.HeliosController:queryScores()
        +---[0.009463ms] xxxService.model.helios.HeliosGetScoreResponse:<init>() #149+ -- -- -0.00348ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #151+ -- -- -0.003233ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #57+ -- -- -0.003395ms] xxxService.model.helios.HeliosGetScoreRequest:getFilterByAppId() #57
     1+ -- -- -10.157226ms] xxxService.service.HeliosService:queryScoresTimeBetween() #57+ -- -- -0.009989ms] org.apache.commons.collections.CollectionUtils:isEmpty() #152+ -- -- -0.003394ms] java.util.HashSet:<init>() #156+ -- -- -0.083535ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData() #160+ -- -- -0.017819ms] java.util.List:stream() #162+ -- -- -0.011787ms] java.util.stream.Collectors:groupingBy() #57
        +---[min=0.047561ms,max=2.02786ms,total=2.075421ms,count=2] java.util.stream.Stream:collect() #57+ -- -- -0.015525ms] java.util.Map:values() #164+ -- -- -0.021965ms] java.util.Collection:iterator() #57
        +---[min=7.25E-4ms,max=0.009733ms,total=0.115783ms,count=121] java.util.Iterator:hasNext() #57
        +---[min=8.43E-4ms,max=0.011422ms,total=0.142771ms,count=120] java.util.Iterator:next() #57
        +---[min=7.81E-4ms,max=0.010883ms,total=0.128809ms,count=120] java.util.List:get() #165
        +---[min=0.001023ms,max=0.004301ms,total=0.150165ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:<init>() #166
        +---[min=0.001066ms,max=0.004648ms,total=0.154698ms,count=120] xxxService.helios.entity.HeliosScore:getNamespace() #167
        +---[min=0.001137ms,max=0.005607ms,total=0.170279ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setNamespace() #57
        +---[min=0.001023ms,max=0.004292ms,total=0.151767ms,count=120] xxxService.helios.entity.HeliosScore:getAppId() #168
        +---[min=0.001105ms,max=0.004701ms,total=0.164955ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setAppId() #57
        +---[min=0.001359ms,max=0.007931ms,total=0.233665ms,count=120] java.util.ArrayList:<init>() #169
        +---[min=0.001117ms,max=0.00785ms,total=0.168539ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:setScores() #57
        +---[min=0.001073ms,max=0.004488ms,total=0.156654ms,count=120] xxxService.model.helios.HeliosGetScoreResponse:getValues() #170
        +---[min=7.98E-4ms,max=0.00977ms,total=0.125818ms,count=120] java.util.List:add() #57
        +---[min=0.022304ms,max=0.12093ms,total=8.88628ms,count=120] xxxService.helios.HeliosHelper:splitScores() #172
        +---[min=0.001092ms,max=0.004967ms,total=0.161288ms,count=120] xxxService.model.helios.HeliosGetScoreRequest:getStartTime() #175
        +---[min=7.02E-4ms,max=0.012136ms,total=0.467786ms,count=480] java.util.Date:getTime() #57
        +---[min=0.001022ms,max=0.004944ms,total=0.151353ms,count=120] xxxService.helios.entity.HeliosScore:getTimeFrom() #178
        +---[min=0.001018ms,max=0.004731ms,total=0.148025ms,count=120] xxxService.helios.entity.HeliosScore:getTimeFrom() #183
        +---[min=7.3E-4ms,max=0.009359ms,total=0.120588ms,count=120] java.util.Date:setTime() #57
        +---[min=0.00107ms,max=0.008948ms,total=0.162848ms,count=120] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() #185
        +---[min=0.001034ms,max=0.014003ms,total=0.158614ms,count=120] xxxService.helios.entity.HeliosScore:getTimeTo() #186
        +---[min=6.99E-4ms,max=0.009995ms,total=0.11179ms,count=120] java.util.List:size() #189
        +---[min=6.95E-4ms,max=0.005468ms,total=1.116308ms,count=1440] java.util.Date:<init>() #193
        +---[min=7.79E-4ms,max=0.029909ms,total=1.407528ms,count=1440] java.util.Set:add() #57
        +---[min=0.001097ms,max=0.008616ms,total=0.160597ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #197
        +---[min=8.23E-4ms,max=0.0294ms,total=0.153353ms,count=120] java.util.List:subList() #57
        +---[min=0.005771ms,max=0.04465ms,total=1.992151ms,count=120] java.util.List:addAll() #57
        +---[min=0.001098ms,max=0.007013ms,total=0.169555ms,count=120] xxxService.model.helios.HeliosGetScoreResponse$Score:getScores() #201
        +---[min=7.04E-4ms,max=0.01315ms,total=0.120998ms,count=120] java.util.List:size() #57+ -- -- -0.197732ms] java.util.ArrayList:<init>() #204+ -- -- -0.018589ms] java.util.ArrayList:stream() #57+ -- -- -0.025192ms] java.util.stream.Stream:sorted() #57+ -- -- -0.012544ms] java.util.stream.Stream:map() #57+ -- -- -0.012188ms] java.util.stream.Collectors:toList() #57
        `---[0.0067ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #57
Copy the code

Analysis of the

You can see that the biggest time consuming area is now finally database queries. Today, it only takes 25 to 40ms to query data for a whole day.

The results of

Link:

The program code on the link still needs to deal with more than ten ms, mainly the overhead when the string is converted to int[]. This step can be further optimized.

conclusion

We can draw some conclusions from this optimization:

1. Create as few objects as possible
2. SimpleDateFormatIs very expensive.
3. Date.compareThe cost is not low
4. Even the simplest operations likelist.size() list.addAnd the cost can be significant
5. The right tools for performance analysis and optimization are essential in order to draw useful conclusions and optimize accordingly. At first I thought reducing object creation would be all right, but that’s not where the bulk of the performance cost lies. Again, Arthas Trace is needed to truly optimize.

Dynamic tracking is highly recommended, and every engineer who wants to advance should have an in-depth understanding of dynamic tracking.