Comment mon String.getBytes (UTF_8) s'est cassé et ce que j'en ai fait

(spoiler) débazé, démonté et est arrivé à la conclusion que le problème est dans les instructions SSE

Bonjour, Habr!

Tout a commencé avec le fait que j'ai écrit un test de charge en Java pour le composant interne du système sur lequel je travaille. Le test a créé plusieurs threads et a tenté d'exécuter quelque chose très souvent. Pendant l'exécution, parfois java.lang.ArrayIndexOutOfBoundsException: 0 erreurs apparaissent sur une ligne très similaire à ceci:

"test".getBytes(StandardCharsets.UTF_8) 

La ligne, bien sûr, était différente, mais après une petite étude, j'ai réussi à y trouver le problème. En conséquence, le benchmark JMH a été écrit:

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

Qui s'est écrasé après quelques secondes de fonctionnement à l'exception suivante:

 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) 

Je n'ai jamais rencontré cela auparavant, j'ai donc essayé des solutions triviales comme la mise à jour de la JVM et le redémarrage de l'ordinateur, mais cela n'a bien sûr pas aidé. Le problème est survenu sur mon MacBook Pro (13 pouces, 2017) Intel Core i7 3,5 GHz et ne s'est pas reproduit sur les machines de mes collègues. Ne trouvant pas d'autres facteurs, j'ai décidé d'étudier davantage le code.

Le problème s'est produit à l'intérieur de la machine virtuelle Java de la classe StringCoding dans la méthode 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; ... } 

Dans de rares cas, le tableau ba a été créé avec une longueur de 0 élément, ce qui a provoqué une erreur à l'avenir.

J'ai essayé de supprimer la dépendance à UTF_8, mais cela n'a pas fonctionné. La dépendance a dû être laissée, sinon le problème ne s'est pas reproduit, mais il s'est avéré éliminer beaucoup d'excès:

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

maxBytesPerChar renvoie une constante du champ final égale à 3,0, mais la méthode elle-même dans de rares cas (1 pour 1000000000) a renvoyé 0. Il était doublement étrange que la suppression du transtypage en double fonctionne comme elle le devrait dans tous les cas.

J'ai ajouté les options du compilateur JIT -XX: -TieredCompilation et -client, mais cela n'a eu aucune incidence. Au final, j'ai compilé hsdis-amd64.dylib pour Mac, ajouté les options -XX: PrintAssemblyOptions = intel, -XX: CompileCommand = print, * MyBenchmark.encode et -XX: CompileCommand = dontinline, * MyBenchmark.encode et commencé à comparer le JIT généré '' assembleur om pour une méthode avec custom en double et sans:

     : 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 

L'une des différences était la disponibilité des instructions vcvtss2sd et vcvttsd2si. Je suis passé en C ++ et j'ai décidé de jouer la séquence en asm en ligne, mais pendant le débogage, il s'est avéré que le compilateur clang avec l'option -O0 utilise l'instruction cvtss2sd lors de la comparaison de float! = 1.0. En fin de compte, cela revenait à la fonction de comparaison:

 /* * 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; } 

Et cette fonction dans de rares cas est retournée fausse. J'ai écrit un petit wrapper pour calculer le pourcentage d'exécutions erronées:

 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; } 

Le résultat était le suivant: Itérations: 2147483647, erreurs: 111, secondes erreurs de comparaison: 0. Fait intéressant, la deuxième vérification n'a jamais généré d'erreur.

J'ai désactivé le support SSE de clang, la fonction de comparaison a commencé à ressembler à ceci:

 /* * 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; } 

Et le problème ne se reproduisait plus. De cela, je peux conclure que le jeu d'instructions SSE ne fonctionne pas très bien sur mon système.

Je travaille en tant que programmeur depuis plus de 7 ans, et je programme depuis plus de 16 ans, et pendant ce temps, je faisais confiance aux opérations primitives. Cela fonctionne toujours et le résultat est toujours le même. Réaliser qu'une comparaison d'un flotteur à un moment donné peut se casser est bien sûr un choc. Et ce qui peut être fait avec cela sauf pour remplacer le Mac n'est pas clair.