How I Cut a Java Service’s Response Time from Seconds to Milliseconds with Arthas

Background

Helios processes massive score data – 1440 minutes per day for each application, amounting to hundreds of thousands of points. Querying a full day’s scores originally incurred multi‑second latency, while the underlying database call only took about 11 ms, indicating that most time was spent assembling the response.

Optimization Process

2.1 Initial Unoptimized Version

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

2.1.2 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>()
        +---[0.007132ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime()
        ... (trace continues showing each method call and its cost) ...
        +---[0.38178ms] java.util.stream.Stream:collect()
        `---[0.004627ms] xxxService.model.helios.HeliosGetScoreResponse:setDates() #182

2.1.3 Analysis

Arthas reports a total of about 4 s, but the actual wall‑time measured on the link is only 350‑450 ms. The extra time comes from Arthas itself, because the method contains heavy loops. The function has three nested loops: ~140 app IDs, a single batch of data per day, and 1440 minute‑level entries. The most expensive operation is SimpleDateFormat.formatDate(), which is called for every minute.

2.2 First Optimization

2.2.1 Optimization Direction

Change the iteration strategy: split the large merged object into many small objects and iterate by time point, reducing the creation of hundreds of thousands of objects.

Replace Set<String> dateSet with Set<Date> dateSet to avoid repeated formatDate() calls.

Replace Integer.parseInt with a pre‑built Map<String,Integer> dictionary for the strings “0”‑“100”. (Later JMH tests showed Integer.parseInt remained the fastest.)

2.2.2 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);
        Calendar indexDate = DateUtils.roundDownMinute(request.getStartTime().getTime());
        int index = 0;
        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;
}

2.2.3 Arthas Trace

---ts=2021-08-17 14:44:11
    `---[6997.005629ms] xxxService.controller.HeliosController:queryScores()
        +---[0.020032ms] xxxService.model.helios.HeliosGetScoreResponse:<init>()
        +---[0.007451ms] xxxService.model.helios.HeliosGetScoreRequest:getStartTime()
        +---[0.001054ms-7.458198ms] xxxService.model.helios.HeliosGetScoreRequest:getEndTime() (total 213.19538ms, 170754 calls)
        +---[15.255919ms] xxxService.service.HeliosService:queryScoresTimeBetween()
        +---[20.06713ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData()
        ... (remaining trace omitted for brevity) ...
        `---[0.006768ms] xxxService.model.helios.HeliosGetScoreResponse:setDates()

2.2.4 Analysis

The first optimization shaved roughly 50 ms off the total. The trace shows the longest remaining cost is Date.compareTo inside the conditional

if (splitHeliosScore.getTimeFrom().compareTo(request.getStartTime()) < 0)

. Even simple getter calls accumulate noticeable overhead.

2.3 Second Optimization

2.3.1 Optimization Direction

Replace Date objects with primitive long timestamps for comparisons.

Replace repeated getTime()/setTime() on Date with a single += 60_000 increment, setting the time only once.

Insert each date into the set only once by using a flag.

After the first loop, determine the final size of the score list and pre‑size the ArrayList to avoid repeated resizing (using a 1.1× buffer).

2.3.2 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);
        long indexDateMills = request.getStartTime().getTime();
        int index = 0;
        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();
        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;
        scoreSize = (int) (score.getScores().size() * 1.1);
    }
    response.setDates(new ArrayList<>(dateSet).stream().sorted().map(DateUtils.yyyyMMddHHmm::formatDate).collect(Collectors.toList()));
    return response;
}

2.3.3 Arthas Trace

---ts=2021-08-17 15:20:41
    `---[1411.395123ms] xxxService.controller.HeliosController:queryScores()
        +---[0.016102ms] xxxService.model.helios.HeliosGetScoreResponse:<init>()
        +---[27.494178ms] xxxService.service.HeliosService:queryScoresTimeBetween()
        +---[19.990512ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData()
        ... (trace continues) ...
        `---[0.007166ms] xxxService.model.helios.HeliosGetScoreResponse:setDates()

2.3.4 Analysis

This pass saved roughly another 80 ms, leaving about 160 ms. The trace highlights three hot methods: getScores (simple getter), list.size(), and list.get(index). Even though these methods do almost nothing, their sheer frequency adds measurable cost.

2.4 Third Optimization

2.4.1 Optimization Direction

Reduce repeated list property accesses.

Replace many individual list.add calls with a single subList insertion.

2.4.2 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);
        long indexDateMills = request.getStartTime().getTime();
        int index = 0;
        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();
        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;
        scoreSize = (int) (score.getScores().size() * 1.1);
    }
    response.setDates(new ArrayList<>(dateSet).stream().sorted().map(DateUtils.yyyyMMddHHmm::formatDate).collect(Collectors.toList()));
    return response;
}

2.4.3 Arthas Trace

---ts=2021-08-17 15:33:40
    `---[138.624811ms] xxxService.controller.HeliosController:queryScores()
        +---[15.227453ms] xxxService.service.HeliosService:queryScoresTimeBetween()
        +---[22.703926ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData()
        ... (trace continues) ...
        `---[0.007166ms] xxxService.model.helios.HeliosGetScoreResponse:setDates()

2.4.4 Analysis

This iteration saved roughly 100 ms, bringing the total down to about 60 ms. The remaining hot spots are now limited to three operations: database query, data merge, and splitting the score string (e.g., converting "100,100,100" to an int[]).

2.5 Fourth Optimization

2.5.1 Optimization Direction

Fix the SQL so it no longer returns an extra row, halving the loop count.

When only a single record is returned, skip the merge logic entirely.

2.5.2 Code

// SQL was corrected (not shown). The Java code now checks record count:
if (heliosScoresRecord.size() == 1) {
    // bypass merge and directly build response
    ...
}

2.5.3 Arthas Trace

---ts=2021-08-17 16:03:24
    `---[38.171379ms] xxxService.controller.HeliosController:queryScores()
        +---[10.157226ms] xxxService.service.HeliosService:queryScoresTimeBetween()
        +---[0.083535ms] xxxService.helios.jobs.HeliosDataMergeJob:mergeData()
        ... (trace continues) ...
        `---[0.0067ms] xxxService.model.helios.HeliosGetScoreResponse:setDates()

2.5.4 Analysis

After fixing the SQL and skipping unnecessary merge steps, the database query becomes the dominant cost, taking only 25‑40 ms for a full‑day request.

Final Observations

Avoid creating unnecessary objects; object allocation can be a major overhead. SimpleDateFormat formatting is expensive and should be minimized. Date.compareTo also incurs noticeable cost.

Even cheap operations like list.size() and list.add add up when executed millions of times.

Accurate profiling tools such as Arthas are essential; initial intuition that object creation was the main culprit proved wrong once the trace revealed the real hot paths.