2012-05-02 14 views
34

¿Por qué el orden en que los métodos de C# en .NET 4.0 están compilados justo a tiempo afecta la rapidez con que se ejecutan? Por ejemplo, consideremos dos métodos equivalentes:¿Por qué el orden de JIT afecta el rendimiento?

public static void SingleLineTest() 
{ 
    Stopwatch stopwatch = new Stopwatch(); 
    stopwatch.Start(); 
    int count = 0; 
    for (uint i = 0; i < 1000000000; ++i) { 
     count += i % 16 == 0 ? 1 : 0; 
    } 
    stopwatch.Stop(); 
    Console.WriteLine("Single-line test --> Count: {0}, Time: {1}", count, stopwatch.ElapsedMilliseconds); 
} 

public static void MultiLineTest() 
{ 
    Stopwatch stopwatch = new Stopwatch(); 
    stopwatch.Start(); 
    int count = 0; 
    for (uint i = 0; i < 1000000000; ++i) { 
     var isMultipleOf16 = i % 16 == 0; 
     count += isMultipleOf16 ? 1 : 0; 
    } 
    stopwatch.Stop(); 
    Console.WriteLine("Multi-line test --> Count: {0}, Time: {1}", count, stopwatch.ElapsedMilliseconds); 
} 

La única diferencia es la introducción de una variable local, que afecta el código ensamblador generado y el rendimiento de bucle. Por qué ese es el caso es un question in its own right.

Posiblemente aún más extraño es que en x86 (pero no x64), el orden en que se invocan los métodos tiene un impacto de alrededor del 20% en el rendimiento. Invocar los métodos como este ...

static void Main() 
{ 
    SingleLineTest(); 
    MultiLineTest(); 
} 

... SingleLineTest y es más rápido. (Compilar utilizando la configuración de lanzamiento 86, asegurando que "Optimizar código" opción está habilitada, y ejecute la prueba de VS2010 exterior.) Sin embargo, invertir el orden ...

static void Main() 
{ 
    MultiLineTest(); 
    SingleLineTest(); 
} 

... y ambos métodos tienen el mismo tiempo (casi, pero no del todo, siempre y cuando MultiLineTest antes). (Al ejecutar esta prueba, es útil agregar algunas llamadas adicionales al SingleLineTest y MultiLineTest para obtener muestras adicionales. Cuantos y qué orden no importa, excepto por qué método se llama primero.)

Por último, para demostrar que para JIT es importante, dejar MultiLineTest principio, pero la fuerza que se SingleLineTest JITed primera ...

static void Main() 
{ 
    RuntimeHelpers.PrepareMethod(typeof(Program).GetMethod("SingleLineTest").MethodHandle); 
    MultiLineTest(); 
    SingleLineTest(); 
} 

Ahora, SingleLineTest es más rápido de nuevo.

Si desactiva "Suprimir la optimización de JIT en la carga del módulo" en VS2010, puede poner un punto de interrupción en SingleLineTest y ver que el código de ensamblaje en el bucle sea el mismo independientemente del orden de JIT; sin embargo, el código de ensamblaje al comienzo del método varía. Pero cómo esto importa cuando se pasa la mayor parte del tiempo en el circuito es desconcertante.

A sample project demonstrating this behavior está en github.

No está claro cómo este comportamiento afecta a las aplicaciones del mundo real. Una preocupación es que puede hacer que el ajuste del rendimiento sea volátil, dependiendo de la orden en que los métodos se llamen primero. Los problemas de este tipo serían difíciles de detectar con un generador de perfiles. Una vez que encontraste los puntos de acceso y optimizaste sus algoritmos, sería difícil saberlo sin mucha conjetura y comprobar si es posible una aceleración adicional mediante métodos JITing.

Actualización: Consulte también el Microsoft Connect entry para este problema.

+0

"... tiene alrededor de un 20% de impacto en el rendimiento" tengo alrededor de 8% –

+1

¿Es la alineación (de las instrucciones reales) la misma? O estar JITted siguiendo el otro método, o el cambio menor en el preámbulo, realmente podría atornillar con la alineación. –

+0

@lukas En dos computadoras, cada una con Intel Core i5s, obtuve un promedio de 1412ms y 1490ms para 'SingleLineTest' y 1773ms y 1792ms para' MultiLineTest'. Esto funciona con aceleraciones de 26% y 20%. Para cada computadora, la desviación estándar para la aceleración llegó al 2%. Hubiera esperado ver alguna diferencia entre las máquinas, pero el 8% es sorprendente. –

Respuesta

25

Tenga en cuenta que no confío en la opción "Suprimir JIT optimización en la carga del módulo", genero el proceso sin depurar y adjunto mi depurador después de que se haya ejecutado el JIT.

En la versión en línea de un solo corre más rápido, esto es Main:

 SingleLineTest(); 
00000000 push  ebp 
00000001 mov   ebp,esp 
00000003 call  dword ptr ds:[0019380Ch] 
      MultiLineTest(); 
00000009 call  dword ptr ds:[00193818h] 
      SingleLineTest(); 
0000000f call  dword ptr ds:[0019380Ch] 
      MultiLineTest(); 
00000015 call  dword ptr ds:[00193818h] 
      SingleLineTest(); 
0000001b call  dword ptr ds:[0019380Ch] 
      MultiLineTest(); 
00000021 call  dword ptr ds:[00193818h] 
00000027 pop   ebp 
     } 
00000028 ret 

Tenga en cuenta que MultiLineTest se ha colocado en un límite de 8 bytes y SingleLineTest en un límite de 4 bytes.

Aquí es Main para la versión en la que ambos corren a la misma velocidad:

  MultiLineTest(); 
00000000 push  ebp 
00000001 mov   ebp,esp 
00000003 call  dword ptr ds:[00153818h] 

      SingleLineTest(); 
00000009 call  dword ptr ds:[0015380Ch] 
      MultiLineTest(); 
0000000f call  dword ptr ds:[00153818h] 
      SingleLineTest(); 
00000015 call  dword ptr ds:[0015380Ch] 
      MultiLineTest(); 
0000001b call  dword ptr ds:[00153818h] 
      SingleLineTest(); 
00000021 call  dword ptr ds:[0015380Ch] 
      MultiLineTest(); 
00000027 call  dword ptr ds:[00153818h] 
0000002d pop   ebp 
     } 
0000002e ret 

Sorprendentemente, las direcciones elegidas por el JIT son idéntica en los últimos 4 dígitos, a pesar de que supuestamente les procesa en el orden opuesto. No estoy seguro de creer eso más.

Se necesita más excavación. Creo que se mencionó que el código antes del ciclo no era exactamente igual en ambas versiones? Yendo a investigar

Aquí está la versión "lenta" de SingleLineTest (y comprobé, los últimos dígitos de la dirección de la función no han cambiado).

  Stopwatch stopwatch = new Stopwatch(); 
00000000 push  ebp 
00000001 mov   ebp,esp 
00000003 push  edi 
00000004 push  esi 
00000005 push  ebx 
00000006 mov   ecx,7A5A2C68h 
0000000b call  FFF91EA0 
00000010 mov   esi,eax 
00000012 mov   dword ptr [esi+4],0 
00000019 mov   dword ptr [esi+8],0 
00000020 mov   byte ptr [esi+14h],0 
00000024 mov   dword ptr [esi+0Ch],0 
0000002b mov   dword ptr [esi+10h],0 
      stopwatch.Start(); 
00000032 cmp   byte ptr [esi+14h],0 
00000036 jne   00000047 
00000038 call  7A22B314 
0000003d mov   dword ptr [esi+0Ch],eax 
00000040 mov   dword ptr [esi+10h],edx 
00000043 mov   byte ptr [esi+14h],1 
      int count = 0; 
00000047 xor   edi,edi 
      for (uint i = 0; i < 1000000000; ++i) { 
00000049 xor   edx,edx 
       count += i % 16 == 0 ? 1 : 0; 
0000004b mov   eax,edx 
0000004d and   eax,0Fh 
00000050 test  eax,eax 
00000052 je   00000058 
00000054 xor   eax,eax 
00000056 jmp   0000005D 
00000058 mov   eax,1 
0000005d add   edi,eax 
      for (uint i = 0; i < 1000000000; ++i) { 
0000005f inc   edx 
00000060 cmp   edx,3B9ACA00h 
00000066 jb   0000004B 
      } 
      stopwatch.Stop(); 
00000068 mov   ecx,esi 
0000006a call  7A23F2C0 
      Console.WriteLine("Single-line test --> Count: {0}, Time: {1}", count, stopwatch.ElapsedMilliseconds); 
0000006f mov   ecx,797C29B4h 
00000074 call  FFF91EA0 
00000079 mov   ecx,eax 
0000007b mov   dword ptr [ecx+4],edi 
0000007e mov   ebx,ecx 
00000080 mov   ecx,797BA240h 
00000085 call  FFF91EA0 
0000008a mov   edi,eax 
0000008c mov   ecx,esi 
0000008e call  7A23ABE8 
00000093 push  edx 
00000094 push  eax 
00000095 push  0 
00000097 push  2710h 
0000009c call  783247EC 
000000a1 mov   dword ptr [edi+4],eax 
000000a4 mov   dword ptr [edi+8],edx 
000000a7 mov   esi,edi 
000000a9 call  793C6F40 
000000ae push  ebx 
000000af push  esi 
000000b0 mov   ecx,eax 
000000b2 mov   edx,dword ptr ds:[03392034h] 
000000b8 mov   eax,dword ptr [ecx] 
000000ba mov   eax,dword ptr [eax+3Ch] 
000000bd call  dword ptr [eax+1Ch] 
000000c0 pop   ebx 
     } 
000000c1 pop   esi 
000000c2 pop   edi 
000000c3 pop   ebp 
000000c4 ret 

Y la "rápida" versión:

  Stopwatch stopwatch = new Stopwatch(); 
00000000 push  ebp 
00000001 mov   ebp,esp 
00000003 push  edi 
00000004 push  esi 
00000005 push  ebx 
00000006 mov   ecx,7A5A2C68h 
0000000b call  FFE11F70 
00000010 mov   esi,eax 
00000012 mov   ecx,esi 
00000014 call  7A1068BC 
      stopwatch.Start(); 
00000019 cmp   byte ptr [esi+14h],0 
0000001d jne   0000002E 
0000001f call  7A12B3E4 
00000024 mov   dword ptr [esi+0Ch],eax 
00000027 mov   dword ptr [esi+10h],edx 
0000002a mov   byte ptr [esi+14h],1 
      int count = 0; 
0000002e xor   edi,edi 
      for (uint i = 0; i < 1000000000; ++i) { 
00000030 xor   edx,edx 
       count += i % 16 == 0 ? 1 : 0; 
00000032 mov   eax,edx 
00000034 and   eax,0Fh 
00000037 test  eax,eax 
00000039 je   0000003F 
0000003b xor   eax,eax 
0000003d jmp   00000044 
0000003f mov   eax,1 
00000044 add   edi,eax 
      for (uint i = 0; i < 1000000000; ++i) { 
00000046 inc   edx 
00000047 cmp   edx,3B9ACA00h 
0000004d jb   00000032 
      } 
      stopwatch.Stop(); 
0000004f mov   ecx,esi 
00000051 call  7A13F390 
      Console.WriteLine("Single-line test --> Count: {0}, Time: {1}", count, stopwatch.ElapsedMilliseconds); 
00000056 mov   ecx,797C29B4h 
0000005b call  FFE11F70 
00000060 mov   ecx,eax 
00000062 mov   dword ptr [ecx+4],edi 
00000065 mov   ebx,ecx 
00000067 mov   ecx,797BA240h 
0000006c call  FFE11F70 
00000071 mov   edi,eax 
00000073 mov   ecx,esi 
00000075 call  7A13ACB8 
0000007a push  edx 
0000007b push  eax 
0000007c push  0 
0000007e push  2710h 
00000083 call  782248BC 
00000088 mov   dword ptr [edi+4],eax 
0000008b mov   dword ptr [edi+8],edx 
0000008e mov   esi,edi 
00000090 call  792C7010 
00000095 push  ebx 
00000096 push  esi 
00000097 mov   ecx,eax 
00000099 mov   edx,dword ptr ds:[03562030h] 
0000009f mov   eax,dword ptr [ecx] 
000000a1 mov   eax,dword ptr [eax+3Ch] 
000000a4 call  dword ptr [eax+1Ch] 
000000a7 pop   ebx 
     } 
000000a8 pop   esi 
000000a9 pop   edi 
000000aa pop   ebp 
000000ab ret 

Sólo los bucles, rápido a la izquierda, lento a la derecha:

00000030 xor   edx,edx     00000049 xor   edx,edx 
00000032 mov   eax,edx     0000004b mov   eax,edx 
00000034 and   eax,0Fh     0000004d and   eax,0Fh 
00000037 test  eax,eax     00000050 test  eax,eax 
00000039 je   0000003F    00000052 je   00000058 
0000003b xor   eax,eax     00000054 xor   eax,eax 
0000003d jmp   00000044    00000056 jmp   0000005D 
0000003f mov   eax,1     00000058 mov   eax,1 
00000044 add   edi,eax     0000005d add   edi,eax 
00000046 inc   edx      0000005f inc   edx 
00000047 cmp   edx,3B9ACA00h   00000060 cmp   edx,3B9ACA00h 
0000004d jb   00000032    00000066 jb   0000004B 

Las instrucciones son idéntica (siendo saltos relativos, el código de máquina es idéntico aunque el desmontaje muestra direcciones diferentes), pero la alineación es diferente. Hay tres saltos. el je cargando una constante 1 está alineado en la versión lenta y no en la versión rápida, pero apenas importa, ya que ese salto solo se toma 1/16 del tiempo. Los otros dos saltos (jmp después de cargar un cero constante y jb repitiendo todo el ciclo) se toman millones de veces más y se alinean en la versión "rápida".

Creo que esta es la pistola humeante.

+0

"los últimos dígitos de la dirección de la función no han cambiado" también es cierto para mí, pero mi salida de desensamblaje es de 104 líneas, donde esta es una 75. –

+0

@lukas: ¿Está buscando un código optimizado x86? –

+0

sí. Pestaña de compilación: el objetivo es x86, el código de optimización está marcado y obtuve el asm de Depurar -> Windows -> Desmontaje –

0

Por lo tanto, para una respuesta definitiva ... Sospecho que tendremos que profundizar en el desmontaje.

Sin embargo, tengo una conjetura. El compilador del SingleLineTest() almacena cada resultado de la ecuación en la pila y muestra cada valor según sea necesario. Sin embargo, el MultiLineTest() puede almacenar valores y tener que acceder a ellos desde allí. Esto podría ocasionar que se pierdan algunos ciclos de reloj. Donde como agarrar los valores de la pila lo mantendrán en un registro.

Curiosamente, cambiar el orden de la compilación de funciones puede estar ajustando las acciones del recolector de elementos no utilizados. Como isMultipleOf16 se define dentro del ciclo, se puede manejar de forma divertida.Es posible que desee mover la definición fuera del ciclo y ver qué cambia ...

+0

Dado que 'isMultipleOf16' es un tipo de valor, se almacena en la pila y no es tocado por el GC. Aparte del cronómetro y la salida de la consola, el GC no debería estar haciendo nada. –

+0

Ah, buen punto. ¿Has mirado el desmontaje en absoluto? – Andrew

+0

"Como isMultipleOf16 es un tipo de valor, se almacena en la pila y el GC no lo toca" Eso es incorrecto. No hay tal garantía. JITer puede mover el tipo de valor al montón. Pero supongo que ese no es el caso aquí. –

0

Mi tiempo es 2400 y 2600 en 2,3Ghz i5-2410M 4GB RAM de 64 bits: Gana 7.

Aquí está mi salida: Solo primer

Después de iniciar el proceso y luego adjuntar el depurador

  SingleLineTest(); 
      MultiLineTest(); 
      SingleLineTest(); 
      MultiLineTest(); 
      SingleLineTest(); 
      MultiLineTest(); 
-------------------------------- 
SingleLineTest() 
      Stopwatch stopwatch = new Stopwatch(); 
00000000 push  ebp 
00000001 mov   ebp,esp 
00000003 push  edi 
00000004 push  esi 
00000005 push  ebx 
00000006 mov   ecx,685D2C68h 
0000000b call  FFD91F70 
00000010 mov   esi,eax 
00000012 mov   ecx,esi 
00000014 call  681D68BC 
      stopwatch.Start(); 
00000019 cmp   byte ptr [esi+14h],0 
0000001d jne   0000002E 
0000001f call  681FB3E4 
00000024 mov   dword ptr [esi+0Ch],eax 
00000027 mov   dword ptr [esi+10h],edx 
0000002a mov   byte ptr [esi+14h],1 
      int count = 0; 
0000002e xor   edi,edi 
      for (int i = 0; i < 1000000000; ++i) 
00000030 xor   edx,edx 
      { 
       count += i % 16 == 0 ? 1 : 0; 
00000032 mov   eax,edx 
00000034 and   eax,8000000Fh 
00000039 jns   00000040 
0000003b dec   eax 
0000003c or   eax,0FFFFFFF0h 
0000003f inc   eax 
00000040 test  eax,eax 
00000042 je   00000048 
00000044 xor   eax,eax 
00000046 jmp   0000004D 
00000048 mov   eax,1 
0000004d add   edi,eax 
      for (int i = 0; i < 1000000000; ++i) 
0000004f inc   edx 
00000050 cmp   edx,3B9ACA00h 
00000056 jl   00000032 
      } 
      stopwatch.Stop(); 
00000058 mov   ecx,esi 
0000005a call  6820F390 
      Console.WriteLine("Single-line test --> Count: {0}, Time: {1}", count, stopwatch.ElapsedMilliseconds); 
0000005f mov   ecx,6A8B29B4h 
00000064 call  FFD91F70 
00000069 mov   ecx,eax 
0000006b mov   dword ptr [ecx+4],edi 
0000006e mov   ebx,ecx 
00000070 mov   ecx,6A8AA240h 
00000075 call  FFD91F70 
0000007a mov   edi,eax 
0000007c mov   ecx,esi 
0000007e call  6820ACB8 
00000083 push  edx 
00000084 push  eax 
00000085 push  0 
00000087 push  2710h 
0000008c call  6AFF48BC 
00000091 mov   dword ptr [edi+4],eax 
00000094 mov   dword ptr [edi+8],edx 
00000097 mov   esi,edi 
00000099 call  6A457010 
0000009e push  ebx 
0000009f push  esi 
000000a0 mov   ecx,eax 
000000a2 mov   edx,dword ptr ds:[039F2030h] 
000000a8 mov   eax,dword ptr [ecx] 
000000aa mov   eax,dword ptr [eax+3Ch] 
000000ad call  dword ptr [eax+1Ch] 
000000b0 pop   ebx 
     } 
000000b1 pop   esi 
000000b2 pop   edi 
000000b3 pop   ebp 
000000b4 ret 

Multi primera:

  MultiLineTest(); 

      SingleLineTest(); 
      MultiLineTest(); 
      SingleLineTest(); 
      MultiLineTest(); 
      SingleLineTest(); 
      MultiLineTest(); 
-------------------------------- 
SingleLineTest() 
      Stopwatch stopwatch = new Stopwatch(); 
00000000 push  ebp 
00000001 mov   ebp,esp 
00000003 push  edi 
00000004 push  esi 
00000005 push  ebx 
00000006 mov   ecx,685D2C68h 
0000000b call  FFF31EA0 
00000010 mov   esi,eax 
00000012 mov   dword ptr [esi+4],0 
00000019 mov   dword ptr [esi+8],0 
00000020 mov   byte ptr [esi+14h],0 
00000024 mov   dword ptr [esi+0Ch],0 
0000002b mov   dword ptr [esi+10h],0 
      stopwatch.Start(); 
00000032 cmp   byte ptr [esi+14h],0 
00000036 jne   00000047 
00000038 call  682AB314 
0000003d mov   dword ptr [esi+0Ch],eax 
00000040 mov   dword ptr [esi+10h],edx 
00000043 mov   byte ptr [esi+14h],1 
      int count = 0; 
00000047 xor   edi,edi 
      for (int i = 0; i < 1000000000; ++i) 
00000049 xor   edx,edx 
      { 
       count += i % 16 == 0 ? 1 : 0; 
0000004b mov   eax,edx 
0000004d and   eax,8000000Fh 
00000052 jns   00000059 
00000054 dec   eax 
00000055 or   eax,0FFFFFFF0h 
00000058 inc   eax 
00000059 test  eax,eax 
0000005b je   00000061 
0000005d xor   eax,eax 
0000005f jmp   00000066 
00000061 mov   eax,1 
00000066 add   edi,eax 
      for (int i = 0; i < 1000000000; ++i) 
00000068 inc   edx 
00000069 cmp   edx,3B9ACA00h 
0000006f jl   0000004B 
      } 
      stopwatch.Stop(); 
00000071 mov   ecx,esi 
00000073 call  682BF2C0 
      Console.WriteLine("Single-line test --> Count: {0}, Time: {1}", count, stopwatch.ElapsedMilliseconds); 
00000078 mov   ecx,6A8B29B4h 
0000007d call  FFF31EA0 
00000082 mov   ecx,eax 
00000084 mov   dword ptr [ecx+4],edi 
00000087 mov   ebx,ecx 
00000089 mov   ecx,6A8AA240h 
0000008e call  FFF31EA0 
00000093 mov   edi,eax 
00000095 mov   ecx,esi 
00000097 call  682BABE8 
0000009c push  edx 
0000009d push  eax 
0000009e push  0 
000000a0 push  2710h 
000000a5 call  6B0A47EC 
000000aa mov   dword ptr [edi+4],eax 
000000ad mov   dword ptr [edi+8],edx 
000000b0 mov   esi,edi 
000000b2 call  6A506F40 
000000b7 push  ebx 
000000b8 push  esi 
000000b9 mov   ecx,eax 
000000bb mov   edx,dword ptr ds:[038E2034h] 
000000c1 mov   eax,dword ptr [ecx] 
000000c3 mov   eax,dword ptr [eax+3Ch] 
000000c6 call  dword ptr [eax+1Ch] 
000000c9 pop   ebx 
     } 
000000ca pop   esi 
000000cb pop   edi 
000000cc pop   ebp 
000000cd ret 
+0

¿Ver esas instrucciones 'nop'? Creo que esto no está optimizado, ejecutándose dentro de las optimizaciones suprimidas del depurador. –

+0

@Ben Sí, adjunté el depurador más tarde, sin embargo, la salida es un poco diferente. –

Cuestiones relacionadas