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

в 9:19, , рубрики: compiler optimization, java, java 8, java 9, performance, performance optimization, string, stringbuilder, Блог компании Контур, Программирование

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

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

    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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 (средство для сбора метрик):

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

Код форматирования

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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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 FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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."<init>":()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."<init>":(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, java.lang.String, java.lang.String);
  Code:
   0:	new	#2; //class java/lang/StringBuffer
   3:	dup
   4:	invokespecial	#3; //Method java/lang/StringBuffer."<init>":()V
   7:	ldc	#4; //String Он, 
   9:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   12:	aload_1
   13:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   16:	ldc	#6; //String , придумал такие 
   18:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   21:	aload_2
   22:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   25:	ldc	#7; //String  задачи. Приду на стенд 
   27:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   30:	aload_3
   31:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   34:	ldc	#8; //String  и скажу ему 
   36:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   39:	aload	4
   41:	invokevirtual	#5; //Method java/lang/StringBuffer.append:(Ljava/lang/String;)Ljava/lang/StringBuffer;
   44:	invokevirtual	#9; //Method java/lang/StringBuffer.toString:()Ljava/lang/String;
   47:	areturn

Раз уж мы заговорили про другие версии Java, то не лишним будет попробовать собрать и прогнать бенчмарк с использованием Java 9 (JRE 9.0.4).

Benchmark                           Mode  Cnt      Score     Error  Units
Metrics...BuilderBenchmark          avgt   30    207,168 ±   4,245  ns/op
Metrics...ConcatenationBenchmark    avgt   30     56,220 ±   1,051  ns/op
Metrics...MessageFormatBuilder      avgt   30    594,952 ±  19,025  ns/op
Metrics...PatternBenchmark          avgt   30   1131,698 ±  14,363  ns/op
Ordinal...BuilderBenchmark          avgt   30     53,221 ±   1,691  ns/op
Ordinal...ConcatenationBenchmark    avgt   30     68,486 ±   1,936  ns/op
Ordinal...MessageFormatBenchmark    avgt   30   1207,907 ±  19,414  ns/op
Ordinal...PatternBenchmark          avgt   30   1972,689 ±  33,432  ns/op

Результаты бенчмарка целиком

# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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:18:00
# Fork: 1 of 3
# Warmup Iteration   1: 0,179 us/op
# Warmup Iteration   2: 0,155 us/op
# Warmup Iteration   3: 0,154 us/op
# Warmup Iteration   4: 0,154 us/op
# Warmup Iteration   5: 0,154 us/op
Iteration   1: 0,154 us/op
Iteration   2: 0,155 us/op
Iteration   3: 0,155 us/op
Iteration   4: 0,154 us/op
Iteration   5: 0,153 us/op
Iteration   6: 0,156 us/op
Iteration   7: 0,168 us/op
Iteration   8: 0,157 us/op
Iteration   9: 0,159 us/op
Iteration  10: 0,156 us/op

# Run progress: 2,08% complete, ETA 00:17:58
# Fork: 2 of 3
# Warmup Iteration   1: 0,182 us/op
# Warmup Iteration   2: 0,160 us/op
# Warmup Iteration   3: 0,154 us/op
# Warmup Iteration   4: 0,162 us/op
# Warmup Iteration   5: 0,155 us/op
Iteration   1: 0,157 us/op
Iteration   2: 0,159 us/op
Iteration   3: 0,154 us/op
Iteration   4: 0,155 us/op
Iteration   5: 0,164 us/op
Iteration   6: 0,155 us/op
Iteration   7: 0,156 us/op
Iteration   8: 0,155 us/op
Iteration   9: 0,169 us/op
Iteration  10: 0,171 us/op

# Run progress: 4,17% complete, ETA 00:17:34
# Fork: 3 of 3
# Warmup Iteration   1: 0,229 us/op
# Warmup Iteration   2: 0,218 us/op
# Warmup Iteration   3: 0,190 us/op
# Warmup Iteration   4: 0,191 us/op
# Warmup Iteration   5: 0,180 us/op
Iteration   1: 0,173 us/op
Iteration   2: 0,168 us/op
Iteration   3: 0,167 us/op
Iteration   4: 0,168 us/op
Iteration   5: 0,161 us/op
Iteration   6: 0,156 us/op
Iteration   7: 0,155 us/op
Iteration   8: 0,156 us/op
Iteration   9: 0,163 us/op
Iteration  10: 0,161 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  0,160 ±(99.9%) 0,004 us/op [Average]
  (min, avg, max) = (0,153, 0,160, 0,173), stdev = 0,006
  CI (99.9%): [0,156, 0,164] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 6,25% complete, ETA 00:17:12
# Fork: 1 of 3
# Warmup Iteration   1: 1,487 us/op
# Warmup Iteration   2: 1,376 us/op
# Warmup Iteration   3: 1,328 us/op
# Warmup Iteration   4: 1,327 us/op
# Warmup Iteration   5: 1,447 us/op
Iteration   1: 1,334 us/op
Iteration   2: 1,353 us/op
Iteration   3: 1,412 us/op
Iteration   4: 1,427 us/op
Iteration   5: 1,793 us/op
Iteration   6: 1,523 us/op
Iteration   7: 1,411 us/op
Iteration   8: 1,468 us/op
Iteration   9: 1,390 us/op
Iteration  10: 1,348 us/op

# Run progress: 8,33% complete, ETA 00:16:49
# Fork: 2 of 3
# Warmup Iteration   1: 1,483 us/op
# Warmup Iteration   2: 1,645 us/op
# Warmup Iteration   3: 1,499 us/op
# Warmup Iteration   4: 1,550 us/op
# Warmup Iteration   5: 1,527 us/op
Iteration   1: 1,591 us/op
Iteration   2: 1,596 us/op
Iteration   3: 1,668 us/op
Iteration   4: 1,784 us/op
Iteration   5: 1,733 us/op
Iteration   6: 1,498 us/op
Iteration   7: 1,532 us/op
Iteration   8: 1,566 us/op
Iteration   9: 1,524 us/op
Iteration  10: 1,334 us/op

# Run progress: 10,42% complete, ETA 00:16:26
# Fork: 3 of 3
# Warmup Iteration   1: 1,504 us/op
# Warmup Iteration   2: 1,314 us/op
# Warmup Iteration   3: 1,285 us/op
# Warmup Iteration   4: 1,290 us/op
# Warmup Iteration   5: 1,284 us/op
Iteration   1: 1,283 us/op
Iteration   2: 1,288 us/op
Iteration   3: 1,287 us/op
Iteration   4: 1,291 us/op
Iteration   5: 1,282 us/op
Iteration   6: 1,286 us/op
Iteration   7: 1,297 us/op
Iteration   8: 1,286 us/op
Iteration   9: 1,284 us/op
Iteration  10: 1,285 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  1,438 ±(99.9%) 0,107 us/op [Average]
  (min, avg, max) = (1,282, 1,438, 1,793), stdev = 0,160
  CI (99.9%): [1,331, 1,546] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 12,50% complete, ETA 00:16:04
# Fork: 1 of 3
# Warmup Iteration   1: 18,564 us/op
# Warmup Iteration   2: 15,904 us/op
# Warmup Iteration   3: 15,757 us/op
# Warmup Iteration   4: 15,458 us/op
# Warmup Iteration   5: 15,754 us/op
Iteration   1: 15,474 us/op
Iteration   2: 15,388 us/op
Iteration   3: 15,454 us/op
Iteration   4: 15,434 us/op
Iteration   5: 15,462 us/op
Iteration   6: 15,437 us/op
Iteration   7: 15,355 us/op
Iteration   8: 15,509 us/op
Iteration   9: 15,415 us/op
Iteration  10: 15,367 us/op

# Run progress: 14,58% complete, ETA 00:15:41
# Fork: 2 of 3
# Warmup Iteration   1: 17,889 us/op
# Warmup Iteration   2: 15,454 us/op
# Warmup Iteration   3: 15,469 us/op
# Warmup Iteration   4: 16,110 us/op
# Warmup Iteration   5: 15,979 us/op
Iteration   1: 15,961 us/op
Iteration   2: 17,628 us/op
Iteration   3: 16,615 us/op
Iteration   4: 16,068 us/op
Iteration   5: 16,430 us/op
Iteration   6: 16,648 us/op
Iteration   7: 14,929 us/op
Iteration   8: 15,597 us/op
Iteration   9: 18,085 us/op
Iteration  10: 16,119 us/op

# Run progress: 16,67% complete, ETA 00:15:18
# Fork: 3 of 3
# Warmup Iteration   1: 20,057 us/op
# Warmup Iteration   2: 16,204 us/op
# Warmup Iteration   3: 15,858 us/op
# Warmup Iteration   4: 16,293 us/op
# Warmup Iteration   5: 15,851 us/op
Iteration   1: 17,172 us/op
Iteration   2: 16,261 us/op
Iteration   3: 15,955 us/op
Iteration   4: 15,694 us/op
Iteration   5: 15,686 us/op
Iteration   6: 15,300 us/op
Iteration   7: 16,633 us/op
Iteration   8: 16,594 us/op
Iteration   9: 15,752 us/op
Iteration  10: 15,459 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  15,963 ±(99.9%) 0,493 us/op [Average]
  (min, avg, max) = (14,929, 15,963, 18,085), stdev = 0,738
  CI (99.9%): [15,470, 16,455] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 18,75% complete, ETA 00:14:55
# Fork: 1 of 3
# Warmup Iteration   1: 193,410 us/op
# Warmup Iteration   2: 178,965 us/op
# Warmup Iteration   3: 174,831 us/op
# Warmup Iteration   4: 174,252 us/op
# Warmup Iteration   5: 172,563 us/op
Iteration   1: 175,277 us/op
Iteration   2: 175,052 us/op
Iteration   3: 170,435 us/op
Iteration   4: 172,218 us/op
Iteration   5: 169,646 us/op
Iteration   6: 174,490 us/op
Iteration   7: 170,822 us/op
Iteration   8: 167,680 us/op
Iteration   9: 172,293 us/op
Iteration  10: 169,461 us/op

# Run progress: 20,83% complete, ETA 00:14:33
# Fork: 2 of 3
# Warmup Iteration   1: 201,756 us/op
# Warmup Iteration   2: 180,306 us/op
# Warmup Iteration   3: 177,044 us/op
# Warmup Iteration   4: 176,753 us/op
# Warmup Iteration   5: 176,762 us/op
Iteration   1: 177,181 us/op
Iteration   2: 180,288 us/op
Iteration   3: 180,234 us/op
Iteration   4: 177,654 us/op
Iteration   5: 179,481 us/op
Iteration   6: 179,769 us/op
Iteration   7: 180,273 us/op
Iteration   8: 180,923 us/op
Iteration   9: 177,576 us/op
Iteration  10: 176,988 us/op

# Run progress: 22,92% complete, ETA 00:14:10
# Fork: 3 of 3
# Warmup Iteration   1: 199,773 us/op
# Warmup Iteration   2: 191,027 us/op
# Warmup Iteration   3: 175,811 us/op
# Warmup Iteration   4: 195,435 us/op
# Warmup Iteration   5: 186,448 us/op
Iteration   1: 190,321 us/op
Iteration   2: 172,248 us/op
Iteration   3: 172,875 us/op
Iteration   4: 173,850 us/op
Iteration   5: 174,142 us/op
Iteration   6: 175,412 us/op
Iteration   7: 173,791 us/op
Iteration   8: 173,810 us/op
Iteration   9: 173,287 us/op
Iteration  10: 174,731 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.builderBenchmark":
  175,407 ±(99.9%) 3,039 us/op [Average]
  (min, avg, max) = (167,680, 175,407, 190,321), stdev = 4,549
  CI (99.9%): [172,368, 178,446] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 25,00% complete, ETA 00:13:47
# Fork: 1 of 3
# Warmup Iteration   1: 0,292 us/op
# Warmup Iteration   2: 0,251 us/op
# Warmup Iteration   3: 0,274 us/op
# Warmup Iteration   4: 0,268 us/op
# Warmup Iteration   5: 0,276 us/op
Iteration   1: 0,291 us/op
Iteration   2: 0,286 us/op
Iteration   3: 0,283 us/op
Iteration   4: 0,294 us/op
Iteration   5: 0,277 us/op
Iteration   6: 0,285 us/op
Iteration   7: 0,283 us/op
Iteration   8: 0,275 us/op
Iteration   9: 0,269 us/op
Iteration  10: 0,274 us/op

# Run progress: 27,08% complete, ETA 00:13:24
# Fork: 2 of 3
# Warmup Iteration   1: 0,309 us/op
# Warmup Iteration   2: 0,281 us/op
# Warmup Iteration   3: 0,292 us/op
# Warmup Iteration   4: 0,276 us/op
# Warmup Iteration   5: 0,280 us/op
Iteration   1: 0,277 us/op
Iteration   2: 0,268 us/op
Iteration   3: 0,283 us/op
Iteration   4: 0,301 us/op
Iteration   5: 0,290 us/op
Iteration   6: 0,275 us/op
Iteration   7: 0,273 us/op
Iteration   8: 0,291 us/op
Iteration   9: 0,293 us/op
Iteration  10: 0,274 us/op

# Run progress: 29,17% complete, ETA 00:13:02
# Fork: 3 of 3
# Warmup Iteration   1: 0,302 us/op
# Warmup Iteration   2: 0,257 us/op
# Warmup Iteration   3: 0,280 us/op
# Warmup Iteration   4: 0,272 us/op
# Warmup Iteration   5: 0,286 us/op
Iteration   1: 0,290 us/op
Iteration   2: 0,286 us/op
Iteration   3: 0,286 us/op
Iteration   4: 0,300 us/op
Iteration   5: 0,285 us/op
Iteration   6: 0,276 us/op
Iteration   7: 0,285 us/op
Iteration   8: 0,310 us/op
Iteration   9: 0,269 us/op
Iteration  10: 0,268 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  0,283 ±(99.9%) 0,007 us/op [Average]
  (min, avg, max) = (0,268, 0,283, 0,310), stdev = 0,010
  CI (99.9%): [0,276, 0,290] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 31,25% complete, ETA 00:12:39
# Fork: 1 of 3
# Warmup Iteration   1: 10,154 us/op
# Warmup Iteration   2: 7,346 us/op
# Warmup Iteration   3: 7,357 us/op
# Warmup Iteration   4: 7,376 us/op
# Warmup Iteration   5: 7,332 us/op
Iteration   1: 7,334 us/op
Iteration   2: 7,343 us/op
Iteration   3: 7,338 us/op
Iteration   4: 7,358 us/op
Iteration   5: 7,343 us/op
Iteration   6: 7,395 us/op
Iteration   7: 7,375 us/op
Iteration   8: 7,381 us/op
Iteration   9: 7,356 us/op
Iteration  10: 7,342 us/op

# Run progress: 33,33% complete, ETA 00:12:16
# Fork: 2 of 3
# Warmup Iteration   1: 10,032 us/op
# Warmup Iteration   2: 7,326 us/op
# Warmup Iteration   3: 7,247 us/op
# Warmup Iteration   4: 7,512 us/op
# Warmup Iteration   5: 8,649 us/op
Iteration   1: 7,502 us/op
Iteration   2: 7,327 us/op
Iteration   3: 7,197 us/op
Iteration   4: 8,295 us/op
Iteration   5: 7,221 us/op
Iteration   6: 7,224 us/op
Iteration   7: 7,210 us/op
Iteration   8: 7,204 us/op
Iteration   9: 7,457 us/op
Iteration  10: 8,124 us/op

# Run progress: 35,42% complete, ETA 00:11:52
# Fork: 3 of 3
# Warmup Iteration   1: 11,735 us/op
# Warmup Iteration   2: 7,658 us/op
# Warmup Iteration   3: 7,495 us/op
# Warmup Iteration   4: 7,258 us/op
# Warmup Iteration   5: 8,326 us/op
Iteration   1: 8,001 us/op
Iteration   2: 7,964 us/op
Iteration   3: 7,854 us/op
Iteration   4: 7,480 us/op
Iteration   5: 7,556 us/op
Iteration   6: 7,928 us/op
Iteration   7: 7,335 us/op
Iteration   8: 8,161 us/op
Iteration   9: 7,989 us/op
Iteration  10: 7,372 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  7,532 ±(99.9%) 0,220 us/op [Average]
  (min, avg, max) = (7,197, 7,532, 8,295), stdev = 0,329
  CI (99.9%): [7,312, 7,752] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 37,50% complete, ETA 00:11:29
# Fork: 1 of 3
# Warmup Iteration   1: 843,574 us/op
# Warmup Iteration   2: 604,431 us/op
# Warmup Iteration   3: 602,075 us/op
# Warmup Iteration   4: 605,613 us/op
# Warmup Iteration   5: 610,006 us/op
Iteration   1: 606,927 us/op
Iteration   2: 634,940 us/op
Iteration   3: 607,559 us/op
Iteration   4: 650,631 us/op
Iteration   5: 653,789 us/op
Iteration   6: 607,988 us/op
Iteration   7: 621,988 us/op
Iteration   8: 607,247 us/op
Iteration   9: 602,864 us/op
Iteration  10: 607,888 us/op

# Run progress: 39,58% complete, ETA 00:11:06
# Fork: 2 of 3
# Warmup Iteration   1: 811,900 us/op
# Warmup Iteration   2: 603,097 us/op
# Warmup Iteration   3: 603,808 us/op
# Warmup Iteration   4: 605,518 us/op
# Warmup Iteration   5: 605,703 us/op
Iteration   1: 616,120 us/op
Iteration   2: 602,626 us/op
Iteration   3: 605,618 us/op
Iteration   4: 599,532 us/op
Iteration   5: 598,845 us/op
Iteration   6: 604,046 us/op
Iteration   7: 615,308 us/op
Iteration   8: 609,050 us/op
Iteration   9: 612,949 us/op
Iteration  10: 613,524 us/op

# Run progress: 41,67% complete, ETA 00:10:43
# Fork: 3 of 3
# Warmup Iteration   1: 852,912 us/op
# Warmup Iteration   2: 707,652 us/op
# Warmup Iteration   3: 651,288 us/op
# Warmup Iteration   4: 599,827 us/op
# Warmup Iteration   5: 621,685 us/op
Iteration   1: 598,476 us/op
Iteration   2: 601,931 us/op
Iteration   3: 602,993 us/op
Iteration   4: 602,098 us/op
Iteration   5: 623,709 us/op
Iteration   6: 615,533 us/op
Iteration   7: 623,482 us/op
Iteration   8: 591,862 us/op
Iteration   9: 624,777 us/op
Iteration  10: 595,762 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  612,002 ±(99.9%) 9,759 us/op [Average]
  (min, avg, max) = (591,862, 612,002, 653,789), stdev = 14,606
  CI (99.9%): [602,244, 621,761] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 43,75% complete, ETA 00:10:20
# Fork: 1 of 3
# Warmup Iteration   1: 85359,249 us/op
# Warmup Iteration   2: 60094,054 us/op
# Warmup Iteration   3: 58604,795 us/op
# Warmup Iteration   4: 63162,713 us/op
# Warmup Iteration   5: 61908,459 us/op
Iteration   1: 58603,106 us/op
Iteration   2: 59940,727 us/op
Iteration   3: 58251,292 us/op
Iteration   4: 58429,386 us/op
Iteration   5: 58252,382 us/op
Iteration   6: 58310,251 us/op
Iteration   7: 59034,690 us/op
Iteration   8: 58480,766 us/op
Iteration   9: 58441,828 us/op
Iteration  10: 58242,481 us/op

# Run progress: 45,83% complete, ETA 00:09:58
# Fork: 2 of 3
# Warmup Iteration   1: 85157,562 us/op
# Warmup Iteration   2: 58764,257 us/op
# Warmup Iteration   3: 58987,052 us/op
# Warmup Iteration   4: 61368,128 us/op
# Warmup Iteration   5: 59257,690 us/op
Iteration   1: 60699,151 us/op
Iteration   2: 59754,186 us/op
Iteration   3: 60091,361 us/op
Iteration   4: 61224,621 us/op
Iteration   5: 58651,375 us/op
Iteration   6: 58365,153 us/op
Iteration   7: 58962,688 us/op
Iteration   8: 58993,352 us/op
Iteration   9: 58819,427 us/op
Iteration  10: 58550,841 us/op

# Run progress: 47,92% complete, ETA 00:09:35
# Fork: 3 of 3
# Warmup Iteration   1: 85371,543 us/op
# Warmup Iteration   2: 58821,258 us/op
# Warmup Iteration   3: 58546,736 us/op
# Warmup Iteration   4: 58518,930 us/op
# Warmup Iteration   5: 59124,297 us/op
Iteration   1: 58823,911 us/op
Iteration   2: 58633,122 us/op
Iteration   3: 58459,387 us/op
Iteration   4: 58571,716 us/op
Iteration   5: 58584,158 us/op
Iteration   6: 58584,505 us/op
Iteration   7: 58472,397 us/op
Iteration   8: 58647,381 us/op
Iteration   9: 64360,849 us/op
Iteration  10: 60359,720 us/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.ImmutableStringBenchmark.concatenationBenchmark":
  59119,874 ±(99.9%) 841,652 us/op [Average]
  (min, avg, max) = (58242,481, 59119,874, 64360,849), stdev = 1259,746
  CI (99.9%): [58278,221, 59961,526] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 50,00% complete, ETA 00:09:13
# Fork: 1 of 3
# Warmup Iteration   1: 262,703 ns/op
# Warmup Iteration   2: 213,253 ns/op
# Warmup Iteration   3: 214,540 ns/op
# Warmup Iteration   4: 211,447 ns/op
# Warmup Iteration   5: 211,299 ns/op
Iteration   1: 212,265 ns/op
Iteration   2: 210,657 ns/op
Iteration   3: 212,277 ns/op
Iteration   4: 219,824 ns/op
Iteration   5: 225,531 ns/op
Iteration   6: 206,097 ns/op
Iteration   7: 204,751 ns/op
Iteration   8: 211,672 ns/op
Iteration   9: 209,949 ns/op
Iteration  10: 208,630 ns/op

# Run progress: 52,08% complete, ETA 00:08:49
# Fork: 2 of 3
# Warmup Iteration   1: 263,284 ns/op
# Warmup Iteration   2: 200,613 ns/op
# Warmup Iteration   3: 194,637 ns/op
# Warmup Iteration   4: 195,592 ns/op
# Warmup Iteration   5: 198,620 ns/op
Iteration   1: 198,124 ns/op
Iteration   2: 199,164 ns/op
Iteration   3: 199,169 ns/op
Iteration   4: 208,831 ns/op
Iteration   5: 215,353 ns/op
Iteration   6: 205,850 ns/op
Iteration   7: 201,657 ns/op
Iteration   8: 212,089 ns/op
Iteration   9: 206,610 ns/op
Iteration  10: 201,656 ns/op

# Run progress: 54,17% complete, ETA 00:08:26
# Fork: 3 of 3
# Warmup Iteration   1: 261,702 ns/op
# Warmup Iteration   2: 197,009 ns/op
# Warmup Iteration   3: 202,197 ns/op
# Warmup Iteration   4: 203,103 ns/op
# Warmup Iteration   5: 210,418 ns/op
Iteration   1: 205,722 ns/op
Iteration   2: 204,451 ns/op
Iteration   3: 209,910 ns/op
Iteration   4: 203,296 ns/op
Iteration   5: 203,002 ns/op
Iteration   6: 207,542 ns/op
Iteration   7: 209,387 ns/op
Iteration   8: 202,788 ns/op
Iteration   9: 197,077 ns/op
Iteration  10: 201,708 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughBuilderBenchmark":
  207,168 ±(99.9%) 4,245 ns/op [Average]
  (min, avg, max) = (197,077, 207,168, 225,531), stdev = 6,353
  CI (99.9%): [202,923, 211,413] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 56,25% complete, ETA 00:08:03
# Fork: 1 of 3
# Warmup Iteration   1: 77,890 ns/op
# Warmup Iteration   2: 60,084 ns/op
# Warmup Iteration   3: 61,112 ns/op
# Warmup Iteration   4: 64,259 ns/op
# Warmup Iteration   5: 63,863 ns/op
Iteration   1: 58,276 ns/op
Iteration   2: 56,546 ns/op
Iteration   3: 56,680 ns/op
Iteration   4: 56,652 ns/op
Iteration   5: 57,838 ns/op
Iteration   6: 58,543 ns/op
Iteration   7: 56,616 ns/op
Iteration   8: 56,765 ns/op
Iteration   9: 56,704 ns/op
Iteration  10: 56,496 ns/op

# Run progress: 58,33% complete, ETA 00:07:40
# Fork: 2 of 3
# Warmup Iteration   1: 79,029 ns/op
# Warmup Iteration   2: 60,338 ns/op
# Warmup Iteration   3: 56,450 ns/op
# Warmup Iteration   4: 56,621 ns/op
# Warmup Iteration   5: 56,712 ns/op
Iteration   1: 56,811 ns/op
Iteration   2: 56,772 ns/op
Iteration   3: 58,599 ns/op
Iteration   4: 58,018 ns/op
Iteration   5: 57,401 ns/op
Iteration   6: 57,331 ns/op
Iteration   7: 56,742 ns/op
Iteration   8: 56,869 ns/op
Iteration   9: 56,881 ns/op
Iteration  10: 56,639 ns/op

# Run progress: 60,42% complete, ETA 00:07:17
# Fork: 3 of 3
# Warmup Iteration   1: 71,819 ns/op
# Warmup Iteration   2: 53,982 ns/op
# Warmup Iteration   3: 53,217 ns/op
# Warmup Iteration   4: 53,991 ns/op
# Warmup Iteration   5: 53,129 ns/op
Iteration   1: 53,270 ns/op
Iteration   2: 53,306 ns/op
Iteration   3: 54,263 ns/op
Iteration   4: 53,325 ns/op
Iteration   5: 54,777 ns/op
Iteration   6: 53,585 ns/op
Iteration   7: 56,112 ns/op
Iteration   8: 55,468 ns/op
Iteration   9: 53,991 ns/op
Iteration  10: 55,320 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughConcatenationBenchmark":
  56,220 ±(99.9%) 1,051 ns/op [Average]
  (min, avg, max) = (53,270, 56,220, 58,599), stdev = 1,573
  CI (99.9%): [55,169, 57,271] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 62,50% complete, ETA 00:06:54
# Fork: 1 of 3
# Warmup Iteration   1: 938,402 ns/op
# Warmup Iteration   2: 777,569 ns/op
# Warmup Iteration   3: 675,804 ns/op
# Warmup Iteration   4: 578,318 ns/op
# Warmup Iteration   5: 617,798 ns/op
Iteration   1: 595,885 ns/op
Iteration   2: 582,897 ns/op
Iteration   3: 581,880 ns/op
Iteration   4: 583,899 ns/op
Iteration   5: 587,891 ns/op
Iteration   6: 582,556 ns/op
Iteration   7: 573,807 ns/op
Iteration   8: 580,034 ns/op
Iteration   9: 580,055 ns/op
Iteration  10: 600,465 ns/op

# Run progress: 64,58% complete, ETA 00:06:31
# Fork: 2 of 3
# Warmup Iteration   1: 917,728 ns/op
# Warmup Iteration   2: 778,207 ns/op
# Warmup Iteration   3: 701,344 ns/op
# Warmup Iteration   4: 614,129 ns/op
# Warmup Iteration   5: 657,221 ns/op
Iteration   1: 607,015 ns/op
Iteration   2: 612,909 ns/op
Iteration   3: 583,067 ns/op
Iteration   4: 578,083 ns/op
Iteration   5: 581,597 ns/op
Iteration   6: 584,794 ns/op
Iteration   7: 579,920 ns/op
Iteration   8: 582,049 ns/op
Iteration   9: 580,960 ns/op
Iteration  10: 577,774 ns/op

# Run progress: 66,67% complete, ETA 00:06:08
# Fork: 3 of 3
# Warmup Iteration   1: 976,629 ns/op
# Warmup Iteration   2: 793,514 ns/op
# Warmup Iteration   3: 684,222 ns/op
# Warmup Iteration   4: 614,079 ns/op
# Warmup Iteration   5: 585,099 ns/op
Iteration   1: 699,791 ns/op
Iteration   2: 666,016 ns/op
Iteration   3: 619,701 ns/op
Iteration   4: 579,987 ns/op
Iteration   5: 576,779 ns/op
Iteration   6: 638,863 ns/op
Iteration   7: 607,345 ns/op
Iteration   8: 582,039 ns/op
Iteration   9: 579,164 ns/op
Iteration  10: 581,331 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughMessageFormatBuilder":
  594,952 ±(99.9%) 19,025 ns/op [Average]
  (min, avg, max) = (573,807, 594,952, 699,791), stdev = 28,475
  CI (99.9%): [575,927, 613,977] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 68,75% complete, ETA 00:05:45
# Fork: 1 of 3
# Warmup Iteration   1: 2299,834 ns/op
# Warmup Iteration   2: 1192,569 ns/op
# Warmup Iteration   3: 1119,558 ns/op
# Warmup Iteration   4: 1117,464 ns/op
# Warmup Iteration   5: 1113,444 ns/op
Iteration   1: 1114,229 ns/op
Iteration   2: 1113,023 ns/op
Iteration   3: 1112,185 ns/op
Iteration   4: 1108,222 ns/op
Iteration   5: 1108,988 ns/op
Iteration   6: 1108,674 ns/op
Iteration   7: 1109,976 ns/op
Iteration   8: 1109,831 ns/op
Iteration   9: 1109,610 ns/op
Iteration  10: 1107,814 ns/op

# Run progress: 70,83% complete, ETA 00:05:22
# Fork: 2 of 3
# Warmup Iteration   1: 2304,824 ns/op
# Warmup Iteration   2: 1199,471 ns/op
# Warmup Iteration   3: 1132,885 ns/op
# Warmup Iteration   4: 1129,351 ns/op
# Warmup Iteration   5: 1127,920 ns/op
Iteration   1: 1125,261 ns/op
Iteration   2: 1127,166 ns/op
Iteration   3: 1141,141 ns/op
Iteration   4: 1124,300 ns/op
Iteration   5: 1125,081 ns/op
Iteration   6: 1126,538 ns/op
Iteration   7: 1125,685 ns/op
Iteration   8: 1130,100 ns/op
Iteration   9: 1176,107 ns/op
Iteration  10: 1154,583 ns/op

# Run progress: 72,92% complete, ETA 00:04:59
# Fork: 3 of 3
# Warmup Iteration   1: 2358,123 ns/op
# Warmup Iteration   2: 1352,622 ns/op
# Warmup Iteration   3: 1156,702 ns/op
# Warmup Iteration   4: 1149,448 ns/op
# Warmup Iteration   5: 1149,654 ns/op
Iteration   1: 1147,214 ns/op
Iteration   2: 1180,265 ns/op
Iteration   3: 1181,957 ns/op
Iteration   4: 1155,407 ns/op
Iteration   5: 1140,645 ns/op
Iteration   6: 1133,507 ns/op
Iteration   7: 1139,044 ns/op
Iteration   8: 1139,680 ns/op
Iteration   9: 1137,071 ns/op
Iteration  10: 1137,626 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughPatternBenchmark":
  1131,698 ±(99.9%) 14,363 ns/op [Average]
  (min, avg, max) = (1107,814, 1131,698, 1181,957), stdev = 21,499
  CI (99.9%): [1117,334, 1146,061] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 75,00% complete, ETA 00:04:36
# Fork: 1 of 3
# Warmup Iteration   1: 60,124 ns/op
# Warmup Iteration   2: 53,887 ns/op
# Warmup Iteration   3: 50,428 ns/op
# Warmup Iteration   4: 53,202 ns/op
# Warmup Iteration   5: 51,629 ns/op
Iteration   1: 54,842 ns/op
Iteration   2: 59,136 ns/op
Iteration   3: 52,904 ns/op
Iteration   4: 53,913 ns/op
Iteration   5: 52,834 ns/op
Iteration   6: 54,876 ns/op
Iteration   7: 52,038 ns/op
Iteration   8: 51,615 ns/op
Iteration   9: 53,753 ns/op
Iteration  10: 55,080 ns/op

# Run progress: 77,08% complete, ETA 00:04:12
# Fork: 2 of 3
# Warmup Iteration   1: 69,893 ns/op
# Warmup Iteration   2: 70,767 ns/op
# Warmup Iteration   3: 54,095 ns/op
# Warmup Iteration   4: 52,366 ns/op
# Warmup Iteration   5: 51,154 ns/op
Iteration   1: 53,590 ns/op
Iteration   2: 59,785 ns/op
Iteration   3: 54,607 ns/op
Iteration   4: 53,504 ns/op
Iteration   5: 53,435 ns/op
Iteration   6: 53,093 ns/op
Iteration   7: 55,045 ns/op
Iteration   8: 56,632 ns/op
Iteration   9: 53,294 ns/op
Iteration  10: 53,475 ns/op

# Run progress: 79,17% complete, ETA 00:03:49
# Fork: 3 of 3
# Warmup Iteration   1: 67,840 ns/op
# Warmup Iteration   2: 60,608 ns/op
# Warmup Iteration   3: 55,115 ns/op
# Warmup Iteration   4: 51,854 ns/op
# Warmup Iteration   5: 51,892 ns/op
Iteration   1: 50,344 ns/op
Iteration   2: 52,877 ns/op
Iteration   3: 49,468 ns/op
Iteration   4: 49,513 ns/op
Iteration   5: 49,646 ns/op
Iteration   6: 49,113 ns/op
Iteration   7: 50,870 ns/op
Iteration   8: 51,113 ns/op
Iteration   9: 52,482 ns/op
Iteration  10: 53,757 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughBuilderBenchmark":
  53,221 ±(99.9%) 1,691 ns/op [Average]
  (min, avg, max) = (49,113, 53,221, 59,785), stdev = 2,531
  CI (99.9%): [51,530, 54,912] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 81,25% complete, ETA 00:03:26
# Fork: 1 of 3
# Warmup Iteration   1: 83,417 ns/op
# Warmup Iteration   2: 68,292 ns/op
# Warmup Iteration   3: 67,835 ns/op
# Warmup Iteration   4: 68,365 ns/op
# Warmup Iteration   5: 67,227 ns/op
Iteration   1: 70,120 ns/op
Iteration   2: 76,220 ns/op
Iteration   3: 69,923 ns/op
Iteration   4: 70,066 ns/op
Iteration   5: 70,546 ns/op
Iteration   6: 73,056 ns/op
Iteration   7: 74,891 ns/op
Iteration   8: 71,014 ns/op
Iteration   9: 71,251 ns/op
Iteration  10: 68,057 ns/op

# Run progress: 83,33% complete, ETA 00:03:03
# Fork: 2 of 3
# Warmup Iteration   1: 86,203 ns/op
# Warmup Iteration   2: 70,289 ns/op
# Warmup Iteration   3: 68,240 ns/op
# Warmup Iteration   4: 66,329 ns/op
# Warmup Iteration   5: 68,189 ns/op
Iteration   1: 70,755 ns/op
Iteration   2: 70,378 ns/op
Iteration   3: 66,964 ns/op
Iteration   4: 68,902 ns/op
Iteration   5: 66,020 ns/op
Iteration   6: 68,630 ns/op
Iteration   7: 67,040 ns/op
Iteration   8: 68,076 ns/op
Iteration   9: 66,649 ns/op
Iteration  10: 67,851 ns/op

# Run progress: 85,42% complete, ETA 00:02:41
# Fork: 3 of 3
# Warmup Iteration   1: 80,438 ns/op
# Warmup Iteration   2: 66,941 ns/op
# Warmup Iteration   3: 66,932 ns/op
# Warmup Iteration   4: 66,243 ns/op
# Warmup Iteration   5: 65,965 ns/op
Iteration   1: 66,020 ns/op
Iteration   2: 65,198 ns/op
Iteration   3: 66,240 ns/op
Iteration   4: 65,758 ns/op
Iteration   5: 65,622 ns/op
Iteration   6: 65,821 ns/op
Iteration   7: 65,357 ns/op
Iteration   8: 66,522 ns/op
Iteration   9: 65,876 ns/op
Iteration  10: 65,746 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughConcatenationBenchmark":
  68,486 ±(99.9%) 1,936 ns/op [Average]
  (min, avg, max) = (65,198, 68,486, 76,220), stdev = 2,897
  CI (99.9%): [66,550, 70,421] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 87,50% complete, ETA 00:02:18
# Fork: 1 of 3
# Warmup Iteration   1: 1721,971 ns/op
# Warmup Iteration   2: 1404,417 ns/op
# Warmup Iteration   3: 1288,016 ns/op
# Warmup Iteration   4: 1221,914 ns/op
# Warmup Iteration   5: 1148,926 ns/op
Iteration   1: 1167,718 ns/op
Iteration   2: 1200,962 ns/op
Iteration   3: 1279,375 ns/op
Iteration   4: 1189,680 ns/op
Iteration   5: 1194,886 ns/op
Iteration   6: 1155,321 ns/op
Iteration   7: 1263,725 ns/op
Iteration   8: 1216,670 ns/op
Iteration   9: 1214,617 ns/op
Iteration  10: 1183,180 ns/op

# Run progress: 89,58% complete, ETA 00:01:55
# Fork: 2 of 3
# Warmup Iteration   1: 1687,903 ns/op
# Warmup Iteration   2: 1448,192 ns/op
# Warmup Iteration   3: 1379,461 ns/op
# Warmup Iteration   4: 1276,630 ns/op
# Warmup Iteration   5: 1295,725 ns/op
Iteration   1: 1211,845 ns/op
Iteration   2: 1198,077 ns/op
Iteration   3: 1212,626 ns/op
Iteration   4: 1186,964 ns/op
Iteration   5: 1239,643 ns/op
Iteration   6: 1222,036 ns/op
Iteration   7: 1275,295 ns/op
Iteration   8: 1213,864 ns/op
Iteration   9: 1212,271 ns/op
Iteration  10: 1242,831 ns/op

# Run progress: 91,67% complete, ETA 00:01:31
# Fork: 3 of 3
# Warmup Iteration   1: 1765,377 ns/op
# Warmup Iteration   2: 1601,591 ns/op
# Warmup Iteration   3: 1314,168 ns/op
# Warmup Iteration   4: 1185,941 ns/op
# Warmup Iteration   5: 1187,965 ns/op
Iteration   1: 1188,869 ns/op
Iteration   2: 1187,571 ns/op
Iteration   3: 1189,977 ns/op
Iteration   4: 1186,874 ns/op
Iteration   5: 1188,421 ns/op
Iteration   6: 1195,331 ns/op
Iteration   7: 1190,250 ns/op
Iteration   8: 1216,980 ns/op
Iteration   9: 1189,504 ns/op
Iteration  10: 1221,858 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughMessageFormatBenchmark":
  1207,907 ±(99.9%) 19,414 ns/op [Average]
  (min, avg, max) = (1155,321, 1207,907, 1279,375), stdev = 29,058
  CI (99.9%): [1188,493, 1227,322] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 9.0.4, VM 9.0.4+11
# VM invoker: C:Program FilesJavajre-9.0.4binjava.exe
# VM options: <none>
# 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: 93,75% complete, ETA 00:01:08
# Fork: 1 of 3
# Warmup Iteration   1: 3552,804 ns/op
# Warmup Iteration   2: 2018,183 ns/op
# Warmup Iteration   3: 2019,489 ns/op
# Warmup Iteration   4: 1971,642 ns/op
# Warmup Iteration   5: 1958,374 ns/op
Iteration   1: 1951,968 ns/op
Iteration   2: 1950,212 ns/op
Iteration   3: 1953,115 ns/op
Iteration   4: 1961,593 ns/op
Iteration   5: 1958,681 ns/op
Iteration   6: 1958,468 ns/op
Iteration   7: 1951,402 ns/op
Iteration   8: 1953,397 ns/op
Iteration   9: 1952,821 ns/op
Iteration  10: 2014,765 ns/op

# Run progress: 95,83% complete, ETA 00:00:45
# Fork: 2 of 3
# Warmup Iteration   1: 3928,522 ns/op
# Warmup Iteration   2: 2167,959 ns/op
# Warmup Iteration   3: 2066,428 ns/op
# Warmup Iteration   4: 1972,538 ns/op
# Warmup Iteration   5: 1948,498 ns/op
Iteration   1: 1948,707 ns/op
Iteration   2: 2003,769 ns/op
Iteration   3: 1974,530 ns/op
Iteration   4: 1944,253 ns/op
Iteration   5: 1973,301 ns/op
Iteration   6: 2066,764 ns/op
Iteration   7: 2128,009 ns/op
Iteration   8: 2042,947 ns/op
Iteration   9: 2052,664 ns/op
Iteration  10: 2049,175 ns/op

# Run progress: 97,92% complete, ETA 00:00:22
# Fork: 3 of 3
# Warmup Iteration   1: 2954,069 ns/op
# Warmup Iteration   2: 2011,884 ns/op
# Warmup Iteration   3: 1934,112 ns/op
# Warmup Iteration   4: 1929,191 ns/op
# Warmup Iteration   5: 1924,142 ns/op
Iteration   1: 1966,331 ns/op
Iteration   2: 1972,040 ns/op
Iteration   3: 1935,918 ns/op
Iteration   4: 1917,124 ns/op
Iteration   5: 1931,921 ns/op
Iteration   6: 1915,141 ns/op
Iteration   7: 1963,801 ns/op
Iteration   8: 1934,464 ns/op
Iteration   9: 1931,712 ns/op
Iteration  10: 1921,676 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.OrdinalStringFormatBenchmark.formatThroughPatternBenchmark":
  1972,689 ±(99.9%) 33,432 ns/op [Average]
  (min, avg, max) = (1915,141, 1972,689, 2128,009), stdev = 50,040
  CI (99.9%): [1939,257, 2006,121] (assumes normal distribution)


# Run complete. Total time: 00:18:23

Benchmark                                                           (N)  Mode  Cnt      Score     Error  Units
ImmutableStringBenchmark.builderBenchmark                            10  avgt   30      0,160 ±   0,004  us/op
ImmutableStringBenchmark.builderBenchmark                           100  avgt   30      1,438 ±   0,107  us/op
ImmutableStringBenchmark.builderBenchmark                          1000  avgt   30     15,963 ±   0,493  us/op
ImmutableStringBenchmark.builderBenchmark                         10000  avgt   30    175,407 ±   3,039  us/op
ImmutableStringBenchmark.concatenationBenchmark                      10  avgt   30      0,283 ±   0,007  us/op
ImmutableStringBenchmark.concatenationBenchmark                     100  avgt   30      7,532 ±   0,220  us/op
ImmutableStringBenchmark.concatenationBenchmark                    1000  avgt   30    612,002 ±   9,759  us/op
ImmutableStringBenchmark.concatenationBenchmark                   10000  avgt   30  59119,874 ± 841,652  us/op
MetricsFormatBenchmark.formatThroughBuilderBenchmark                N/A  avgt   30    207,168 ±   4,245  ns/op
MetricsFormatBenchmark.formatThroughConcatenationBenchmark          N/A  avgt   30     56,220 ±   1,051  ns/op
MetricsFormatBenchmark.formatThroughMessageFormatBuilder            N/A  avgt   30    594,952 ±  19,025  ns/op
MetricsFormatBenchmark.formatThroughPatternBenchmark                N/A  avgt   30   1131,698 ±  14,363  ns/op
OrdinalStringFormatBenchmark.formatThroughBuilderBenchmark          N/A  avgt   30     53,221 ±   1,691  ns/op
OrdinalStringFormatBenchmark.formatThroughConcatenationBenchmark    N/A  avgt   30     68,486 ±   1,936  ns/op
OrdinalStringFormatBenchmark.formatThroughMessageFormatBenchmark    N/A  avgt   30   1207,907 ±  19,414  ns/op
OrdinalStringFormatBenchmark.formatThroughPatternBenchmark          N/A  avgt   30   1972,689 ±  33,432  ns/op

Неожиданный результат! Возможно даже для тех, кто внимательно следил за изменениями в Java 9: JEP-280.
Смотрим в генерируемый байткод для MetricsFormat:

  public static java.lang.String formatThroughConcatenation(java.lang.String, int, long);
    Code:
       0: aload_0
       1: iload_1
       2: lload_2
       3: invokedynamic #7,  0              // InvokeDynamic #0:makeConcatWithConstants:(Ljava/lang/String;IJ)Ljava/lang/String;
       8: areturn

и байткод для OrdinalStringFormat:

  public static java.lang.String formatThroughConcatenation(java.lang.String, java.lang.String, java.lang.String, java.lang.String);
    Code:
       0: aload_0
       1: aload_1
       2: aload_2
       3: aload_3
       4: invokedynamic #5,  0              // InvokeDynamic #0:makeConcatWithConstants:(Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)Ljava/lang/String;
       9: areturn

За генерацию специализированных методов makeConcatWithConstants отвечает StringConcatFactory. Специализация заключается в том, что для каждого случая генерируется отдельный метод: для MetricsFormat создался makeConcatWithConstants-метод, принимающий String, int и long, а из тела MetricsFormat.formatThroughConcatenation() ушла загрузка строковых констант (опкод ldc).
И вот тут-то JIT-компилятор может хорошо покуражиться, что оказалось весьма заметно для форматирования строки с метрикой — результат оказался лучше StringBuilder в 4 раза!
Но так может получаться не всегда, как в случае примера из нашей задачи — результат хуже примерно на четверть. Результат получился хуже как относительно StringBuilder, так и по отношению к результату на Java 8.

Заключение

За рамками обсуждения остались compile-time оптимизации конкатенаций, о которых можно почитать в разделе спецификации, на который уже ссылался ранее (15.18.1), что тоже довольно любопытно.

Выдержка из спецификации

Example 15.18.1-1. String Concatenation

The example expression:

«The square root of 2 is » + Math.sqrt(2)

produces the result:

«The square root of 2 is 1.4142135623730952»

The + operator is syntactically left-associative, no matter whether it is determined by type analysis to represent string concatenation or numeric addition. In some cases care is required to get the desired result. For example, the expression:

a + b + c

is always regarded as meaning:

(a + b) + c

Therefore the result of the expression:

1 + 2 + " fiddlers"

is:

«3 fiddlers»

but the result of:

«fiddlers » + 1 + 2

is:

«fiddlers 12»

И остались без внимания незачейненные вызовы StringBuilder.append() и разбитые на несколько независимых действий конкатенации. Хотя…
Вот для таких методов

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

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

генерируется такой байткод:

Байткод

  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."<init>":()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: invokevirtual #11                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      19: ast   ore        4
      21: new           #7                  // class java/lang/StringBuilder
      24: dup
      25: invokespecial #8                  // Method java/lang/StringBuilder."<init>":()V
      28: aload         4
      30: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      33: iload_1
      34: invokevirtual #12                 // Method java/lang/StringBuilder.append:(I)Ljava/lang/StringBuilder;
      37: ldc           #10                 // String
      39: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      42: invokevirtual #11                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      45: astore        4
      47: new           #7                  // class java/lang/StringBuilder
      50: dup
      51: invokespecial #8                  // Method java/lang/StringBuilder."<init>":()V
      54: aload         4
      56: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      59: lload_2
      60: invokevirtual #13                 // Method java/lang/StringBuilder.append:(J)Ljava/lang/StringBuilder;
      63: invokevirtual #11                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      66: astore        4
      68: aload         4
      70: 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."<init>":(Ljava/lang/String;)V
       8: astore        4
      10: aload         4
      12: ldc           #10                 // String
      14: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      17: pop
      18: aload         4
      20: iload_1
      21: invokevirtual #12                 // Method java/lang/StringBuilder.append:(I)Ljava/lang/StringBuilder;
      24: pop
      25: aload         4
      27: ldc           #10                 // String
      29: invokevirtual #9                  // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      32: pop
      33: aload         4
      35: lload_2
      36: invokevirtual #13                 // Method java/lang/StringBuilder.append:(J)Ljava/lang/StringBuilder;
      39: pop
      40: aload         4
      42: invokevirtual #11                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      45: areturn

В обоих случаях видно, что javac не предпринял каких-либо попыток для оптимизации этого. При этом в случае конкатенации теперь создаётся аж 3 экземпляра StringBuilder, второй метод тоже потяжелел.
Как это отразилось на производительности?

Benchmark                         Mode  Cnt     Score    Error  Units
Metrics...BuilderBenchmark        avgt   30   196,029 ±  4,408  ns/op
Metrics...ConcatenationBenchmark  avgt   30   444,483 ± 15,958  ns/op
Metrics...MessageFormatBuilder    avgt   30   742,672 ± 12,152  ns/op
Metrics...PatternBenchmark        avgt   30  1460,832 ± 24,075  ns/op

Результаты бенчмарка целиком

# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:Program FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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: 271,429 ns/op
# Warmup Iteration   2: 196,309 ns/op
# Warmup Iteration   3: 199,026 ns/op
# Warmup Iteration   4: 204,715 ns/op
# Warmup Iteration   5: 211,038 ns/op
Iteration   1: 203,765 ns/op
Iteration   2: 222,851 ns/op
Iteration   3: 206,074 ns/op
Iteration   4: 190,166 ns/op
Iteration   5: 194,417 ns/op
Iteration   6: 193,172 ns/op
Iteration   7: 198,825 ns/op
Iteration   8: 195,664 ns/op
Iteration   9: 199,013 ns/op
Iteration  10: 193,255 ns/op

# Run progress: 8,33% complete, ETA 00:04:12
# Fork: 2 of 3
# Warmup Iteration   1: 260,478 ns/op
# Warmup Iteration   2: 187,885 ns/op
# Warmup Iteration   3: 190,952 ns/op
# Warmup Iteration   4: 190,522 ns/op
# Warmup Iteration   5: 188,620 ns/op
Iteration   1: 189,690 ns/op
Iteration   2: 189,475 ns/op
Iteration   3: 190,417 ns/op
Iteration   4: 189,153 ns/op
Iteration   5: 188,654 ns/op
Iteration   6: 195,455 ns/op
Iteration   7: 196,520 ns/op
Iteration   8: 198,637 ns/op
Iteration   9: 197,228 ns/op
Iteration  10: 192,514 ns/op

# Run progress: 16,67% complete, ETA 00:03:49
# Fork: 3 of 3
# Warmup Iteration   1: 264,150 ns/op
# Warmup Iteration   2: 189,343 ns/op
# Warmup Iteration   3: 192,978 ns/op
# Warmup Iteration   4: 192,287 ns/op
# Warmup Iteration   5: 191,892 ns/op
Iteration   1: 196,412 ns/op
Iteration   2: 193,130 ns/op
Iteration   3: 193,759 ns/op
Iteration   4: 194,552 ns/op
Iteration   5: 194,657 ns/op
Iteration   6: 194,341 ns/op
Iteration   7: 196,031 ns/op
Iteration   8: 195,504 ns/op
Iteration   9: 203,200 ns/op
Iteration  10: 194,339 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughBuilderBenchmark":
  196,029 ±(99.9%) 4,408 ns/op [Average]
  (min, avg, max) = (188,654, 196,029, 222,851), stdev = 6,598
  CI (99.9%): [191,621, 200,437] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:Program FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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: 631,123 ns/op
# Warmup Iteration   2: 422,155 ns/op
# Warmup Iteration   3: 426,209 ns/op
# Warmup Iteration   4: 448,415 ns/op
# Warmup Iteration   5: 446,539 ns/op
Iteration   1: 422,996 ns/op
Iteration   2: 475,941 ns/op
Iteration   3: 461,148 ns/op
Iteration   4: 431,991 ns/op
Iteration   5: 450,734 ns/op
Iteration   6: 516,239 ns/op
Iteration   7: 431,390 ns/op
Iteration   8: 432,352 ns/op
Iteration   9: 452,826 ns/op
Iteration  10: 425,379 ns/op

# Run progress: 33,33% complete, ETA 00:03:03
# Fork: 2 of 3
# Warmup Iteration   1: 693,705 ns/op
# Warmup Iteration   2: 463,112 ns/op
# Warmup Iteration   3: 445,281 ns/op
# Warmup Iteration   4: 457,800 ns/op
# Warmup Iteration   5: 453,018 ns/op
Iteration   1: 437,737 ns/op
Iteration   2: 427,742 ns/op
Iteration   3: 443,569 ns/op
Iteration   4: 501,467 ns/op
Iteration   5: 446,490 ns/op
Iteration   6: 426,738 ns/op
Iteration   7: 427,594 ns/op
Iteration   8: 461,360 ns/op
Iteration   9: 425,101 ns/op
Iteration  10: 452,461 ns/op

# Run progress: 41,67% complete, ETA 00:02:40
# Fork: 3 of 3
# Warmup Iteration   1: 635,491 ns/op
# Warmup Iteration   2: 443,077 ns/op
# Warmup Iteration   3: 442,987 ns/op
# Warmup Iteration   4: 431,363 ns/op
# Warmup Iteration   5: 426,921 ns/op
Iteration   1: 433,445 ns/op
Iteration   2: 429,941 ns/op
Iteration   3: 438,845 ns/op
Iteration   4: 427,774 ns/op
Iteration   5: 426,440 ns/op
Iteration   6: 424,521 ns/op
Iteration   7: 430,905 ns/op
Iteration   8: 490,199 ns/op
Iteration   9: 449,060 ns/op
Iteration  10: 432,094 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughConcatenationBenchmark":
  444,483 ±(99.9%) 15,958 ns/op [Average]
  (min, avg, max) = (422,996, 444,483, 516,239), stdev = 23,886
  CI (99.9%): [428,524, 460,441] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:Program FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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: 1161,265 ns/op
# Warmup Iteration   2: 998,957 ns/op
# Warmup Iteration   3: 845,871 ns/op
# Warmup Iteration   4: 742,562 ns/op
# Warmup Iteration   5: 735,021 ns/op
Iteration   1: 734,366 ns/op
Iteration   2: 742,179 ns/op
Iteration   3: 723,182 ns/op
Iteration   4: 728,268 ns/op
Iteration   5: 738,145 ns/op
Iteration   6: 739,328 ns/op
Iteration   7: 732,186 ns/op
Iteration   8: 774,538 ns/op
Iteration   9: 815,751 ns/op
Iteration  10: 714,448 ns/op

# Run progress: 58,33% complete, ETA 00:01:54
# Fork: 2 of 3
# Warmup Iteration   1: 1174,440 ns/op
# Warmup Iteration   2: 994,761 ns/op
# Warmup Iteration   3: 836,255 ns/op
# Warmup Iteration   4: 740,181 ns/op
# Warmup Iteration   5: 732,687 ns/op
Iteration   1: 741,292 ns/op
Iteration   2: 742,536 ns/op
Iteration   3: 743,853 ns/op
Iteration   4: 724,039 ns/op
Iteration   5: 739,011 ns/op
Iteration   6: 743,141 ns/op
Iteration   7: 735,273 ns/op
Iteration   8: 746,909 ns/op
Iteration   9: 733,629 ns/op
Iteration  10: 765,130 ns/op

# Run progress: 66,67% complete, ETA 00:01:31
# Fork: 3 of 3
# Warmup Iteration   1: 1184,020 ns/op
# Warmup Iteration   2: 969,928 ns/op
# Warmup Iteration   3: 832,638 ns/op
# Warmup Iteration   4: 735,386 ns/op
# Warmup Iteration   5: 745,396 ns/op
Iteration   1: 756,195 ns/op
Iteration   2: 749,304 ns/op
Iteration   3: 739,421 ns/op
Iteration   4: 754,232 ns/op
Iteration   5: 734,976 ns/op
Iteration   6: 737,265 ns/op
Iteration   7: 740,118 ns/op
Iteration   8: 742,716 ns/op
Iteration   9: 731,562 ns/op
Iteration  10: 737,156 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughMessageFormatBuilder":
  742,672 ±(99.9%) 12,152 ns/op [Average]
  (min, avg, max) = (714,448, 742,672, 815,751), stdev = 18,188
  CI (99.9%): [730,520, 754,824] (assumes normal distribution)


# JMH version: 1.20
# VM version: JDK 1.8.0_161, VM 25.161-b12
# VM invoker: C:Program FilesJavajre1.8.0_161binjava.exe
# VM options: <none>
# 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: 2230,607 ns/op
# Warmup Iteration   2: 1705,927 ns/op
# Warmup Iteration   3: 1527,384 ns/op
# Warmup Iteration   4: 1492,499 ns/op
# Warmup Iteration   5: 1437,785 ns/op
Iteration   1: 1458,388 ns/op
Iteration   2: 1477,134 ns/op
Iteration   3: 1456,519 ns/op
Iteration   4: 1465,800 ns/op
Iteration   5: 1488,031 ns/op
Iteration   6: 1459,507 ns/op
Iteration   7: 1480,816 ns/op
Iteration   8: 1462,555 ns/op
Iteration   9: 1461,078 ns/op
Iteration  10: 1494,234 ns/op

# Run progress: 83,33% complete, ETA 00:00:45
# Fork: 2 of 3
# Warmup Iteration   1: 2186,425 ns/op
# Warmup Iteration   2: 1640,445 ns/op
# Warmup Iteration   3: 1409,303 ns/op
# Warmup Iteration   4: 1402,054 ns/op
# Warmup Iteration   5: 1411,979 ns/op
Iteration   1: 1429,291 ns/op
Iteration   2: 1412,831 ns/op
Iteration   3: 1426,304 ns/op
Iteration   4: 1417,528 ns/op
Iteration   5: 1507,471 ns/op
Iteration   6: 1444,355 ns/op
Iteration   7: 1435,535 ns/op
Iteration   8: 1402,223 ns/op
Iteration   9: 1400,843 ns/op
Iteration  10: 1401,743 ns/op

# Run progress: 91,67% complete, ETA 00:00:22
# Fork: 3 of 3
# Warmup Iteration   1: 2223,753 ns/op
# Warmup Iteration   2: 1766,516 ns/op
# Warmup Iteration   3: 1452,903 ns/op
# Warmup Iteration   4: 1462,324 ns/op
# Warmup Iteration   5: 1485,965 ns/op
Iteration   1: 1533,760 ns/op
Iteration   2: 1551,043 ns/op
Iteration   3: 1468,389 ns/op
Iteration   4: 1463,317 ns/op
Iteration   5: 1466,646 ns/op
Iteration   6: 1487,802 ns/op
Iteration   7: 1467,299 ns/op
Iteration   8: 1460,768 ns/op
Iteration   9: 1488,246 ns/op
Iteration  10: 1455,518 ns/op


Result "ru.gnkoshelev.jbreak2018.perf_tests.strings.MetricsFormatBenchmark.formatThroughPatternBenchmark":
  1460,832 ±(99.9%) 24,075 ns/op [Average]
  (min, avg, max) = (1400,843, 1460,832, 1551,043), stdev = 36,034
  CI (99.9%): [1436,758, 1484,907] (assumes normal distribution)


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

Benchmark                                                   Mode  Cnt     Score    Error  Units
MetricsFormatBenchmark.formatThroughBuilderBenchmark        avgt   30   196,029 ±  4,408  ns/op
MetricsFormatBenchmark.formatThroughConcatenationBenchmark  avgt   30   444,483 ± 15,958  ns/op
MetricsFormatBenchmark.formatThroughMessageFormatBuilder    avgt   30   742,672 ± 12,152  ns/op
MetricsFormatBenchmark.formatThroughPatternBenchmark        avgt   30  1460,832 ± 24,075  ns/op

Ожидаемо поплохело варианту MetricsFormat.formatThroughConcatenation(), а вот с оптимизацией pop/aload в MetricsFormat.formatThroughBuilder() JIT-компилятор справился отлично — полученный результат по производительности ничем не отличается от зачейненного варианта.

P.S.

Код бенчмарков лежит на github: jbreak2018-strings-perf-tests.

Заключительные две части выйдут с меньшим лагом. Третья часть выйдет в середине недели.

Автор: Григорий Кошелев

Источник

Поделиться

* - обязательные к заполнению поля