Хабрахабр

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

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

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

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

"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 метод отрабатывал как надо во всех случаях.

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

НЕ рабочий вариант с кастом:
0x000000010a44e3ca: mov rbp,rax ;*synchronization entry ; - sun.nio.cs.UTF_8$Encoder::<init>@-1 (line 558) ; - sun.nio.cs.UTF_8$Encoder::<init>@2 (line 554) ; - sun.nio.cs.UTF_8::newEncoder@6 (line 72) ; - org.sample.MyBenchmark::encode@3 (line 50) 0x000000010a44e3cd: movabs rdx,0x76ab16350 ;
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 <init> ; - sun.nio.cs.UTF_8$Encoder::<init>@6 (line 558) ; - sun.nio.cs.UTF_8$Encoder::<init>@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::<init>@-1 (line 558) ; - sun.nio.cs.UTF_8$Encoder::<init>@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 <init> ; - sun.nio.cs.UTF_8$Encoder::<init>@6 (line 558) ; - sun.nio.cs.UTF_8$Encoder::<init>@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'а в какой то момент может сломаться это конечно шок.

Теги
Показать больше

Похожие статьи

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»
Закрыть