Разбор перформансных задач с JBreak (Часть 2)18.03.2018 16:18

habr.png

Только поутихли страсти с первой части разбора, вышедшей на прошлой неделе, как публикую продолжение: сегодня речь пойдёт о второй задаче.

Код второй задачи: 

    String format(String user, String grade, String company, String message) {
        return String.format(
                "Он, %s, придумал такие %s задачи. Приду на стенд %s и скажу ему %s",
                user, grade, company, message);
    }

    String format(String user, String grade, String company, String message) {
        return "Он, " + user
                + ", придумал такие " + grade
                + " задачи. Приду на стенд " + company
                + " и скажу ему " + message;
    }

    String format(String user, String grade, String company, String message) {
        return new StringBuilder("Он, ")
                .append(user)
                .append(", придумал такие ")
                .append(grade)
                .append(" задачи. Приду на стенд ")
                .append(company)
                .append(" и скажу ему ")
                .append(message)
                .toString();
    }


Условие (упрощённо):

Определить, какие методы быстрые, а какие — медленные (JRE 1.8.0_161).


Немного расширим задачу, добавив ещё один способ форматирования строки вне конкурса: 

    public String formatThroughMessageFormat(String user, String grade, String company, String message) {
        return MessageFormat.format(
                "Он, {0}, придумал такие {1} задачи. Приду на стенд {2} и скажу ему {3}",
                user, grade, company, message);
    }

Решение


Миф о медленной конкатенации


Очевидный неправильный ответ: конкатенация — это медленно (во всяком случае — медленнее, чем StringBuilder).
Миф о медленной конкатенации, вероятнее всего, уходит своими корнями в пример, демонстрирующий влияние иммутабельности строк на вычислительную сложность алгоритма: 

    public static String constructThroughConcatenation(String[] strings) {
        String result = "";
        for (String s : strings) {
            result = result + s;
        }
        return result;
    }

    public static String constructThroughBuilder(String[] strings) {
        StringBuilder sb = new StringBuilder();
        for (String s : strings) {
            sb.append(s);
        }
        return sb.toString();
    }


Результат бенчмарка говорит сам за себя (здесь N — размер массива strings): 

Benchmark                    (N)  Mode  Cnt       Score      Error  Units
...builderBenchmark           10  avgt   30       0,182 ±    0,004  us/op
...builderBenchmark          100  avgt   30       1,566 ±    0,014  us/op
...builderBenchmark         1000  avgt   30      18,188 ±    0,372  us/op
...builderBenchmark        10000  avgt   30     214,308 ±    7,523  us/op
...concatenationBenchmark     10  avgt   30       0,209 ±    0,003  us/op
...concatenationBenchmark    100  avgt   30      13,220 ±    0,305  us/op
...concatenationBenchmark   1000  avgt   30    1158,463 ±   48,124  us/op
...concatenationBenchmark  10000  avgt   30  127585,013 ± 5716,547  us/op


Результаты бенчмарка целиком
# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark
# Parameters: (N = 10)

# Run progress: 0,00% complete, ETA 00:09:00
# Fork: 1 of 3
# Warmup Iteration   1: 0,251 us/op
# Warmup Iteration   2: 0,192 us/op
# Warmup Iteration   3: 0,206 us/op
# Warmup Iteration   4: 0,183 us/op
# Warmup Iteration   5: 0,181 us/op
Iteration   1: 0,180 us/op
Iteration   2: 0,181 us/op
Iteration   3: 0,188 us/op
Iteration   4: 0,180 us/op
Iteration   5: 0,202 us/op
Iteration   6: 0,192 us/op
Iteration   7: 0,195 us/op
Iteration   8: 0,178 us/op
Iteration   9: 0,179 us/op
Iteration  10: 0,192 us/op

# Run progress: 4,17% complete, ETA 00:08:47
# Fork: 2 of 3
# Warmup Iteration   1: 0,249 us/op
# Warmup Iteration   2: 0,179 us/op
# Warmup Iteration   3: 0,178 us/op
# Warmup Iteration   4: 0,178 us/op
# Warmup Iteration   5: 0,179 us/op
Iteration   1: 0,178 us/op
Iteration   2: 0,181 us/op
Iteration   3: 0,178 us/op
Iteration   4: 0,179 us/op
Iteration   5: 0,181 us/op
Iteration   6: 0,182 us/op
Iteration   7: 0,183 us/op
Iteration   8: 0,177 us/op
Iteration   9: 0,177 us/op
Iteration  10: 0,177 us/op

# Run progress: 8,33% complete, ETA 00:08:24
# Fork: 3 of 3
# Warmup Iteration   1: 0,249 us/op
# Warmup Iteration   2: 0,179 us/op
# Warmup Iteration   3: 0,177 us/op
# Warmup Iteration   4: 0,179 us/op
# Warmup Iteration   5: 0,179 us/op
Iteration   1: 0,180 us/op
Iteration   2: 0,180 us/op
Iteration   3: 0,178 us/op
Iteration   4: 0,178 us/op
Iteration   5: 0,181 us/op
Iteration   6: 0,180 us/op
Iteration   7: 0,180 us/op
Iteration   8: 0,179 us/op
Iteration   9: 0,182 us/op
Iteration  10: 0,178 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  0,182 ±(99.9%) 0,004 us/op [Average]
  (min, avg, max) = (0,177, 0,182, 0,202), stdev = 0,006
  CI (99.9%): [0,178, 0,186] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark
# Parameters: (N = 100)

# Run progress: 12,50% complete, ETA 00:08:01
# Fork: 1 of 3
# Warmup Iteration   1: 2,016 us/op
# Warmup Iteration   2: 1,592 us/op
# Warmup Iteration   3: 1,548 us/op
# Warmup Iteration   4: 1,557 us/op
# Warmup Iteration   5: 1,553 us/op
Iteration   1: 1,561 us/op
Iteration   2: 1,563 us/op
Iteration   3: 1,568 us/op
Iteration   4: 1,570 us/op
Iteration   5: 1,560 us/op
Iteration   6: 1,560 us/op
Iteration   7: 1,563 us/op
Iteration   8: 1,564 us/op
Iteration   9: 1,570 us/op
Iteration  10: 1,566 us/op

# Run progress: 16,67% complete, ETA 00:07:38
# Fork: 2 of 3
# Warmup Iteration   1: 2,011 us/op
# Warmup Iteration   2: 1,578 us/op
# Warmup Iteration   3: 1,556 us/op
# Warmup Iteration   4: 1,560 us/op
# Warmup Iteration   5: 1,601 us/op
Iteration   1: 1,551 us/op
Iteration   2: 1,563 us/op
Iteration   3: 1,558 us/op
Iteration   4: 1,555 us/op
Iteration   5: 1,562 us/op
Iteration   6: 1,560 us/op
Iteration   7: 1,556 us/op
Iteration   8: 1,565 us/op
Iteration   9: 1,565 us/op
Iteration  10: 1,553 us/op

# Run progress: 20,83% complete, ETA 00:07:15
# Fork: 3 of 3
# Warmup Iteration   1: 2,099 us/op
# Warmup Iteration   2: 1,769 us/op
# Warmup Iteration   3: 1,751 us/op
# Warmup Iteration   4: 1,554 us/op
# Warmup Iteration   5: 1,555 us/op
Iteration   1: 1,602 us/op
Iteration   2: 1,663 us/op
Iteration   3: 1,567 us/op
Iteration   4: 1,565 us/op
Iteration   5: 1,569 us/op
Iteration   6: 1,548 us/op
Iteration   7: 1,555 us/op
Iteration   8: 1,553 us/op
Iteration   9: 1,559 us/op
Iteration  10: 1,563 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  1,566 ±(99.9%) 0,014 us/op [Average]
  (min, avg, max) = (1,548, 1,566, 1,663), stdev = 0,020
  CI (99.9%): [1,552, 1,580] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark
# Parameters: (N = 1000)

# Run progress: 25,00% complete, ETA 00:06:52
# Fork: 1 of 3
# Warmup Iteration   1: 25,482 us/op
# Warmup Iteration   2: 17,783 us/op
# Warmup Iteration   3: 17,741 us/op
# Warmup Iteration   4: 18,389 us/op
# Warmup Iteration   5: 18,693 us/op
Iteration   1: 17,891 us/op
Iteration   2: 17,909 us/op
Iteration   3: 17,966 us/op
Iteration   4: 17,632 us/op
Iteration   5: 17,884 us/op
Iteration   6: 17,821 us/op
Iteration   7: 17,962 us/op
Iteration   8: 17,825 us/op
Iteration   9: 18,039 us/op
Iteration  10: 17,891 us/op

# Run progress: 29,17% complete, ETA 00:06:29
# Fork: 2 of 3
# Warmup Iteration   1: 23,928 us/op
# Warmup Iteration   2: 17,799 us/op
# Warmup Iteration   3: 17,615 us/op
# Warmup Iteration   4: 17,823 us/op
# Warmup Iteration   5: 17,996 us/op
Iteration   1: 17,901 us/op
Iteration   2: 18,052 us/op
Iteration   3: 18,093 us/op
Iteration   4: 17,722 us/op
Iteration   5: 17,951 us/op
Iteration   6: 17,958 us/op
Iteration   7: 18,071 us/op
Iteration   8: 18,043 us/op
Iteration   9: 17,681 us/op
Iteration  10: 17,934 us/op

# Run progress: 33,33% complete, ETA 00:06:06
# Fork: 3 of 3
# Warmup Iteration   1: 26,743 us/op
# Warmup Iteration   2: 18,281 us/op
# Warmup Iteration   3: 18,178 us/op
# Warmup Iteration   4: 18,474 us/op
# Warmup Iteration   5: 18,661 us/op
Iteration   1: 18,735 us/op
Iteration   2: 20,414 us/op
Iteration   3: 18,762 us/op
Iteration   4: 18,673 us/op
Iteration   5: 18,280 us/op
Iteration   6: 18,336 us/op
Iteration   7: 18,259 us/op
Iteration   8: 18,362 us/op
Iteration   9: 18,295 us/op
Iteration  10: 19,312 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  18,188 ±(99.9%) 0,372 us/op [Average]
  (min, avg, max) = (17,632, 18,188, 20,414), stdev = 0,557
  CI (99.9%): [17,816, 18,561] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark
# Parameters: (N = 10000)

# Run progress: 37,50% complete, ETA 00:05:44
# Fork: 1 of 3
# Warmup Iteration   1: 282,300 us/op
# Warmup Iteration   2: 225,761 us/op
# Warmup Iteration   3: 223,512 us/op
# Warmup Iteration   4: 261,430 us/op
# Warmup Iteration   5: 292,495 us/op
Iteration   1: 220,548 us/op
Iteration   2: 217,293 us/op
Iteration   3: 240,740 us/op
Iteration   4: 218,483 us/op
Iteration   5: 216,646 us/op
Iteration   6: 211,005 us/op
Iteration   7: 209,140 us/op
Iteration   8: 204,410 us/op
Iteration   9: 208,205 us/op
Iteration  10: 217,127 us/op

# Run progress: 41,67% complete, ETA 00:05:21
# Fork: 2 of 3
# Warmup Iteration   1: 259,280 us/op
# Warmup Iteration   2: 230,647 us/op
# Warmup Iteration   3: 209,753 us/op
# Warmup Iteration   4: 215,611 us/op
# Warmup Iteration   5: 210,592 us/op
Iteration   1: 203,746 us/op
Iteration   2: 208,074 us/op
Iteration   3: 207,905 us/op
Iteration   4: 213,764 us/op
Iteration   5: 206,427 us/op
Iteration   6: 207,121 us/op
Iteration   7: 215,708 us/op
Iteration   8: 213,091 us/op
Iteration   9: 211,328 us/op
Iteration  10: 204,837 us/op

# Run progress: 45,83% complete, ETA 00:04:58
# Fork: 3 of 3
# Warmup Iteration   1: 253,784 us/op
# Warmup Iteration   2: 227,220 us/op
# Warmup Iteration   3: 202,387 us/op
# Warmup Iteration   4: 211,402 us/op
# Warmup Iteration   5: 207,545 us/op
Iteration   1: 206,279 us/op
Iteration   2: 205,982 us/op
Iteration   3: 211,830 us/op
Iteration   4: 238,729 us/op
Iteration   5: 237,315 us/op
Iteration   6: 238,384 us/op
Iteration   7: 223,376 us/op
Iteration   8: 210,594 us/op
Iteration   9: 200,957 us/op
Iteration  10: 200,183 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  214,308 ±(99.9%) 7,523 us/op [Average]
  (min, avg, max) = (200,183, 214,308, 240,740), stdev = 11,260
  CI (99.9%): [206,785, 221,831] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark
# Parameters: (N = 10)

# Run progress: 50,00% complete, ETA 00:04:35
# Fork: 1 of 3
# Warmup Iteration   1: 0,273 us/op
# Warmup Iteration   2: 0,201 us/op
# Warmup Iteration   3: 0,209 us/op
# Warmup Iteration   4: 0,208 us/op
# Warmup Iteration   5: 0,208 us/op
Iteration   1: 0,208 us/op
Iteration   2: 0,207 us/op
Iteration   3: 0,208 us/op
Iteration   4: 0,208 us/op
Iteration   5: 0,208 us/op
Iteration   6: 0,208 us/op
Iteration   7: 0,208 us/op
Iteration   8: 0,213 us/op
Iteration   9: 0,206 us/op
Iteration  10: 0,206 us/op

# Run progress: 54,17% complete, ETA 00:04:12
# Fork: 2 of 3
# Warmup Iteration   1: 0,301 us/op
# Warmup Iteration   2: 0,207 us/op
# Warmup Iteration   3: 0,204 us/op
# Warmup Iteration   4: 0,206 us/op
# Warmup Iteration   5: 0,206 us/op
Iteration   1: 0,208 us/op
Iteration   2: 0,207 us/op
Iteration   3: 0,206 us/op
Iteration   4: 0,206 us/op
Iteration   5: 0,208 us/op
Iteration   6: 0,205 us/op
Iteration   7: 0,207 us/op
Iteration   8: 0,221 us/op
Iteration   9: 0,214 us/op
Iteration  10: 0,207 us/op

# Run progress: 58,33% complete, ETA 00:03:49
# Fork: 3 of 3
# Warmup Iteration   1: 0,273 us/op
# Warmup Iteration   2: 0,199 us/op
# Warmup Iteration   3: 0,213 us/op
# Warmup Iteration   4: 0,206 us/op
# Warmup Iteration   5: 0,208 us/op
Iteration   1: 0,210 us/op
Iteration   2: 0,220 us/op
Iteration   3: 0,208 us/op
Iteration   4: 0,205 us/op
Iteration   5: 0,205 us/op
Iteration   6: 0,209 us/op
Iteration   7: 0,210 us/op
Iteration   8: 0,209 us/op
Iteration   9: 0,208 us/op
Iteration  10: 0,208 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  0,209 ±(99.9%) 0,003 us/op [Average]
  (min, avg, max) = (0,205, 0,209, 0,221), stdev = 0,004
  CI (99.9%): [0,206, 0,211] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark
# Parameters: (N = 100)

# Run progress: 62,50% complete, ETA 00:03:26
# Fork: 1 of 3
# Warmup Iteration   1: 17,351 us/op
# Warmup Iteration   2: 13,141 us/op
# Warmup Iteration   3: 13,015 us/op
# Warmup Iteration   4: 13,004 us/op
# Warmup Iteration   5: 13,073 us/op
Iteration   1: 13,056 us/op
Iteration   2: 13,158 us/op
Iteration   3: 13,005 us/op
Iteration   4: 13,126 us/op
Iteration   5: 13,001 us/op
Iteration   6: 13,072 us/op
Iteration   7: 13,085 us/op
Iteration   8: 13,063 us/op
Iteration   9: 13,196 us/op
Iteration  10: 13,084 us/op

# Run progress: 66,67% complete, ETA 00:03:03
# Fork: 2 of 3
# Warmup Iteration   1: 17,545 us/op
# Warmup Iteration   2: 13,517 us/op
# Warmup Iteration   3: 13,500 us/op
# Warmup Iteration   4: 13,089 us/op
# Warmup Iteration   5: 13,099 us/op
Iteration   1: 13,312 us/op
Iteration   2: 13,689 us/op
Iteration   3: 13,157 us/op
Iteration   4: 13,532 us/op
Iteration   5: 14,263 us/op
Iteration   6: 14,110 us/op
Iteration   7: 14,207 us/op
Iteration   8: 13,167 us/op
Iteration   9: 13,530 us/op
Iteration  10: 13,127 us/op

# Run progress: 70,83% complete, ETA 00:02:40
# Fork: 3 of 3
# Warmup Iteration   1: 17,107 us/op
# Warmup Iteration   2: 12,677 us/op
# Warmup Iteration   3: 12,549 us/op
# Warmup Iteration   4: 12,714 us/op
# Warmup Iteration   5: 14,134 us/op
Iteration   1: 13,898 us/op
Iteration   2: 13,726 us/op
Iteration   3: 12,997 us/op
Iteration   4: 12,736 us/op
Iteration   5: 12,702 us/op
Iteration   6: 12,670 us/op
Iteration   7: 12,690 us/op
Iteration   8: 12,735 us/op
Iteration   9: 12,761 us/op
Iteration  10: 12,750 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  13,220 ±(99.9%) 0,305 us/op [Average]
  (min, avg, max) = (12,670, 13,220, 14,263), stdev = 0,456
  CI (99.9%): [12,915, 13,525] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark
# Parameters: (N = 1000)

# Run progress: 75,00% complete, ETA 00:02:17
# Fork: 1 of 3
# Warmup Iteration   1: 2069,805 us/op
# Warmup Iteration   2: 1256,239 us/op
# Warmup Iteration   3: 1094,567 us/op
# Warmup Iteration   4: 1088,928 us/op
# Warmup Iteration   5: 1128,676 us/op
Iteration   1: 1098,263 us/op
Iteration   2: 1092,322 us/op
Iteration   3: 1092,764 us/op
Iteration   4: 1091,264 us/op
Iteration   5: 1084,967 us/op
Iteration   6: 1082,483 us/op
Iteration   7: 1087,570 us/op
Iteration   8: 1085,939 us/op
Iteration   9: 1087,219 us/op
Iteration  10: 1099,661 us/op

# Run progress: 79,17% complete, ETA 00:01:54
# Fork: 2 of 3
# Warmup Iteration   1: 1886,339 us/op
# Warmup Iteration   2: 1079,598 us/op
# Warmup Iteration   3: 1249,267 us/op
# Warmup Iteration   4: 1223,656 us/op
# Warmup Iteration   5: 1155,596 us/op
Iteration   1: 1074,649 us/op
Iteration   2: 1158,081 us/op
Iteration   3: 1156,362 us/op
Iteration   4: 1164,930 us/op
Iteration   5: 1109,143 us/op
Iteration   6: 1172,856 us/op
Iteration   7: 1277,790 us/op
Iteration   8: 1201,096 us/op
Iteration   9: 1111,431 us/op
Iteration  10: 1267,544 us/op

# Run progress: 83,33% complete, ETA 00:01:31
# Fork: 3 of 3
# Warmup Iteration   1: 2372,316 us/op
# Warmup Iteration   2: 1381,800 us/op
# Warmup Iteration   3: 1360,184 us/op
# Warmup Iteration   4: 1131,667 us/op
# Warmup Iteration   5: 1209,669 us/op
Iteration   1: 1278,702 us/op
Iteration   2: 1219,975 us/op
Iteration   3: 1141,188 us/op
Iteration   4: 1244,753 us/op
Iteration   5: 1229,355 us/op
Iteration   6: 1168,263 us/op
Iteration   7: 1153,918 us/op
Iteration   8: 1330,528 us/op
Iteration   9: 1207,424 us/op
Iteration  10: 1183,450 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  1158,463 ±(99.9%) 48,124 us/op [Average]
  (min, avg, max) = (1074,649, 1158,463, 1330,528), stdev = 72,029
  CI (99.9%): [1110,339, 1206,587] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark
# Parameters: (N = 10000)

# Run progress: 87,50% complete, ETA 00:01:08
# Fork: 1 of 3
# Warmup Iteration   1: 551317,226 us/op
# Warmup Iteration   2: 428150,732 us/op
# Warmup Iteration   3: 416550,724 us/op
# Warmup Iteration   4: 117977,293 us/op
# Warmup Iteration   5: 121797,206 us/op
Iteration   1: 120847,573 us/op
Iteration   2: 134688,534 us/op
Iteration   3: 130307,702 us/op
Iteration   4: 122642,500 us/op
Iteration   5: 119836,801 us/op
Iteration   6: 128095,357 us/op
Iteration   7: 119841,822 us/op
Iteration   8: 125189,403 us/op
Iteration   9: 125955,061 us/op
Iteration  10: 137509,499 us/op

# Run progress: 91,67% complete, ETA 00:00:46
# Fork: 2 of 3
# Warmup Iteration   1: 602435,410 us/op
# Warmup Iteration   2: 404409,425 us/op
# Warmup Iteration   3: 404721,946 us/op
# Warmup Iteration   4: 133065,650 us/op
# Warmup Iteration   5: 123633,597 us/op
Iteration   1: 117683,792 us/op
Iteration   2: 126726,151 us/op
Iteration   3: 125225,846 us/op
Iteration   4: 128106,852 us/op
Iteration   5: 121581,390 us/op
Iteration   6: 128516,807 us/op
Iteration   7: 145913,920 us/op
Iteration   8: 134438,346 us/op
Iteration   9: 118692,163 us/op
Iteration  10: 125122,644 us/op

# Run progress: 95,83% complete, ETA 00:00:23
# Fork: 3 of 3
# Warmup Iteration   1: 515801,468 us/op
# Warmup Iteration   2: 403393,041 us/op
# Warmup Iteration   3: 388443,058 us/op
# Warmup Iteration   4: 127654,236 us/op
# Warmup Iteration   5: 117518,788 us/op
Iteration   1: 119643,439 us/op
Iteration   2: 137466,542 us/op
Iteration   3: 146242,312 us/op
Iteration   4: 143566,288 us/op
Iteration   5: 138948,391 us/op
Iteration   6: 120434,984 us/op
Iteration   7: 126233,747 us/op
Iteration   8: 118765,491 us/op
Iteration   9: 121795,027 us/op
Iteration  10: 117532,020 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  127585,013 ±(99.9%) 5716,547 us/op [Average]
  (min, avg, max) = (117532,020, 127585,013, 146242,312), stdev = 8556,259
  CI (99.9%): [121868,467, 133301,560] (assumes normal distribution)


# Run complete. Total time: 00:09:14

Benchmark                                          (N)  Mode  Cnt       Score      Error  Units
ImmutableStringBenchmark.builderBenchmark           10  avgt   30       0,182 ±    0,004  us/op
ImmutableStringBenchmark.builderBenchmark          100  avgt   30       1,566 ±    0,014  us/op
ImmutableStringBenchmark.builderBenchmark         1000  avgt   30      18,188 ±    0,372  us/op
ImmutableStringBenchmark.builderBenchmark        10000  avgt   30     214,308 ±    7,523  us/op
ImmutableStringBenchmark.concatenationBenchmark     10  avgt   30       0,209 ±    0,003  us/op
ImmutableStringBenchmark.concatenationBenchmark    100  avgt   30      13,220 ±    0,305  us/op
ImmutableStringBenchmark.concatenationBenchmark   1000  avgt   30    1158,463 ±   48,124  us/op
ImmutableStringBenchmark.concatenationBenchmark  10000  avgt   30  127585,013 ± 5716,547  us/op


O(n^2) против O(n) — очевидное превосходство StringBuilder над конкатенацией.

Бенчмарк и разрушение мифа


Запустим бенчмарк для указанных в задаче методов:

  1. formatThroughPattern — использование String.format()
  2. formatThroughConcatenation — использование конкатенации строк
  3. formatThroughBuilder — использование StringBuilder
  4. formatThroughMessageFormat — использование MessageFormat.format().


Код бенчмарка
package ru.gnkoshelev.jbreak2018.perf_tests.strings;

import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Warmup;
import org.openjdk.jmh.infra.Blackhole;

import java.util.concurrent.TimeUnit;

import static ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormat.formatThroughBuilder;
import static ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormat.formatThroughConcatenation;
import static ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormat.formatThroughMessageFormat;
import static ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormat.formatThroughPattern;

/**
 * Created by kgn on 16.03.2018.
 */
@Fork(value = 3, warmups = 0)
@Warmup(iterations = 5, time = 1_500, timeUnit = TimeUnit.MILLISECONDS)
@Measurement(iterations = 10, time = 1_500, timeUnit = TimeUnit.MILLISECONDS)
@OutputTimeUnit(value = TimeUnit.NANOSECONDS)
@BenchmarkMode(Mode.AverageTime)
@State(Scope.Benchmark)
public class OrdinalStringFormatBenchmark {
    public String user;
    public String grade;
    public String message;
    public String company;

    @Setup
    public void setup() {
        user = "молодец";
        grade = "хорошие";
        company = "Контура";
        message = "спасибо";
    }

    @Benchmark
    public void formatThroughPatternBenchmark(Blackhole bh) {
        bh.consume(formatThroughPattern(user, company, grade, message));
    }

    @Benchmark
    public void formatThroughConcatenationBenchmark(Blackhole bh) {
        bh.consume(formatThroughConcatenation(user, company, grade, message));
    }

    @Benchmark
    public void formatThroughBuilderBenchmark(Blackhole bh) {
        bh.consume(formatThroughBuilder(user, company, grade, message));
    }

    @Benchmark
    public void formatThroughMessageFormatBenchmark(Blackhole bh) {
        bh.consume(formatThroughMessageFormat(user, company, grade, message));
    }
}


Результат бенчмарка: 

Benchmark                               Mode  Cnt     Score    Error  Units
...formatThroughBuilderBenchmark        avgt   30    50,719 ±  1,139  ns/op
...formatThroughConcatenationBenchmark  avgt   30    49,416 ±  0,435  ns/op
...formatThroughMessageFormatBenchmark  avgt   30  1018,011 ± 12,805  ns/op
...formatThroughPatternBenchmark        avgt   30  1506,341 ± 21,927  ns/op


Результаты бенчмарка целиком
# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughBuilderBenchmark

# Run progress: 0,00% complete, ETA 00:04:30
# Fork: 1 of 3
# Warmup Iteration   1: 66,501 ns/op
# Warmup Iteration   2: 60,551 ns/op
# Warmup Iteration   3: 56,899 ns/op
# Warmup Iteration   4: 49,136 ns/op
# Warmup Iteration   5: 48,549 ns/op
Iteration   1: 52,092 ns/op
Iteration   2: 49,894 ns/op
Iteration   3: 54,802 ns/op
Iteration   4: 53,570 ns/op
Iteration   5: 50,592 ns/op
Iteration   6: 51,676 ns/op
Iteration   7: 51,835 ns/op
Iteration   8: 49,216 ns/op
Iteration   9: 53,597 ns/op
Iteration  10: 50,949 ns/op

# Run progress: 8,33% complete, ETA 00:04:13
# Fork: 2 of 3
# Warmup Iteration   1: 64,670 ns/op
# Warmup Iteration   2: 51,154 ns/op
# Warmup Iteration   3: 49,878 ns/op
# Warmup Iteration   4: 49,587 ns/op
# Warmup Iteration   5: 52,958 ns/op
Iteration   1: 53,521 ns/op
Iteration   2: 53,372 ns/op
Iteration   3: 52,264 ns/op
Iteration   4: 50,248 ns/op
Iteration   5: 50,198 ns/op
Iteration   6: 49,958 ns/op
Iteration   7: 49,277 ns/op
Iteration   8: 49,983 ns/op
Iteration   9: 50,250 ns/op
Iteration  10: 50,128 ns/op

# Run progress: 16,67% complete, ETA 00:03:49
# Fork: 3 of 3
# Warmup Iteration   1: 64,392 ns/op
# Warmup Iteration   2: 50,621 ns/op
# Warmup Iteration   3: 48,771 ns/op
# Warmup Iteration   4: 48,909 ns/op
# Warmup Iteration   5: 49,029 ns/op
Iteration   1: 49,144 ns/op
Iteration   2: 48,941 ns/op
Iteration   3: 49,632 ns/op
Iteration   4: 49,275 ns/op
Iteration   5: 48,470 ns/op
Iteration   6: 48,599 ns/op
Iteration   7: 50,489 ns/op
Iteration   8: 48,866 ns/op
Iteration   9: 50,790 ns/op
Iteration  10: 49,945 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughBuilderBenchmark":
  50,719 ±(99.9%) 1,139 ns/op [Average]
  (min, avg, max) = (48,470, 50,719, 54,802), stdev = 1,704
  CI (99.9%): [49,580, 51,858] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughConcatenationBenchmark

# Run progress: 25,00% complete, ETA 00:03:26
# Fork: 1 of 3
# Warmup Iteration   1: 64,954 ns/op
# Warmup Iteration   2: 49,711 ns/op
# Warmup Iteration   3: 49,847 ns/op
# Warmup Iteration   4: 49,832 ns/op
# Warmup Iteration   5: 48,330 ns/op
Iteration   1: 48,820 ns/op
Iteration   2: 48,948 ns/op
Iteration   3: 48,992 ns/op
Iteration   4: 48,912 ns/op
Iteration   5: 49,423 ns/op
Iteration   6: 51,057 ns/op
Iteration   7: 49,861 ns/op
Iteration   8: 49,339 ns/op
Iteration   9: 49,602 ns/op
Iteration  10: 49,135 ns/op

# Run progress: 33,33% complete, ETA 00:03:03
# Fork: 2 of 3
# Warmup Iteration   1: 63,647 ns/op
# Warmup Iteration   2: 49,904 ns/op
# Warmup Iteration   3: 49,307 ns/op
# Warmup Iteration   4: 48,602 ns/op
# Warmup Iteration   5: 49,369 ns/op
Iteration   1: 49,388 ns/op
Iteration   2: 48,579 ns/op
Iteration   3: 50,546 ns/op
Iteration   4: 50,421 ns/op
Iteration   5: 49,246 ns/op
Iteration   6: 48,432 ns/op
Iteration   7: 49,458 ns/op
Iteration   8: 50,071 ns/op
Iteration   9: 49,405 ns/op
Iteration  10: 49,432 ns/op

# Run progress: 41,67% complete, ETA 00:02:40
# Fork: 3 of 3
# Warmup Iteration   1: 64,515 ns/op
# Warmup Iteration   2: 49,747 ns/op
# Warmup Iteration   3: 49,217 ns/op
# Warmup Iteration   4: 49,306 ns/op
# Warmup Iteration   5: 48,832 ns/op
Iteration   1: 50,280 ns/op
Iteration   2: 50,300 ns/op
Iteration   3: 48,426 ns/op
Iteration   4: 49,774 ns/op
Iteration   5: 48,891 ns/op
Iteration   6: 49,231 ns/op
Iteration   7: 49,051 ns/op
Iteration   8: 48,662 ns/op
Iteration   9: 49,083 ns/op
Iteration  10: 49,724 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughConcatenationBenchmark":
  49,416 ±(99.9%) 0,435 ns/op [Average]
  (min, avg, max) = (48,426, 49,416, 51,057), stdev = 0,651
  CI (99.9%): [48,981, 49,851] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughMessageFormatBenchmark

# Run progress: 50,00% complete, ETA 00:02:17
# Fork: 1 of 3
# Warmup Iteration   1: 1469,943 ns/op
# Warmup Iteration   2: 1297,225 ns/op
# Warmup Iteration   3: 1118,280 ns/op
# Warmup Iteration   4: 1008,395 ns/op
# Warmup Iteration   5: 1010,427 ns/op
Iteration   1: 1045,570 ns/op
Iteration   2: 1055,899 ns/op
Iteration   3: 1032,176 ns/op
Iteration   4: 1033,352 ns/op
Iteration   5: 1024,963 ns/op
Iteration   6: 1029,085 ns/op
Iteration   7: 1022,343 ns/op
Iteration   8: 1012,589 ns/op
Iteration   9: 1026,919 ns/op
Iteration  10: 1015,923 ns/op

# Run progress: 58,33% complete, ETA 00:01:54
# Fork: 2 of 3
# Warmup Iteration   1: 1466,094 ns/op
# Warmup Iteration   2: 1164,720 ns/op
# Warmup Iteration   3: 1093,806 ns/op
# Warmup Iteration   4: 999,967 ns/op
# Warmup Iteration   5: 1010,377 ns/op
Iteration   1: 1011,633 ns/op
Iteration   2: 999,827 ns/op
Iteration   3: 1005,580 ns/op
Iteration   4: 1012,595 ns/op
Iteration   5: 1007,700 ns/op
Iteration   6: 1012,898 ns/op
Iteration   7: 1034,821 ns/op
Iteration   8: 1003,250 ns/op
Iteration   9: 1011,014 ns/op
Iteration  10: 1006,375 ns/op

# Run progress: 66,67% complete, ETA 00:01:31
# Fork: 3 of 3
# Warmup Iteration   1: 1572,302 ns/op
# Warmup Iteration   2: 1494,790 ns/op
# Warmup Iteration   3: 1214,017 ns/op
# Warmup Iteration   4: 1057,334 ns/op
# Warmup Iteration   5: 1099,289 ns/op
Iteration   1: 987,605 ns/op
Iteration   2: 990,904 ns/op
Iteration   3: 991,050 ns/op
Iteration   4: 1000,703 ns/op
Iteration   5: 1056,985 ns/op
Iteration   6: 1028,472 ns/op
Iteration   7: 1058,749 ns/op
Iteration   8: 1003,892 ns/op
Iteration   9: 1009,049 ns/op
Iteration  10: 1008,405 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughMessageFormatBenchmark":
  1018,011 ±(99.9%) 12,805 ns/op [Average]
  (min, avg, max) = (987,605, 1018,011, 1058,749), stdev = 19,165
  CI (99.9%): [1005,206, 1030,815] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughPatternBenchmark

# Run progress: 75,00% complete, ETA 00:01:08
# Fork: 1 of 3
# Warmup Iteration   1: 2070,487 ns/op
# Warmup Iteration   2: 1660,717 ns/op
# Warmup Iteration   3: 1619,241 ns/op
# Warmup Iteration   4: 1494,624 ns/op
# Warmup Iteration   5: 1554,734 ns/op
Iteration   1: 1516,562 ns/op
Iteration   2: 1503,105 ns/op
Iteration   3: 1501,292 ns/op
Iteration   4: 1501,102 ns/op
Iteration   5: 1487,718 ns/op
Iteration   6: 1486,100 ns/op
Iteration   7: 1496,293 ns/op
Iteration   8: 1543,699 ns/op
Iteration   9: 1564,870 ns/op
Iteration  10: 1645,359 ns/op

# Run progress: 83,33% complete, ETA 00:00:45
# Fork: 2 of 3
# Warmup Iteration   1: 2398,095 ns/op
# Warmup Iteration   2: 1813,653 ns/op
# Warmup Iteration   3: 1597,230 ns/op
# Warmup Iteration   4: 1564,952 ns/op
# Warmup Iteration   5: 1503,908 ns/op
Iteration   1: 1507,203 ns/op
Iteration   2: 1489,109 ns/op
Iteration   3: 1484,389 ns/op
Iteration   4: 1490,826 ns/op
Iteration   5: 1487,540 ns/op
Iteration   6: 1503,939 ns/op
Iteration   7: 1511,837 ns/op
Iteration   8: 1506,471 ns/op
Iteration   9: 1502,044 ns/op
Iteration  10: 1514,643 ns/op

# Run progress: 91,67% complete, ETA 00:00:22
# Fork: 3 of 3
# Warmup Iteration   1: 2069,954 ns/op
# Warmup Iteration   2: 1857,799 ns/op
# Warmup Iteration   3: 1664,149 ns/op
# Warmup Iteration   4: 1586,673 ns/op
# Warmup Iteration   5: 1500,493 ns/op
Iteration   1: 1475,253 ns/op
Iteration   2: 1472,748 ns/op
Iteration   3: 1492,754 ns/op
Iteration   4: 1509,337 ns/op
Iteration   5: 1490,256 ns/op
Iteration   6: 1487,948 ns/op
Iteration   7: 1507,194 ns/op
Iteration   8: 1487,571 ns/op
Iteration   9: 1486,298 ns/op
Iteration  10: 1536,766 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughPatternBenchmark":
  1506,341 ±(99.9%) 21,927 ns/op [Average]
  (min, avg, max) = (1472,748, 1506,341, 1645,359), stdev = 32,819
  CI (99.9%): [1484,414, 1528,268] (assumes normal distribution)


# Run complete. Total time: 00:04:35

Benchmark                                                         Mode  Cnt     Score    Error  Units
OrdinalStringFormatBenchmark.formatThroughBuilderBenchmark        avgt   30    50,719 ±  1,139  ns/op
OrdinalStringFormatBenchmark.formatThroughConcatenationBenchmark  avgt   30    49,416 ±  0,435  ns/op
OrdinalStringFormatBenchmark.formatThroughMessageFormatBenchmark  avgt   30  1018,011 ± 12,805  ns/op
OrdinalStringFormatBenchmark.formatThroughPatternBenchmark        avgt   30  1506,341 ± 21,927  ns/op


Что вообще произошло?


1. String.format() ожидаемо оказался самым медленным результатом — это и применение регулярок, и создание вспомогательных объектов, и множество валидаций строки шаблона и аргументов. Если сравнивать с MessageFormat.format(), который у нас вне конкурса, то по наблюдениям на разных шаблонах можно получить разные результаты — в каких-то случаях быстрее один способ, в каких-то другой. В нашем случае MessageFormat.format() оказался быстрее. При этом его результат можно было ещё существенно ускорить, если переиспользовать объект MessageFormat повторно, — в этом случае будут сэкономлены ресурсы на парсинг шаблона.

2. Использование StringBuilder и обычной конкатенации дали одинаковый результат. Чуть большее время бенчмарка со StringBuilder — обман зрения результат незначительных флуктуаций.

Ещё один бенчмарк и подтверждение мифа?


Позволю себе ещё один бенчмарк. Будем форматировать строки в том виде, в каком их просит Graphite (средство для сбора метрик): 

<метрика> <значение>


Код форматирования
package ru.gnkoshelev.jbreak2018.perf_tests.strings;

import java.text.MessageFormat;

/**
 * Created by kgn on 18.03.2018.
 */
public class MetricsFormat {
    public static String formatThroughPattern(String metrics, int value, long timestamp) {
        return String.format(
                "%s %d %d",
                metrics, value, timestamp);
    }

    public static String formatThroughConcatenation(String metrics, int value, long timestamp) {
        return metrics + " " + value + " " + timestamp;
    }

    public static String formatThroughBuilder(String metrics, int value, long timestamp) {
        return new StringBuilder(metrics)
                .append(" ")
                .append(value)
                .append(" ")
                .append(timestamp)
                .toString();
    }

    public static String formatThroughMessageFormat(String metrics, int value, long timestamp) {
        return MessageFormat.format(
                "{0} {1} {2}",
                metrics, String.valueOf(value), String.valueOf(timestamp));
    }
}


И кусок бенчмарка (полный код всех бенчмарков доступен на github): 

@Fork(value = 3, warmups = 0)
@Warmup(iterations = 5, time = 1_500, timeUnit = TimeUnit.MILLISECONDS)
@Measurement(iterations = 10, time = 1_500, timeUnit = TimeUnit.MILLISECONDS)
@OutputTimeUnit(value = TimeUnit.NANOSECONDS)
@BenchmarkMode(Mode.AverageTime)
@State(Scope.Benchmark)
public class MetricsFormatBenchmark {
    public String metrics;
    public int value;
    public long timestamp;

    @Setup
    public void setup() {
        metrics = "my-awesome-project"
                + ".my-awesome-microservice-of-my-awesome-project"
                + ".my-host-for-my-awesome-microservice-of-my-awesome-project"
                + ".my-custom-metric-from-my-host-of-my-awesome-microservice-of-my-awesome-project"
                + ".p99-for-my-custom-metric-of-my-awesome-microservice-of-my-awesome-project";
        value = 1;
        timestamp = 1521331200000L;
    }

    @Benchmark
    public void formatThroughPatternBenchmark(Blackhole bh) {
        bh.consume(formatThroughPattern(metrics, value, timestamp));
    }

    @Benchmark
    public void formatThroughConcatenationBenchmark(Blackhole bh) {
        bh.consume(formatThroughConcatenation(metrics, value, timestamp));
    }

    @Benchmark
    public void formatThroughBuilderBenchmark(Blackhole bh) {
        bh.consume(formatThroughBuilder(metrics, value, timestamp));
    }

    @Benchmark
    public void formatThroughMessageFormatBuilder(Blackhole bh) {
        bh.consume(formatThroughMessageFormat(metrics, value, timestamp));
    }
}


Результаты бенчмарка: 

Benchmark                               Mode  Cnt     Score    Error  Units
...formatThroughBuilderBenchmark        avgt   30   212,410 ±  2,383  ns/op
...formatThroughConcatenationBenchmark  avgt   30   340,894 ±  1,759  ns/op
...formatThroughMessageFormatBuilder    avgt   30   747,888 ± 16,856  ns/op
...formatThroughPatternBenchmark        avgt   30  1432,906 ± 10,302  ns/op


Результаты бенчмарка целиком
# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughBuilderBenchmark

# Run progress: 0,00% complete, ETA 00:04:30
# Fork: 1 of 3
# Warmup Iteration   1: 364,237 ns/op
# Warmup Iteration   2: 225,585 ns/op
# Warmup Iteration   3: 214,730 ns/op
# Warmup Iteration   4: 208,999 ns/op
# Warmup Iteration   5: 209,362 ns/op
Iteration   1: 211,761 ns/op
Iteration   2: 210,992 ns/op
Iteration   3: 210,520 ns/op
Iteration   4: 210,215 ns/op
Iteration   5: 210,570 ns/op
Iteration   6: 211,235 ns/op
Iteration   7: 211,023 ns/op
Iteration   8: 210,616 ns/op
Iteration   9: 222,262 ns/op
Iteration  10: 224,458 ns/op

# Run progress: 8,33% complete, ETA 00:04:12
# Fork: 2 of 3
# Warmup Iteration   1: 318,609 ns/op
# Warmup Iteration   2: 206,168 ns/op
# Warmup Iteration   3: 206,740 ns/op
# Warmup Iteration   4: 210,160 ns/op
# Warmup Iteration   5: 210,540 ns/op
Iteration   1: 208,689 ns/op
Iteration   2: 209,858 ns/op
Iteration   3: 210,219 ns/op
Iteration   4: 208,769 ns/op
Iteration   5: 211,801 ns/op
Iteration   6: 208,374 ns/op
Iteration   7: 211,621 ns/op
Iteration   8: 210,325 ns/op
Iteration   9: 212,575 ns/op
Iteration  10: 213,103 ns/op

# Run progress: 16,67% complete, ETA 00:03:49
# Fork: 3 of 3
# Warmup Iteration   1: 278,328 ns/op
# Warmup Iteration   2: 205,199 ns/op
# Warmup Iteration   3: 211,429 ns/op
# Warmup Iteration   4: 212,721 ns/op
# Warmup Iteration   5: 216,514 ns/op
Iteration   1: 210,979 ns/op
Iteration   2: 214,867 ns/op
Iteration   3: 211,800 ns/op
Iteration   4: 217,169 ns/op
Iteration   5: 212,202 ns/op
Iteration   6: 210,910 ns/op
Iteration   7: 212,878 ns/op
Iteration   8: 215,043 ns/op
Iteration   9: 214,553 ns/op
Iteration  10: 212,912 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughBuilderBenchmark":
  212,410 ±(99.9%) 2,383 ns/op [Average]
  (min, avg, max) = (208,374, 212,410, 224,458), stdev = 3,566
  CI (99.9%): [210,027, 214,793] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughConcatenationBenchmark

# Run progress: 25,00% complete, ETA 00:03:26
# Fork: 1 of 3
# Warmup Iteration   1: 461,604 ns/op
# Warmup Iteration   2: 338,344 ns/op
# Warmup Iteration   3: 339,651 ns/op
# Warmup Iteration   4: 341,987 ns/op
# Warmup Iteration   5: 341,775 ns/op
Iteration   1: 340,811 ns/op
Iteration   2: 340,931 ns/op
Iteration   3: 341,112 ns/op
Iteration   4: 341,395 ns/op
Iteration   5: 338,871 ns/op
Iteration   6: 337,875 ns/op
Iteration   7: 346,943 ns/op
Iteration   8: 339,328 ns/op
Iteration   9: 335,932 ns/op
Iteration  10: 338,702 ns/op

# Run progress: 33,33% complete, ETA 00:03:03
# Fork: 2 of 3
# Warmup Iteration   1: 470,278 ns/op
# Warmup Iteration   2: 334,495 ns/op
# Warmup Iteration   3: 336,727 ns/op
# Warmup Iteration   4: 339,971 ns/op
# Warmup Iteration   5: 339,774 ns/op
Iteration   1: 339,405 ns/op
Iteration   2: 339,588 ns/op
Iteration   3: 340,777 ns/op
Iteration   4: 345,855 ns/op
Iteration   5: 342,180 ns/op
Iteration   6: 337,955 ns/op
Iteration   7: 345,554 ns/op
Iteration   8: 337,636 ns/op
Iteration   9: 345,226 ns/op
Iteration  10: 339,453 ns/op

# Run progress: 41,67% complete, ETA 00:02:40
# Fork: 3 of 3
# Warmup Iteration   1: 473,061 ns/op
# Warmup Iteration   2: 334,747 ns/op
# Warmup Iteration   3: 340,089 ns/op
# Warmup Iteration   4: 334,962 ns/op
# Warmup Iteration   5: 334,361 ns/op
Iteration   1: 338,737 ns/op
Iteration   2: 338,276 ns/op
Iteration   3: 340,775 ns/op
Iteration   4: 341,302 ns/op
Iteration   5: 342,850 ns/op
Iteration   6: 341,880 ns/op
Iteration   7: 342,687 ns/op
Iteration   8: 343,406 ns/op
Iteration   9: 341,336 ns/op
Iteration  10: 340,047 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughConcatenationBenchmark":
  340,894 ±(99.9%) 1,759 ns/op [Average]
  (min, avg, max) = (335,932, 340,894, 346,943), stdev = 2,632
  CI (99.9%): [339,136, 342,653] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughMessageFormatBuilder

# Run progress: 50,00% complete, ETA 00:02:17
# Fork: 1 of 3
# Warmup Iteration   1: 1174,256 ns/op
# Warmup Iteration   2: 955,340 ns/op
# Warmup Iteration   3: 833,853 ns/op
# Warmup Iteration   4: 743,211 ns/op
# Warmup Iteration   5: 749,805 ns/op
Iteration   1: 736,922 ns/op
Iteration   2: 739,920 ns/op
Iteration   3: 745,799 ns/op
Iteration   4: 749,026 ns/op
Iteration   5: 753,321 ns/op
Iteration   6: 756,947 ns/op
Iteration   7: 748,437 ns/op
Iteration   8: 745,221 ns/op
Iteration   9: 743,668 ns/op
Iteration  10: 749,899 ns/op

# Run progress: 58,33% complete, ETA 00:01:54
# Fork: 2 of 3
# Warmup Iteration   1: 1093,949 ns/op
# Warmup Iteration   2: 904,903 ns/op
# Warmup Iteration   3: 888,462 ns/op
# Warmup Iteration   4: 756,249 ns/op
# Warmup Iteration   5: 842,296 ns/op
Iteration   1: 729,334 ns/op
Iteration   2: 797,580 ns/op
Iteration   3: 736,540 ns/op
Iteration   4: 741,176 ns/op
Iteration   5: 731,403 ns/op
Iteration   6: 732,560 ns/op
Iteration   7: 767,631 ns/op
Iteration   8: 731,333 ns/op
Iteration   9: 731,261 ns/op
Iteration  10: 753,285 ns/op

# Run progress: 66,67% complete, ETA 00:01:31
# Fork: 3 of 3
# Warmup Iteration   1: 1156,247 ns/op
# Warmup Iteration   2: 1031,444 ns/op
# Warmup Iteration   3: 849,080 ns/op
# Warmup Iteration   4: 730,123 ns/op
# Warmup Iteration   5: 724,077 ns/op
Iteration   1: 729,569 ns/op
Iteration   2: 781,161 ns/op
Iteration   3: 716,803 ns/op
Iteration   4: 724,149 ns/op
Iteration   5: 818,748 ns/op
Iteration   6: 815,800 ns/op
Iteration   7: 728,733 ns/op
Iteration   8: 727,143 ns/op
Iteration   9: 734,503 ns/op
Iteration  10: 738,770 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughMessageFormatBuilder":
  747,888 ±(99.9%) 16,856 ns/op [Average]
  (min, avg, max) = (716,803, 747,888, 818,748), stdev = 25,229
  CI (99.9%): [731,032, 764,744] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
# VM options: 
# Warmup: 5 iterations, 1500 ms each
# Measurement: 10 iterations, 1500 ms each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Average time, time/op
# Benchmark: ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughPatternBenchmark

# Run progress: 75,00% complete, ETA 00:01:08
# Fork: 1 of 3
# Warmup Iteration   1: 2117,334 ns/op
# Warmup Iteration   2: 1622,235 ns/op
# Warmup Iteration   3: 1431,764 ns/op
# Warmup Iteration   4: 1431,065 ns/op
# Warmup Iteration   5: 1438,533 ns/op
Iteration   1: 1420,598 ns/op
Iteration   2: 1492,345 ns/op
Iteration   3: 1419,019 ns/op
Iteration   4: 1425,040 ns/op
Iteration   5: 1423,276 ns/op
Iteration   6: 1428,505 ns/op
Iteration   7: 1435,056 ns/op
Iteration   8: 1432,752 ns/op
Iteration   9: 1427,263 ns/op
Iteration  10: 1436,453 ns/op

# Run progress: 83,33% complete, ETA 00:00:45
# Fork: 2 of 3
# Warmup Iteration   1: 2111,790 ns/op
# Warmup Iteration   2: 1603,000 ns/op
# Warmup Iteration   3: 1427,974 ns/op
# Warmup Iteration   4: 1437,411 ns/op
# Warmup Iteration   5: 1438,924 ns/op
Iteration   1: 1423,295 ns/op
Iteration   2: 1429,621 ns/op
Iteration   3: 1428,471 ns/op
Iteration   4: 1434,627 ns/op
Iteration   5: 1439,802 ns/op
Iteration   6: 1441,290 ns/op
Iteration   7: 1438,296 ns/op
Iteration   8: 1441,198 ns/op
Iteration   9: 1456,831 ns/op
Iteration  10: 1443,969 ns/op

# Run progress: 91,67% complete, ETA 00:00:22
# Fork: 3 of 3
# Warmup Iteration   1: 2149,129 ns/op
# Warmup Iteration   2: 1608,200 ns/op
# Warmup Iteration   3: 1406,910 ns/op
# Warmup Iteration   4: 1413,134 ns/op
# Warmup Iteration   5: 1413,094 ns/op
Iteration   1: 1409,053 ns/op
Iteration   2: 1417,015 ns/op
Iteration   3: 1423,907 ns/op
Iteration   4: 1419,448 ns/op
Iteration   5: 1425,128 ns/op
Iteration   6: 1425,369 ns/op
Iteration   7: 1428,064 ns/op
Iteration   8: 1432,042 ns/op
Iteration   9: 1433,438 ns/op
Iteration  10: 1455,998 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughPatternBenchmark":
  1432,906 ±(99.9%) 10,302 ns/op [Average]
  (min, avg, max) = (1409,053, 1432,906, 1492,345), stdev = 15,420
  CI (99.9%): [1422,604, 1443,208] (assumes normal distribution)


# Run complete. Total time: 00:04:35

Benchmark                                                   Mode  Cnt     Score    Error  Units
MetricsFormatBenchmark.formatThroughBuilderBenchmark        avgt   30   212,410 ±  2,383  ns/op
MetricsFormatBenchmark.formatThroughConcatenationBenchmark  avgt   30   340,894 ±  1,759  ns/op
MetricsFormatBenchmark.formatThroughMessageFormatBuilder    avgt   30   747,888 ± 16,856  ns/op
MetricsFormatBenchmark.formatThroughPatternBenchmark        avgt   30  1432,906 ± 10,302  ns/op


Что вообще произошло?


1. String.format() и MessageFormat.format() нам не так интересны.

2. Результат StringBuilder оказался лучше примерно в 1.5 раза. И тут уже не до случайностей.

Глубже в байткод, дальше в исходники


Чтобы разобраться в происходящем, глянем на байткод, который получился в результате компиляции наших методов в MetricsFormat: 

  public static java.lang.String formatThroughConcatenation(java.lang.String, int, long);
    Code:
       0: new           #7                  // class java/lang/StringBuilder
       3: dup
       4: invokespecial #8                  // Method java/lang/StringBuilder."":()V
       7: aload_0
       8: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      11: ldc           #10                 // String
      13: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      16: iload_1
      17: invokevirtual #11                 // Method java/lang/StringBuilder.append:(I)Ljava/lang/StringBuilder;
      20: ldc           #10                 // String
      22: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      25: lload_2
      26: invokevirtual #12                 // Method java/lang/StringBuilder.append:(J)Ljava/lang/StringBuilder;
      29: invokevirtual #13                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      32: areturn

  public static java.lang.String formatThroughBuilder(java.lang.String, int, long);
    Code:
       0: new           #7                  // class java/lang/StringBuilder
       3: dup
       4: aload_0
       5: invokespecial #14                 // Method java/lang/StringBuilder."":(Ljava/lang/String;)V
       8: ldc           #10                 // String
      10: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      13: iload_1
      14: invokevirtual #11                 // Method java/lang/StringBuilder.append:(I)Ljava/lang/StringBuilder;
      17: ldc           #10                 // String
      19: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      22: lload_2
      23: invokevirtual #12                 // Method java/lang/StringBuilder.append:(J)Ljava/lang/StringBuilder;
      26: invokevirtual #13                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      29: areturn


Разберём в деталях, что мы видим:

  1. В методе, где была конкатенация строк, сейчас создание объекта StringBuilder.
  2. Тела методов очень похожи, но отличаются способом создания StringBuilder — в случае самописного использования StringBuilder вызывается конструктор, принимающий строку на вход, а в варианте с конкатенацией StringBuilder создаётся путём вызова пустого конструктора.
  3. В результате создания пустого StringBuilder требуется дополнительный вызов StringBuilder.append().


Как так получилось, что один единственный дополнительный вызов StringBuilder.append() привёл к снижению производительности?
Посмотрим на конструкторы: 

    public StringBuilder() {
        super(16);
    }

    public StringBuilder(String str) {
        super(str.length() + 16);
        append(str);
    }


Оказывается, что и append-то никуда не делся — он вызывается внутри конструктора. Тем не менее, ответ кроется в этом участке кода, а именно в числе 16: авторы StringBuilder предусмотрительно выделили дополнительное место под 16 символов в буфере при создании объекта.

Когда мы создали StringBuilder и положили в него первую строку metrics, передав её в конструкторе, у нас ещё оставалось 16 символов в запасе, прежде чем нужно будет расширить буфер (массив символов AbstractStringBuilder.value). По случайному совпадению два пробела, число 1 и значение timestamp уложились ровно в 16 символов.

С другой стороны, созданный пустым StringBuilder оказался не готов вместить в себя строку metrics и буфер был пересоздан. Но и тут всё оказывается не так просто.
Интересующий нас кусок кода AbstractStringBuilder: 

    public AbstractStringBuilder append(String str) {
        if (str == null)
            return appendNull();
        int len = str.length();
        ensureCapacityInternal(count + len);
        str.getChars(0, len, value, count);
        count += len;
        return this;
    }

    private void ensureCapacityInternal(int minimumCapacity) {
        // overflow-conscious code
        if (minimumCapacity - value.length > 0) {
            value = Arrays.copyOf(value,
                    newCapacity(minimumCapacity));
        }
    }

    private int newCapacity(int minCapacity) {
        // overflow-conscious code
        int newCapacity = (value.length << 1) + 2;
        if (newCapacity - minCapacity < 0) {
            newCapacity = minCapacity;
        }
        return (newCapacity <= 0 || MAX_ARRAY_SIZE - newCapacity < 0)
            ? hugeCapacity(minCapacity)
            : newCapacity;
    }


Когда в StringBuilder не хватает места при очередном append, осуществляется попытка создать буфер вдвое больший, чем был ранее (length * 2 + 2 если быть точнее).
Если не удаётся (когда в двойной буфер добавляемая строка по-прежнему не помещается, что у нас и произошло при добавлении идентификатора метрики metrics), то создаётся буфер, длина которого равна count + len, где count — уже занятое место в буфере, а len — длина добавляемой строки. В примере с нашей метрикой count == 0, а len == 275.
Таким образом, первый вызов StringBuilder.append() привёл к созданию нового массива символов с длиной 275.
Второй вызов также привёл к повторному созданию массива, так как идентификатор метрики полностью занимал весь буфер. Кроме того, что размер буфера стал равен 275 * 2 + 2 = 552, так ещё потребовалось копирование 275 символов из старого буфера. И тут уже никакой JIT не помог.

Правильный ответ на задачу


Вариант 1 самый медленный, а 2 и 3 дают одинаковый результат.


Статистика


Эта задача была самой простой из предложенных — её правильно решили 10 человек из 32 и ещё 18 участников конференции дали частично правильный ответ.

Частично правильный ответ заключался в том, что, например, методы расставлены правильно, но пояснения к ответу никакого дано не было, либо оно было верно только от части.

Самый распространённый ответ по 2 и 3 — javac выдаёт одинаковый байткод. Несмотря на то, что это не совсем так, как мы выяснили выше — данный ответ засчитывался как правильный.

Интересные факты


В одном из пояснений было верно подмечено, что компиляция конкатенации в StringBuilder не специфицирована. В разделе 15.18.1 спецификации упоминается следующее:

An implementation may choose to perform conversion and concatenation in one step to avoid creating and then discarding an intermediate String object. To increase the performance of repeated string concatenation, a Java compiler may use the StringBuffer class or a similar technique to reduce the number of intermediate String objects that are created by evaluation of an expression.


Интересно, что в спецификации к Java 8 говорится о StringBuffer, тогда как с Java 1.5 (когда появился StringBuilder) код конкатенации компилируется в StringBuilder. При этом в Java 1.4 код метода formatThroughConcatenation компилируется в байткод, единственным отличием которого является использование StringBuffer вместо StringBuilder.

Байткод в результате компиляции в Java 1.4
public java.lang.String formatThroughConcatenation(java.lang.String, java.lang.String, j
    
            
© Habrahabr.ru