¿Qué tan eficaz es StackFrame?

Question

Estoy considerando utilizar algo como StackFrame stackFrame = new StackFrame(1) para registrar el método de ejecución, pero no sé sobre sus implicaciones de rendimiento. ¿La pila rastrea algo que se construye de todos modos con cada llamada a un método para que el rendimiento no sea una preocupación o es algo que solo se construye cuando se lo solicita? ¿Recomiendas esto en una aplicación donde el rendimiento es muy importante? Si es así, ¿significa eso que debo deshabilitarlo para el lanzamiento?

Answer 1

edición: Algunos antecedentes

---

Tenemos una característica similar que está desactivado el 99% de las veces; estábamos usando un enfoque como:

public void DoSomething() 
{ 
    TraceCall(MethodBase.GetCurrentMethod().Name); 
    // Do Something 
} 

public void TraceCall(string methodName) 
{ 
    if (!loggingEnabled) { return; } 
    // Log... 
} 

TraceCall(MethodBase.GetCurrentMethod().Name) 

Era simple, pero independientemente de si es o no el rastreo se ha activado estábamos incurriendo el impacto en el rendimiento de la utilización de reflexión para buscar el nombre del método.

Nuestras opciones eran o bien requieren más código en cada método (y errores simples de riesgo o rechazo) o para cambiar al uso de StackFrame para determinar el método de llamada única cuando el registro fue habilitado.

Opción A:

public void DoSomething() 
{ 
    if (loggingEnabled) 
    { 
     TraceCall(MethodBase.GetCurrentMethod().Name); 
    } 
    // Do Something 
} 

public void TraceCall(string methodName) 
{ 
    if (!loggingEnabled) { return; } 
    // Log... 
} 

Opción B:

public void DoSomething() 
{ 
    TraceCall(); 
    // Do Something 
} 

public void TraceCall() 
{ 
    if (!loggingEnabled) { return; } 
    StackFrame stackFrame = new StackFrame(1); 
    // Log... 
} 

Optamos por la opción B. Se ofrece mejoras de rendimiento significativas sobre la Opción A al iniciar sesión está desactivado, el 99% de las veces y es muy simple de implementar.

Aquí es una alteración del código de Michael, para mostrar la relación costo/beneficio de este enfoque

using System; 
using System.Diagnostics; 
using System.Reflection; 

namespace ConsoleApplication 
{ 
    class Program 
    { 
     static bool traceCalls; 

     static void Main(string[] args) 
     { 
      Stopwatch sw; 

      // warm up 
      for (int i = 0; i < 100000; i++) 
      { 
       TraceCall(); 
      } 

      // call 100K times, tracing *disabled*, passing method name 
      sw = Stopwatch.StartNew(); 
      traceCalls = false; 
      for (int i = 0; i < 100000; i++) 
      { 
       TraceCall(MethodBase.GetCurrentMethod()); 
      } 
      sw.Stop(); 
      Console.WriteLine("Tracing Disabled, passing Method Name: {0}ms" 
          , sw.ElapsedMilliseconds); 

      // call 100K times, tracing *enabled*, passing method name 
      sw = Stopwatch.StartNew(); 
      traceCalls = true; 
      for (int i = 0; i < 100000; i++) 
      { 
       TraceCall(MethodBase.GetCurrentMethod()); 
      } 
      sw.Stop(); 
      Console.WriteLine("Tracing Enabled, passing Method Name: {0}ms" 
          , sw.ElapsedMilliseconds); 

      // call 100K times, tracing *disabled*, determining method name 
      sw = Stopwatch.StartNew(); 
      traceCalls = false; 
      for (int i = 0; i < 100000; i++) 
      { 
       TraceCall(); 
      } 
      Console.WriteLine("Tracing Disabled, looking up Method Name: {0}ms" 
         , sw.ElapsedMilliseconds); 

      // call 100K times, tracing *enabled*, determining method name 
      sw = Stopwatch.StartNew(); 
      traceCalls = true; 
      for (int i = 0; i < 100000; i++) 
      { 
       TraceCall(); 
      } 
      Console.WriteLine("Tracing Enabled, looking up Method Name: {0}ms" 
         , sw.ElapsedMilliseconds); 

      Console.ReadKey(); 
     } 

     private static void TraceCall() 
     { 
      if (traceCalls) 
      { 
       StackFrame stackFrame = new StackFrame(1); 
       TraceCall(stackFrame.GetMethod().Name); 
      } 
     } 

     private static void TraceCall(MethodBase method) 
     { 
      if (traceCalls) 
      { 
       TraceCall(method.Name); 
      } 
     } 

     private static void TraceCall(string methodName) 
     { 
      // Write to log 
     } 
    } 
} 

Los Resultados:

Tracing Disabled, passing Method Name: 294ms 
Tracing Enabled, passing Method Name: 298ms 
Tracing Disabled, looking up Method Name: 0ms 
Tracing Enabled, looking up Method Name: 1230ms 

Answer 2

De la documentación de MSDN, parece que StackFrames se están creando todo el tiempo:

Un StackFrame se crea y se empujaron en la pila de llamadas para cada llamada a la función realizado durante la ejecución de un hilo. El marco de la pila siempre incluye información de MethodBase y, opcionalmente, incluye el nombre del archivo, el número de línea y la información del número de columna .

El constructor new StackFrame(1) que se dice podría hacer esto:

private void BuildStackFrame(int skipFrames, bool fNeedFileInfo) 
{ 
    StackFrameHelper sfh = new StackFrameHelper(fNeedFileInfo, null); 
    StackTrace.GetStackFramesInternal(sfh, 0, null); 
    int numberOfFrames = sfh.GetNumberOfFrames(); 
    skipFrames += StackTrace.CalculateFramesToSkip(sfh, numberOfFrames); 
    if ((numberOfFrames - skipFrames) > 0) 
    { 
     this.method = sfh.GetMethodBase(skipFrames); 
     this.offset = sfh.GetOffset(skipFrames); 
     this.ILOffset = sfh.GetILOffset(skipFrames); 
     if (fNeedFileInfo) 
     { 
      this.strFileName = sfh.GetFilename(skipFrames); 
      this.iLineNumber = sfh.GetLineNumber(skipFrames); 
      this.iColumnNumber = sfh.GetColumnNumber(skipFrames); 
     } 
    } 
} 

GetStackFramesInternal es un método externo. CalculateFramesToSkip tiene un bucle que funciona exactamente una vez, ya que especificó solo 1 fotograma. Todo lo demás se ve bastante rápido.

¿Ha intentado medir cuánto tardaría en crear, digamos, 1 millón de ellas?

Answer 3

Una prueba rápida e ingenuo indica que para el código sensibles al rendimiento, sí, usted quiere prestar atención a esto:

No generar marcos 100K: 3 ms

Generar marcos 100K: 1805ms

Alrededor de 20 microsegundos por fotograma generado, en mi máquina. No mucho, pero una diferencia medible en un gran número de iteraciones.

Hablando de sus preguntas posteriores ("¿Debo deshabilitar la generación de StackFrame en mi aplicación?"), Le sugiero que analice su aplicación, realice pruebas de rendimiento como la que hice aquí y vea si la diferencia de rendimiento equivale a cualquier cosa con su carga de trabajo.

using System; 
using System.Diagnostics; 

namespace ConsoleApplication 
{ 
    class Program 
    { 
     static bool generateFrame; 

     static void Main(string[] args) 
     { 
      Stopwatch sw; 

      // warm up 
      for (int i = 0; i < 100000; i++) 
      { 
       CallA(); 
      } 

      // call 100K times; no stackframes 
      sw = Stopwatch.StartNew(); 
      for (int i = 0; i < 100000; i++) 
      { 
       CallA(); 
      } 
      sw.Stop(); 
      Console.WriteLine("Don't generate 100K frames: {0}ms" 
           , sw.ElapsedMilliseconds); 

      // call 100K times; generate stackframes 
      generateFrame = true; 
      sw = Stopwatch.StartNew(); 
      for (int i = 0; i < 100000; i++) 
      { 
       CallA(); 
      } 
      Console.WriteLine("Generate 100K frames: {0}ms" 
          , sw.ElapsedMilliseconds); 

      Console.ReadKey(); 
     } 

     private static void CallA() 
     { 
      CallB(); 
     } 

     private static void CallB() 
     { 
      CallC(); 
     } 

     private static void CallC() 
     { 
      if (generateFrame) 
      { 
       StackFrame stackFrame = new StackFrame(1); 
      } 
     } 
    } 
} 

Answer 4

Estoy pensando en usar algo como StackFrame StackFrame = new StackFrame (1) para registrar el método de ejecución

Fuera de interés: ¿Por qué? Si solo quiere el método actual, entonces

string methodName = System.Reflection.MethodBase.GetCurrentMethod().Name; 

parece mejor. Quizás no sea más eficiente (no lo comparé, pero Reflection muestra que GetCurrentMethod() no crea simplemente un StackFrame sino que hace algo de "magia"), pero es más claro en su intención.

Answer 5

Creo que Paul Williams dio en el clavo con el trabajo hecho. Si profundiza en StackFrameHelper, encontrará que fNeedFileInfo es en realidad el factor determinante del rendimiento, especialmente en el modo de depuración. Intente configurarlo falso si el rendimiento es importante. De todos modos, no obtendrá mucha información útil en el modo de lanzamiento.

Si pasa falsa aquí todavía tendrá los nombres de método cuando se hace una ToString() y sin emitir ninguna información, sólo mover punteros de pila alrededor, es muy rápido.

Answer 6

Sé lo que quiere decir, pero este resultado de ejemplo es un exceso. Ejecutar GetCurrentMethod incluso cuando el registro está desactivado es una pérdida. Debería ser algo como:

if (loggingEnabled) TraceCall(MethodBase.GetCurrentMethod()); 

O si desea que el TraceCall siempre ejecutados:

TraceCall(loggingEnabled ? MethodBase.GetCurrentMethod() : null); 

Answer 7

Sé que esto es una entrada antigua, pero por si acaso alguno viene a través de ella hay otra alternativa si tiene como objetivo .Net 4.5

Puede usar el atributo CallerMemberName para identificar el nombre del método de llamada. Es mucho más rápido que la reflexión o StackFrame. Aquí están los resultados de una prueba rápida que se repite un millón de veces. StackFrame es extremadamente lento en comparación con la reflexión, y el nuevo atributo hace que ambos parezcan estar quietos. Esto se ejecutó en el IDE.

Reflexión Resultado: 00: 00: 01,4098808

StackFrame Resultado 00:00:06.2002501

CallerMemberName atributo Resultado: 00: 00: 00,0042708

Hecho

La siguiente es desde el exe compilado: Reflexión Resultado: 00: 00: 01,2136738 StackFrame Resultado 00: 00: 03.6343924 CallerMemberName attribute Resultado: 00: 00: 00.0000947 Hecho

 static void Main(string[] args) 
    { 

     Stopwatch sw = new Stopwatch(); 

     sw.Stop(); 

     Console.WriteLine("Reflection Result:"); 

     sw.Start(); 
     for (int i = 0; i < 1000000; i++) 
     { 
      //Using reflection to get the current method name. 
      PassedName(MethodBase.GetCurrentMethod().Name); 
     } 
     Console.WriteLine(sw.Elapsed); 

     Console.WriteLine("StackFrame Result"); 

     sw.Restart(); 

     for (int i = 0; i < 1000000; i++) 
     { 
      UsingStackFrame(); 
     } 

     Console.WriteLine(sw.Elapsed); 

     Console.WriteLine("CallerMemberName attribute Result:"); 

     sw.Restart(); 
     for (int i = 0; i < 1000000; i++) 
     { 
      UsingCallerAttribute(); 
     } 

     Console.WriteLine(sw.Elapsed); 

     sw.Stop(); 



     Console.WriteLine("Done"); 
     Console.Read(); 
    } 


    static void PassedName(string name) 
    { 

    } 

    static void UsingStackFrame() 
    { 
     string name = new StackFrame(1).GetMethod().Name; 
    } 


    static void UsingCallerAttribute([CallerMemberName] string memberName = "") 
    { 

    }