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

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

    Код второй задачи:
        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).

    Другие публикации серии: Часть 1, Часть 3, Часть 4.

    Немного расширим задачу, добавив ещё один способ форматирования строки вне конкурса:
        public String formatThroughMessageFormat(String user, String grade, String company, String message) {
            return MessageFormat.format(
                    "Он, {0}, придумал такие {1} задачи. Приду на стенд {2} и скажу ему {3}",
                    user, grade, company, message);
        }
    


    Решение


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


    Очевидный неправильный ответ: конкатенация — это медленно (во всяком случае — медленнее, чем StringBuilder).
    Миф о медленной конкатенации, вероятнее всего, уходит своими корнями в пример, демонстрирующий влияние иммутабельности строк на вычислительную сложность алгоритма:
        public static String constructThroughConcatenation(String[] strings) {
            String result = "";
            for (String s : strings) {
                result = result + s;
            }
            return result;
        }
    
        public static String constructThroughBuilder(String[] strings) {
            StringBuilder sb = new StringBuilder();
            for (String s : strings) {
                sb.append(s);
            }
            return sb.toString();
        }
    

    Результат бенчмарка говорит сам за себя (здесь N — размер массива strings):
    Benchmark                    (N)  Mode  Cnt       Score      Error  Units
    ...builderBenchmark           10  avgt   30       0,182 ±    0,004  us/op
    ...builderBenchmark          100  avgt   30       1,566 ±    0,014  us/op
    ...builderBenchmark         1000  avgt   30      18,188 ±    0,372  us/op
    ...builderBenchmark        10000  avgt   30     214,308 ±    7,523  us/op
    ...concatenationBenchmark     10  avgt   30       0,209 ±    0,003  us/op
    ...concatenationBenchmark    100  avgt   30      13,220 ±    0,305  us/op
    ...concatenationBenchmark   1000  avgt   30    1158,463 ±   48,124  us/op
    ...concatenationBenchmark  10000  avgt   30  127585,013 ± 5716,547  us/op
    

    Результаты бенчмарка целиком
    # JMH version: 1.20
    # VM version: JDK 1.8.0_161, VM 25.161-b12
    # VM invoker: C:\Program Files\Java\jre1.8.0_161\bin\java.exe
    # VM options: <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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 дают одинаковый результат.

    В нашем примере для обоих вариантов 2 и 3 HotSpot применил оптимизацию OptimizeStringConcat, заменив вызов Java-кода на использование intrinsic-методов. Если отключить оптимизацию -XX:-OptimizeStringConcat, то получим следующие результаты:
    Benchmark                         Mode  Cnt     Score     Error  Units
    Ordinal...BuilderBenchmark        avgt   30   126,876 ±   5,962  ns/op
    Ordinal...ConcatenationBenchmark  avgt   30   186,758 ±  11,158  ns/op
    Ordinal...MessageFormatBenchmark  avgt   30  1157,645 ±  34,743  ns/op
    Ordinal...PatternBenchmark        avgt   30  1756,613 ± 131,212  ns/op

    Ниже ещё будет про особенность работы OptimizeStringConcat.

    Статистика


    Эта задача была самой простой из предложенных — её правильно решили 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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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 Files\Java\jre-9.0.4\bin\java.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).
    По умолчанию в StringConcatFactory выполняется стратегия Strategy.MH_INLINE_SIZED_EXACT — генерация с использованием MethodHandle с предварительным вычислением размера буфера, равного размеру результирующей строки:
        /**
         * <p><b>{@link Strategy#MH_INLINE_SIZED_EXACT}: "MethodHandles inline,
         * sized exactly".</b>
         *
         * <p>This strategy replicates what StringBuilders are doing: it builds the
         * byte[] array on its own and passes that byte[] array to String
         * constructor. This strategy requires access to some private APIs in JDK,
         * most notably, the read-only Integer/Long.stringSize methods that measure
         * the character length of the integers, and the private String constructor
         * that accepts byte[] arrays without copying. While this strategy assumes a
         * particular implementation details for String, this opens the door for
         * building a very optimal concatenation sequence. This is the only strategy
         * that requires porting if there are private JDK changes occur.
         */
        private static final class MethodHandleInlineCopyStrategy { }
    

    Это позволило обойти проблемы при форматировании строки с метрикой, наблюдавшиеся в сгенерированном коде для Java 8. Но так может получаться не всегда, как в случае примера из нашей задачи — результат хуже примерно на четверть. Результат получился хуже как относительно StringBuilder, так и по отношению к результату на Java 8.

    OptimizeStringConcat


    Интересен и тот факт, что метод MetricsFormat.formatThroughConcatenation() показал в 4 раза лучший результат по сравнению с MetricsFormat.formatThroughBuilder()!
    Дело в том, что это не makeConcatWithConstants так быстр, как недостаточно хорошо оптимизирован метод с вызовом StringBuilder. Как верно заметил apangin ниже в комментариях: заменив тип timestamp с long на int можно обнаружить, что разница между двумя реализациями уже не будет такой существенной.

    Особенность этого примера заключается в том, что -XX:+OptimizeStringConcat не работает для StringBuilder.append(long), а появившийся в Java 9 механизм Indify String Concatenation лишён этого недостатка.

    Заключение


    За рамками обсуждения остались 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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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 Files\Java\jre1.8.0_161\bin\java.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-компилятор справился отлично — полученный результат по производительности ничем не отличается от зачейненного варианта. Тем не менее, обе версии использования StringBuilder не являются эквивалентными, например, OptimizeStringConcat умеет распознавать только зачейненный вариант использования StringBuilder.

    P.S.


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

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

    UPD. Другие публикации серии: Часть 1, Часть 3, Часть 4.
    Контур 164,18
    Делаем веб-сервисы для бизнеса
    Поделиться публикацией
    Комментарии 11
    • +3
      За задачи и разбор +1, но делать выводы о производительности по байткоду не совсем корректно, как я показывал в презентации. Замени, например, timestamp с long на int и сравни заново… Довод про конструктор StringBuilder развалился на глазах, правда? И выводы будут уже совсем другие.

      В этой же презентации про конкатенацию, кстати, тоже есть. Нельзя бенчмаркать StringBuilder и не упомянуть фичу Хотспота под названием OptimizeStringConcat.
      • 0
        За задачи и разбор +1, но делать выводы о производительности по байткоду не совсем корректно, как я показывал в презентации.

        Спасибо!
        За исключением тех случаев, когда javac генерирует идентичный байткод. :) В остальном согласен, и чем дальше (тот же JEP-280), тем поведение JIT-компилятора становится менее предсказуемым.

        В этой же презентации про конкатенацию, кстати, тоже есть. Нельзя бенчмаркать StringBuilder и не упомянуть фичу Хотспота под названием OptimizeStringConcat.

        О, точно, я уже под утро заканчивал статью и про OptimizeStringConcat совсем забыл, а это важная штука.

      • 0
        Касательно корректности рассуждений о производительности с учётом огромного числа эвристик HotSpot'а: задача объяснить наблюдаемое поведение выглядит значительно привлекательнее задачи оценки или сравнения производительности алгоритмов.
        Но выбор в пользу первого варианта объяснялся форматом проведения викторины на конференции, когда по ответам можно было быстро отсортировать решения и уже дальше смотреть пояснения к ответам. В следующий раз стоит выбрать детерминированный вариант задач.
        • 0
          И вот тут-то JIT-компилятор может хорошо покуражиться

          JIT-то тут при чём? Основную работу делает собственно фабрика, генерируя цепочку методхэндлов, которые сперва считают суммарную длину всех строк, затем выделяют один массив точно нужного размера и всовывают его в строку через небезопасный конструктор.

          • 0
            Согласен, в этом месте влияние JIT не настолько существенное — выше Андрей apangin намекнул на различия в определении длины строки под long в StringBuilder и StringConcatFactory. apangin, я же правильно понял, что речь об этом?
            • 0

              Да, и ещё то, что с int типом будет уже не важно, создаётся ли StringBuilder() с размером по умолчанию или StringBuilder(metrics) с заранее предопределённым размером. В обоих случаях паттерн new StringBuilder(*).append()...append().toString() скомпилируется как интринсик без вызова Java кода, и производительность Concatenation vs. StringBuilder будет одинаковая, несмотря на различия в байткоде.


              Если же в цепочке попадётся append(long), то оптимизация не отработает — ну, не реализовали почему-то в JDK 8), то есть, будет честный вызов Java кода.

              • 0
                Ага, я чуть позже про OptimizeStringConcat дописал.

                Если же в цепочке попадётся append(long), то оптимизация не отработает — ну, не реализовали почему-то в JDK 8), то есть, будет честный вызов Java кода.
                Судя по изменениям в stringopts.cpp в JDK 10/JDK 9 относительно JDK 8, то в новых версиях это по-прежнему не оптимизируется.
                • 0
                  Ну так потому что уже особо не надо: JEP-280 срабатывает в подавляющем большинстве случаев (кроме модуля java.base и вручную написанных StringBuilder'ов). По сути дела и существующую оптимизацию если удалить, сильно хуже не станет.
                  • +2
                    Как сказать… не пересобирать же из исходников все 100500 подключаемых библиотек, скомпилированных под Java 6-7-8.
                    • +1
                      Я думаю, какой-нибудь jlink проще научить обновлять байткод в таких ситуациях. Все же пользуются jlink начиная с Java 9 ;-)
          • 0
            Опубликовал продолжение — Часть 3.

            Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

            Самое читаемое