(спойлер) дебажил, дизасемблил и пришел к выводу что проблема в 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::<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 ; {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 <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'а в какой то момент может сломаться это конечно шок. И что с этим можно сделать кроме как заменить Мак не ясно.
Автор: fls_welvet
