Как исправить ошибку java hotspot tm

Приветствую, за время праздников подготовил статью про низкоуровневое профилирование и производительность. Перед погружением предлагаю читателю ознакомится с кратким предуведомлением:

Здесь целых три пункта

Погружение

Как-то на СО мне попался любопытный вопрос: Missing bounds checking elimination in String constructor? Автор сформулировал свой вопрос так:

Looking into UTF8 decoding performance, I noticed the performance of protobuf’s UnsafeProcessor::decodeUtf8 is better than String(byte[] bytes, int offset, int length, Charset charset) for the following non-ascii string: "Quizdeltagerne spiste jordbær med flØde, mens cirkusklovnen".

…

I assume the difference is due to missing bounds checking elimination which I expected to kick in, especially since there is an explicit bounds check in the form of a call to checkBoundsOffCount(offset, length, bytes.length) in the beginning of String(byte[] bytes, int offset, int length, Charset charset).

Сформулировано несколько сумбурно и запутанно и с самого начала не очень понятно, почему сравнивается код UnsafeProcessor.decodeUtf8() и String(byte[], int, int, Charset). Перво-наперво проясним эту часть.

Дело в том, что в них по-разному выполняется доступ к элементам входящего массива байтов.

Если для раскодирования используется c.g.p.Utf8.UnsafeProcessor.decodeUtf8(), то его производительность лучше, чем у c.g.p.Utf8.SafeProcessor и String(byte[] bytes, int offset, int length, Charset charset), ведь доступ к ячейкам массива в UnsafeProcessor.decodeUtf8() происходит так:

while (offset < limit) {
  byte b = UnsafeUtil.getByte(bytes, offset);
  //...
  offset++;
}

UnsafeUtil.getByte() делегирует обращение к Unsafe.getByte(), который предоставляет доступ к «сырой» памяти, что быстрее (и опаснее), чем обычный доступ, выполняемый в SafeProcessor.decodeUtf8() (и в конструкторе строки):

while (offset < limit) {
  byte b = bytes[offset];
  //...
  offset++;
}

Код бенчмарка можно посмотреть в гисте, а вот его вывод:

Benchmark                       Mode  Cnt    Score   Error  Units
StringBenchmark.safeDecoding    avgt   10  127.107 ± 3.642  ns/op
StringBenchmark.unsafeDecoding  avgt   10  100.915 ± 4.090  ns/op

Чем интересен этот пример для рядового разработчика? Интересен он тем, что автор высказал предположение о роли проверок выхода за пределы массива и предложил способ сгладить эту разницу:

while (offset < limit) {}

-->

while (0 <= offset && offset < limit) {}

И действительно, это уравняло время работы обоих методов:

Benchmark                       Mode  Cnt    Score    Error  Units
StringBenchmark.safeDecoding    avgt   10  100.802 ± 13.147  ns/op
StringBenchmark.unsafeDecoding  avgt   10  102.774 ±  3.893  ns/op

Мне захотелось разобраться в этом случае и по возможности принести какую-то пользу сообществу. Первым делом я сосредоточился на исследовании кода JDK, а именно упомянутого выше конструктора:

public String(byte[] bytes, int offset, int length, Charset charset) {
  Objects.requireNonNull(charset);
  checkBoundsOffCount(offset, length, bytes.length);
  if (length == 0) {
    this.value = "".value;
    this.coder = "".coder;
  } else if (charset == UTF_8.INSTANCE) {
    if (COMPACT_STRINGS && !StringCoding.hasNegatives(bytes, offset, length)) {
      this.value = Arrays.copyOfRange(bytes, offset, offset + length);
      this.coder = LATIN1;
    } else {
      int sl = offset + length;
      int dp = 0;
      byte[] dst = null;
      if (COMPACT_STRINGS) {
        dst = new byte[length];
        while (offset < sl) {
          int b1 = bytes[offset];
          if (b1 >= 0) {
            dst[dp++] = (byte)b1;
            offset++;
            continue;
          }
          //...
}

Для этого я использовал бенчмарк:

@State(Scope.Thread)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public class StringConstructorBenchmark {
  private byte[] array;

  @Setup
  public void setup() {
    var str = "Quizdeltagerne spiste jordbær med fløde, mens cirkusklovnen. Я";
    array = str.getBytes(StandardCharsets.UTF_8);
  }

  @Benchmark
  public String newString()  {
      return new String(array, 0, array.length, StandardCharsets.UTF_8);
  }
}

Опыт показывает, что незначительное изменение условия while в конструкторе строки даёт ощутимый прирост:

// while (offset < sl)

StringConstructorBenchmark.newString     173,092 ± 3,048 ns/op

// while (0 <= offset && offset < sl)

StringConstructorBenchmark.newString     126,908 ± 2,355 ns/op

Странности

Поговорим о странностях рассматриваемого примера.

Итак, изначально предположение состоит в том, что причина почти 20% разницы в производительности заключается в использовании небезопасного доступа, что позволяет сэкономить на проверках выхода за границы массива.

Это хорошо согласуется с наблюдаемой картиной: как только мы заменяем одностороннюю проверку offset < sl двусторонней 0 <= offset && offset < sl, то компилятор прозревает и выбрасывает проверки из кода.

Предположение кажется верным и понятным, а вот поведение компилятора не очень, ведь проверка отрицательного значения переменной offset выполняется в самом начале метода:

public String(byte[] bytes, int offset, int length, Charset charset) {
  Objects.requireNonNull(charset);
  checkBoundsOffCount(offset, length, bytes.length);
  //...
}

Далее в цикле у нас есть только приращение, следовательно значение переменной offset никогда не может стать отрицательным (а превышение допустимого ограничено самой петлёй). Это понятно человеку, но почему-то непонятно компилятору. Попахивает явным багом и он действительно имеет место быть, но обо всём по порядку.

Проверка

Для успокоения совести выполним решающую проверку, а именно сравним ассемблерный код «до» и «после». Для этого подключим LinuxPerfAsmProfiler, руководство по использованию которого описано в отдельной статье.

Порядок действий следующий:

1) берём свежие исходники OpenJDK и собираем с помощью

bash configure && make clean && make images

2) берём свежие binutils (в моём случае верcии 2.37) и собираем из тех же исходников

3) подкладываем собранный hsdis-*.so в папку к libjvm.so

4) профилируем

Полный профиль «до» доступен здесь, полный профиль «после» — тут. Дабы избавить от необходимости вычитки длинной простыни подсвечу основное, а именно цикл while:

До

2.22% ││   │ 0x00007fed70eb4c21:   mov    (%rsp),%r8               ;*iload_2 {reexecute=0 rethrow=0 return_oop=0}
      ││   │                                                       ; - java.lang.String::<init>@107 (line 537)
2.32% ↘│   │ 0x00007fed70eb4c25:   cmp    %r13d,%ecx
       │   │ 0x00007fed70eb4c28:   jge    0x00007fed70eb5388       ;*if_icmpge {reexecute=0 rethrow=0 return_oop=0}
       │   │                                                       ; - java.lang.String::<init>@110 (line 537)
3.05%  │   │ 0x00007fed70eb4c2e:   cmp    0x8(%rsp),%ecx
       │   │ 0x00007fed70eb4c32:   jae    0x00007fed70eb5319
2.38%  │   │ 0x00007fed70eb4c38:   mov    %r8,(%rsp)
2.64%  │   │ 0x00007fed70eb4c3c:   movslq %ecx,%r8
2.46%  │   │ 0x00007fed70eb4c3f:   mov    %rax,%rbx
3.44%  │   │ 0x00007fed70eb4c42:   sub    %r8,%rbx
2.62%  │   │ 0x00007fed70eb4c45:   add    $0x1,%rbx
2.64%  │   │ 0x00007fed70eb4c49:   and    $0xfffffffffffffffe,%rbx
2.30%  │   │ 0x00007fed70eb4c4d:   mov    %ebx,%r8d
3.08%  │   │ 0x00007fed70eb4c50:   add    %ecx,%r8d
2.55%  │   │ 0x00007fed70eb4c53:   movslq %r8d,%r8
2.45%  │   │ 0x00007fed70eb4c56:   add    $0xfffffffffffffffe,%r8
2.13%  │   │ 0x00007fed70eb4c5a:   cmp    (%rsp),%r8
       │   │ 0x00007fed70eb4c5e:   jae    0x00007fed70eb5319
3.36%  │   │ 0x00007fed70eb4c64:   mov    %ecx,%edi                ;*aload_1 {reexecute=0 rethrow=0 return_oop=0}
       │   │                                                       ; - java.lang.String::<init>@113 (line 538)
2.86%  │  ↗│ 0x00007fed70eb4c66:   movsbl 0x10(%r14,%rdi,1),%r8d   ;*baload {reexecute=0 rethrow=0 return_oop=0}
       │  ││                                                       ; - java.lang.String::<init>@115 (line 538)
2.48%  │  ││ 0x00007fed70eb4c6c:   mov    %r9d,%edx
2.26%  │  ││ 0x00007fed70eb4c6f:   inc    %edx                     ;*iinc {reexecute=0 rethrow=0 return_oop=0}
       │  ││                                                       ; - java.lang.String::<init>@127 (line 540)
3.28%  │  ││ 0x00007fed70eb4c71:   mov    %edi,%ebx
2.44%  │  ││ 0x00007fed70eb4c73:   inc    %ebx                     ;*iinc {reexecute=0 rethrow=0 return_oop=0}
       │  ││                                                       ; - java.lang.String::<init>@134 (line 541)
2.35%  │  ││ 0x00007fed70eb4c75:   test   %r8d,%r8d
       ╰  ││ 0x00007fed70eb4c78:   jge    0x00007fed70eb4c04       ;*iflt {reexecute=0 rethrow=0 return_oop=0}
          ││                                                       ; - java.lang.String::<init>@120 (line 539)

После

17.28%    ││ 0x00007f6b88eb6061:   mov    %edx,%r10d               ;*iload_2 {reexecute=0 rethrow=0 return_oop=0}
          ││                                                       ; - java.lang.String::<init>@107 (line 537)
 0.11%    ↘│ 0x00007f6b88eb6064:   test   %r10d,%r10d
           │ 0x00007f6b88eb6067:   jl     0x00007f6b88eb669c       ;*iflt {reexecute=0 rethrow=0 return_oop=0}
           │                                                       ; - java.lang.String::<init>@108 (line 537)
 0.39%     │ 0x00007f6b88eb606d:   cmp    %r13d,%r10d
           │ 0x00007f6b88eb6070:   jge    0x00007f6b88eb66d0       ;*if_icmpge {reexecute=0 rethrow=0 return_oop=0}
           │                                                       ; - java.lang.String::<init>@114 (line 537)
 0.66%     │ 0x00007f6b88eb6076:   mov    %ebx,%r9d
13.70%     │ 0x00007f6b88eb6079:   cmp    0x8(%rsp),%r10d
 0.01%     │ 0x00007f6b88eb607e:   jae    0x00007f6b88eb6671
 0.14%     │ 0x00007f6b88eb6084:   movsbl 0x10(%r14,%r10,1),%edi   ;*baload {reexecute=0 rethrow=0 return_oop=0}
           │                                                       ; - java.lang.String::<init>@119 (line 538)
 0.37%     │ 0x00007f6b88eb608a:   mov    %r9d,%ebx
 0.99%     │ 0x00007f6b88eb608d:   inc    %ebx                     ;*iinc {reexecute=0 rethrow=0 return_oop=0}
           │                                                       ; - java.lang.String::<init>@131 (line 540)
12.88%     │ 0x00007f6b88eb608f:   movslq %r9d,%rsi                ;*bastore {reexecute=0 rethrow=0 return_oop=0}
           │                                                       ; - java.lang.String::<init>@196 (line 548)
 0.17%     │ 0x00007f6b88eb6092:   mov    %r10d,%edx
 0.39%     │ 0x00007f6b88eb6095:   inc    %edx                     ;*iinc {reexecute=0 rethrow=0 return_oop=0}
           │                                                       ; - java.lang.String::<init>@138 (line 541)
 0.96%     │ 0x00007f6b88eb6097:   test   %edi,%edi
 0.02%     │ 0x00007f6b88eb6099:   jl     0x00007f6b88eb60dc       ;*iflt {reexecute=0 rethrow=0 return_oop=0}
           │                                                       ; - java.lang.String::<init>@124 (line 539)

Сразу бросается в глаза, что код «после» стал на 8 строк короче: инструкции между байт-кодами if_icmpge и aload_1 (предполагаемо отвечающие за проверку выхода за границы массива) куда-то делись. Вот они, выделенные в отдельный листинг:

2.38%  │   │ 0x00007fed70eb4c38:   mov    %r8,(%rsp)
2.64%  │   │ 0x00007fed70eb4c3c:   movslq %ecx,%r8
2.46%  │   │ 0x00007fed70eb4c3f:   mov    %rax,%rbx
3.44%  │   │ 0x00007fed70eb4c42:   sub    %r8,%rbx
2.62%  │   │ 0x00007fed70eb4c45:   add    $0x1,%rbx
2.64%  │   │ 0x00007fed70eb4c49:   and    $0xfffffffffffffffe,%rbx
2.30%  │   │ 0x00007fed70eb4c4d:   mov    %ebx,%r8d
3.08%  │   │ 0x00007fed70eb4c50:   add    %ecx,%r8d

В дальнейшем оказалось, что это не единичное проявление бага, метод String.translateEscapes() содержит похожий код

char[] chars = toCharArray();
int length = chars.length;
int from = 0;
int to = 0;
while (from < length) {        // <---
  char ch = chars[from++];
  if (ch == '\') {
    ch = from < length ? chars[from++] : '';

который будучи изменённым «по образу и подобию» показал похожий прирост на исходной строке:

// from < length
StringConstructorBenchmark.translateEscapes avgt 53,627 ± 0,850 ns/op

// from >=0 && from < length
StringConstructorBenchmark.translateEscapes avgt 48,087 ± 1,129 ns/op

После этого я создал JDK-8278518 и на всякий случай создал ПР с изменениями в коде JDK (там же см. бенчмарки). Вдруг в обсуждении всплывёт что-то любопытное?

И таки да!

Внезапно оказалось, что
1) во-первых, исчезнувшие 8 строк кода — это не проверка выхода за границы массива
2) сама проверка всё ещё там!

На деле выход за границы массива проверяется всего двумя инструкциями:

// до

0x00007fed70eb4c2e:   cmp    0x8(%rsp),%ecx
0x00007fed70eb4c32:   jae    0x00007fed70eb5319

// после

0x00007f6b88eb6079:   cmp    0x8(%rsp),%r10d
0x00007f6b88eb607e:   jae    0x00007f6b88eb6671

А что же тогда делают исчезнувшие 8 строк? Ответ прост: ничего полезного. В псевдокоде их можно записать как

long temp = sl;
loop {
  long newTemp = (long)((int)((temp - (long)offset + 1) & (-2L)) + offset) - 2L;
  if (newTemp u>= temp) jump;
  temp = newTemp;
}

Иными словами баг состоит не в том, что компилятор не смог выбросить лишний код, а в том, что он добавил избыточный. Разумеется, исправлять это нужно в коде самой виртуальной машины, сделать это самостоятельно я не смог, поэтому задачу подхватил Роланд Вестрелин. Вот как он объясняет происходящее:

The loop has 2 backedges. One is frequently taken, the other is not. The loop head is cloned for the least frequent backedge by ciTypeFlow. C2 then builds an outer Loop with the most frequently taken backedge and an inner counted loop with the least frequently taken backedge.
Preventing ciTypeFlow from cloning any loop head causes C2 to split the loop head with 2 backedges and to pick the most frequent backedge for the inner loop, which becomes a counted loop and is fully optimized. That leads to the following performance numbers:

StringBenchmark.safeDecoding 65.404 ± 0.723 ns/op
StringBenchmark.unsafeDecoding 73.004 ± 12.800 ns/op

So it would seem that in the case of multiple backedges, ciTypeFlow should not get in the way and leave C2 choose the inner loop.

Выводы

Внутри виртуальной машины всё ещё скрыты возможности для различных оптимизаций и улучшений, беда лишь в том, что их обнаружение по большей части дело случая.

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

• String.decodeASCII()

• StringLatin1.regionMatchesCI()

• StringLatin1.regionMatchesCI_UTF16()

• StringUTF16.replace()

• Long.toString(long, int)

• StringCoding.implEncodeAsciiArray()

• sun.nio.cs.*.Encoder.encodeArrayLoop()

• ZipFile.Source.getMetaVersion()

Если в вашем коде есть такой же шаблон в критически важном месте, то вы всегда можете неплохо улучшить производительность с помощью простого и элегантного костыля (или ждите, когда JDK-8278518 исправят должным образом).

На сегодня всё

UPD: Ещё один случай, когда изменение условного выражения в цикле даёт прирост производительности.

23:18:36.984  [ Npc Table ]

23:18:36.984   ~ Loaded: 47 AI params for 41 NPCs.

23:18:37.937   ~ Loaded: 6518 Npc Templates.

23:18:38.156   ~ Loaded: 23688 npc skills.

23:18:38.546  Problems with droplist for Npc template Bearded Keltir[18003]

23:18:39.093   ~ INFO: Players droplist was cached

23:18:39.140   ~ Loaded: 458 Minions.

23:18:39.203   ~ Loaded: 1335 SkillLearn entrys.

23:18:39.218  [ Npc Table ]

23:18:39.234   ~ Loading Scripts…

Exception in thread «main» java.lang.NullPointerException

        at blackdev.util.ext.scripts.Compiler.<init>(Compiler.java:39)

        at blackdev.util.ext.scripts.Compiler.getInstance(Compiler.java:32)

        at blackdev.util.ext.scripts.Scripts.load(Scripts.java:132)

        at blackdev.util.ext.scripts.Scripts.<init>(Scripts.java:49)

        at blackdev.util.ext.scripts.Scripts.getInstance(Scripts.java:41)

        at blackdev.gameserver.tables.NpcTable.RestoreNpcData(NpcTable.java:349)

        at blackdev.gameserver.tables.NpcTable.<init>(NpcTable.java:64)

        at blackdev.gameserver.tables.NpcTable.getInstance(NpcTable.java:51)

        at blackdev.gameserver.GameServer.<init>(GameServer.java:194)

        at blackdev.gameserver.GameServer.main(GameServer.java:529)

Что за ошибка?