Как у меня сломался String.getBytes(UTF_8) и что я с этим делал

habr.png

(спойлер) дебажил, дизасемблил и пришел к выводу что проблема в SSE инструкциях

Привет, Хабр!

Все началось с того что я писал Load тест на Java для внутреннего компонента системы над которой сейчас работаю. Тест создавал несколько потоков и пытался что-то выполнить очень много раз. В процессе выполнения иногда появлялись java.lang.ArrayIndexOutOfBoundsException: 0 ошибки на строчке очень похожей на эту:

"test".getBytes(StandardCharsets.UTF_8)


Строчка конечно была другая, но после небольшого изучения удалось найти проблему именно в ней. В итоге был написан JMH бенчмарк:

@Benchmark
public byte[] originalTest() {
  return "test".getBytes(StandardCharsets.UTF_8);
}


Который падал после нескольких секунд работы со следующим исключением:

java.lang.ArrayIndexOutOfBoundsException: 0
        at sun.nio.cs.UTF_8$Encoder.encode(UTF_8.java:716)
        at java.lang.StringCoding.encode(StringCoding.java:364)
        at java.lang.String.getBytes(String.java:941)
        at org.sample.MyBenchmark.originalTest(MyBenchmark.java:41)
        at org.sample.generated.MyBenchmark_originalTest.originalTest_thrpt_jmhLoop(MyBenchmark_originalTest.java:103)
        at org.sample.generated.MyBenchmark_originalTest.originalTest_Throughput(MyBenchmark_originalTest.java:72)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:210)
        at org.openjdk.jmh.runner.LoopBenchmarkHandler$BenchmarkTask.call(LoopBenchmarkHandler.java:192)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)


Я никогда не сталкивался с таким раньше, поэтому попробовал тривиальные решения вроде обновить JVM и перезагрузить компьютер, но это, разумеется, не помогло. Проблема возникала на моем MacBook Pro (13-inch, 2017) 3,5 GHz Intel Core i7 и не повторялась на машинах коллег. Не найдя других факторов я решил изучать код дальше.

Проблема возникала внутри JVM класса StringCoding в методе encode ():

private static int scale(int len, float expansionFactor) {
    // We need to perform double, not float, arithmetic; otherwise
    // we lose low order bits when len is larger than 2**24.
    return (int)(len * (double)expansionFactor);
}

static byte[] encode(Charset cs, char[] ca, int off, int len) {
    CharsetEncoder ce = cs.newEncoder();
    int en = scale(len, ce.maxBytesPerChar());
    byte[] ba = new byte[en];
    if (len == 0)
        return ba;
...
}


Массив ba в редких случаях создавался длинной в 0 элементов и это и вызывало ошибку в дальнейшем.

Я попробовал убрав зависимость от UTF_8, но это не получилось. Зависимость пришлось оставить, иначе проблема не воспроизводилась, но получилось убрать много лишнего:

private static int encode() {
    return (int) ((double) StandardCharsets.UTF_8.newEncoder().maxBytesPerChar());
}


maxBytesPerChar возвращает константу из final поля равную 3.0, но сам метод в редких случаях (1 на 1000000000) возвращал 0. Вдвойне странно было то, что убрав каст в double метод отрабатывал как надо во всех случаях.

Я добавил опции JIT компилятора -XX:-TieredCompilation и -client, но это никак не повлияло. В итоге я собрал hsdis-amd64.dylib под Мак, добавил опции -XX: PrintAssemblyOptions=intel, -XX: CompileCommand=print,*MyBenchmark.encode и -XX: CompileCommand=dontinline,*MyBenchmark.encode и начал сравнивать сгенерированный JIT’ом ассемблер для метода с кастом в double и без:

НЕ рабочий вариант с кастом:
0x000000010a44e3ca: mov    rbp,rax            ;*synchronization entry
                                            ; - sun.nio.cs.UTF_8$Encoder::@-1 (line 558)
                                            ; - sun.nio.cs.UTF_8$Encoder::@2 (line 554)
                                            ; - sun.nio.cs.UTF_8::newEncoder@6 (line 72)
                                            ; - org.sample.MyBenchmark::encode@3 (line 50)

0x000000010a44e3cd: movabs rdx,0x76ab16350    ;   {oop(a 'sun/nio/cs/UTF_8')}
0x000000010a44e3d7: vmovss xmm0,DWORD PTR [rip+0xffffffffffffff61]        # 0x000000010a44e340 
                                            ;   {section_word}
0x000000010a44e3df: vmovss xmm1,DWORD PTR [rip+0xffffffffffffff5d]        # 0x000000010a44e344
                                            ;   {section_word}
0x000000010a44e3e7: mov    rsi,rbp
0x000000010a44e3ea: nop
0x000000010a44e3eb: call   0x000000010a3f40a0  ; OopMap{rbp=Oop off=144}
                                            ;*invokespecial 
                                            ; - sun.nio.cs.UTF_8$Encoder::@6 (line 558)
                                            ; - sun.nio.cs.UTF_8$Encoder::@2 (line 554)
                                            ; - sun.nio.cs.UTF_8::newEncoder@6 (line 72)
                                            ; - org.sample.MyBenchmark::encode@3 (line 50)
                                            ;   {optimized virtual_call}
0x000000010a44e3f0: mov    BYTE PTR [rbp+0x2c],0x3f  ;*new
                                            ; - sun.nio.cs.UTF_8::newEncoder@0 (line 72)
                                            ; - org.sample.MyBenchmark::encode@3 (line 50)

0x000000010a44e3f4: vcvtss2sd xmm0,xmm0,DWORD PTR [rbp+0x10]
0x000000010a44e3f9: vcvttsd2si eax,xmm0
0x000000010a44e3fd: cmp    eax,0x80000000
0x000000010a44e403: jne    0x000000010a44e414
0x000000010a44e405: sub    rsp,0x8
0x000000010a44e409: vmovsd QWORD PTR [rsp],xmm0
0x000000010a44e40e: call   Stub::d2i_fixup    ;   {runtime_call}
0x000000010a44e413: pop    rax                ;*d2i  ; - org.sample.MyBenchmark::encode@10 (line 50)

0x000000010a44e414: add    rsp,0x20
0x000000010a44e418: pop    rbp

Рабочий вариант без каста:
0x000000010ef7e04a: mov    rbp,rax            ;*synchronization entry
                                                ; - sun.nio.cs.UTF_8$Encoder::@-1 (line 558)
                                                ; - sun.nio.cs.UTF_8$Encoder::@2 (line 554)
                                                ; - sun.nio.cs.UTF_8::newEncoder@6 (line 72)
                                                ; - org.sample.MyBenchmark::encode@3 (line 50)

0x000000010ef7e04d: movabs rdx,0x76ab16350    ;   {oop(a 'sun/nio/cs/UTF_8')}
0x000000010ef7e057: vmovss xmm0,DWORD PTR [rip+0xffffffffffffff61]        # 0x000000010ef7dfc0
                                            ;   {section_word}
0x000000010ef7e05f: vmovss xmm1,DWORD PTR [rip+0xffffffffffffff5d]        # 0x000000010ef7dfc4
                                            ;   {section_word}
0x000000010ef7e067: mov    rsi,rbp
0x000000010ef7e06a: nop
0x000000010ef7e06b: call   0x000000010ef270a0  ; OopMap{rbp=Oop off=144}
                                            ;*invokespecial 
                                            ; - sun.nio.cs.UTF_8$Encoder::@6 (line 558)
                                            ; - sun.nio.cs.UTF_8$Encoder::@2 (line 554)
                                            ; - sun.nio.cs.UTF_8::newEncoder@6 (line 72)
                                            ; - org.sample.MyBenchmark::encode@3 (line 50)
                                            ;   {optimized virtual_call}
0x000000010ef7e070: mov    BYTE PTR [rbp+0x2c],0x3f  ;*new
                                            ; - sun.nio.cs.UTF_8::newEncoder@0 (line 72)
                                            ; - org.sample.MyBenchmark::encode@3 (line 50)

0x000000010ef7e074: vmovss xmm1,DWORD PTR [rbp+0x10]
0x000000010ef7e079: vcvttss2si eax,xmm1
0x000000010ef7e07d: cmp    eax,0x80000000
0x000000010ef7e083: jne    0x000000010ef7e094
0x000000010ef7e085: sub    rsp,0x8
0x000000010ef7e089: vmovss DWORD PTR [rsp],xmm1
0x000000010ef7e08e: call   Stub::f2i_fixup    ;   {runtime_call}
0x000000010ef7e093: pop    rax                ;*f2i  ; - org.sample.MyBenchmark::encode@9 (line 50)

0x000000010ef7e094: add    rsp,0x20
0x000000010ef7e098: pop    rbp


Одно из отличий было наличие инструкций vcvtss2sd и vcvttsd2si. Я переключился на C++ и решил воспроизвести последовательность на inline asm, но в процессе отладки выяснилось что clang компилятор с опцией -O0 использует cvtss2sd инструкцию при сравнении float!= 1.0. В итоге все свелось к функции compare:

/*
 * sse
    0x105ea2f30 <+0>:  pushq  %rbp
    0x105ea2f31 <+1>:  movq   %rsp, %rbp

    0x105ea2f34 <+4>:  movsd  0x6c(%rip), %xmm0         ; xmm0 = mem[0],zero
    0x105ea2f3c <+12>: movss  0x6c(%rip), %xmm1         ; xmm1 = mem[0],zero,zero,zero
    0x105ea2f44 <+20>: movss  %xmm1, -0x4(%rbp)
->  0x105ea2f49 <+25>: cvtss2sd -0x4(%rbp), %xmm1
    0x105ea2f4e <+30>: ucomisd %xmm0, %xmm1

    0x105ea2f52 <+34>: setne  %al
    0x105ea2f55 <+37>: setp   %cl
    0x105ea2f58 <+40>: orb    %cl, %al
    0x105ea2f5a <+42>: andb   $0x1, %al
    0x105ea2f5c <+44>: movzbl %al, %eax
    0x105ea2f5f <+47>: popq   %rbp
    0x105ea2f60 <+48>: retq
    0x105ea2f61 <+49>: nopw   %cs:(%rax,%rax)
 */

bool compare() {
    float val = 1.0;
    return val != 1.0;
}


И эта функция в редких случаях возвращала false. Я написал небольшую обертку чтобы сосчитать процент ошибочных выполнений:

int main() {
    int error = 0;
    int secondCompareError = 0;

    for (int i = 0; i < INT_MAX; i++) {
        float result = 1.0;

        if (result != 1.0) {
            error++;

            if (result != 1.0) {
                secondCompareError++;
            }
        }
    }

    std::cout << "Iterations: " << INT_MAX
              << ", errors: " << error
              <<", second compare errors: " << secondCompareError
              << std::endl;
    return 0;
}


Результат был следующий: Iterations: 2147483647, errors: 111, second compare errors: 0. Интересно то, что повторная проверка никогда не выдавала ошибки.

Я отключил поддержку SSE у clang, функция compare стала выглядеть так:

/*
 * no sse
    0x102745f50 <+0>:  pushq  %rbp
    0x102745f51 <+1>:  movq   %rsp, %rbp

    0x102745f54 <+4>:  movl   $0x3f800000, -0x4(%rbp)   ; imm = 0x3F800000
->  0x102745f5b <+11>: flds   -0x4(%rbp)
    0x102745f5e <+14>: fld1
    0x102745f60 <+16>: fxch   %st(1)
    0x102745f62 <+18>: fucompi %st(1)
    0x102745f64 <+20>: fstp   %st(0)

    0x102745f66 <+22>: setp   %al
    0x102745f69 <+25>: setne  %cl
    0x102745f6c <+28>: orb    %al, %cl
    0x102745f6e <+30>: andb   $0x1, %cl
    0x102745f71 <+33>: movzbl %cl, %eax
    0x102745f74 <+36>: popq   %rbp
    0x102745f75 <+37>: retq
    0x102745f76 <+38>: nopw   %cs:(%rax,%rax)
 */
bool compare() {
    float val = 1.0;
    return val != 1.0;
}


И проблема больше не воспроизводилась. Из этого я могу сделать выводы что набор SSE инструкция не очень хорошо работает на моей системе.

Я работаю программистом больше 7 лет, а программирую больше 16 и за это время я привык доверять примитивным операциям. Она всегда работает и результат всегда одинаковый. Осознать что сравнение float’а в какой то момент может сломаться это конечно шок. И что с этим можно сделать кроме как заменить Мак не ясно.

© Habrahabr.ru