Quanto performante è StackFrame?

Question

Sto considerando l'utilizzo di qualcosa come StackFrame stackFrame = new StackFrame(1) per registrare il metodo di esecuzione, ma non conosco le sue implicazioni sulle prestazioni. Lo stack traccia qualcosa che è comunque costruito con ogni chiamata di metodo, quindi le prestazioni non dovrebbero essere un problema o è qualcosa che viene creato solo quando richiesto? Ti raccomandi contro di esso in un'applicazione in cui le prestazioni sono molto importanti? Se è così, significa che dovrei disabilitarlo per il rilascio?

Answer 1

edit: Alcuni retroscena

---

Abbiamo una caratteristica simile che è disattivata il 99% del tempo; abbiamo utilizzato un approccio come:

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

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

TraceCall(MethodBase.GetCurrentMethod().Name) 

Era semplice, ma indipendentemente dal fatto che il tracciamento è stata abilitata siamo stati incorrere il calo di prestazioni di utilizzare Reflection per cercare il nome del metodo.

Le nostre opzioni erano a uno richiedere più il codice a ogni metodo (e di rischio semplici errori o il rifiuto) o per passare ad usare StackFrame per determinare il metodo chiamante solo quando la registrazione è stato attivato.

Opzione A:

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

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

Opzione B:

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

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

Abbiamo optato per l'opzione B. Offre significativi miglioramenti delle prestazioni oltre Opzione A quando la registrazione è disattivata, il 99% del tempo ed è molto semplice da implementare.

Ecco un'alterazione del codice di Michael, per visualizzare il rapporto costi/benefici di questo approccio

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

I risultati:

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

Dalla documentazione MSDN, sembra StackFrames vengono creati in continuazione:

Uno StackFrame viene creato e spinto sul nello stack di chiamate per ogni funzione di chiamata fatta durante l'esecuzione di un thread. Il frame dello stack include sempre le informazioni su MethodBase e, opzionalmente, include il nome del file, il numero di riga e le informazioni sul numero di colonna .

Il costruttore new StackFrame(1) si chiamerebbe farebbe questo:

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 è un metodo esterno. CalculateFramesToSkip ha un ciclo che opera esattamente una volta, poiché hai specificato solo 1 fotogramma. Tutto il resto sembra abbastanza veloce.

Hai provato a misurare il tempo necessario per creare, diciamo, 1 milione di loro?

Answer 3

Un test rapido ed ingenuo indica che per il codice prestazioni sensibili, sì, si vuole prestare attenzione a questo:

Non generare 100K frames: 3ms

Generare 100K fotogrammi: 1805ms

Sulla mia macchina circa 20 microsecondi per frame generato. Non molto, ma una differenza misurabile su un gran numero di iterazioni.

Parlando alle tue domande successive ("Devo disabilitare la generazione di StackFrame nella mia applicazione?"), Ti suggerisco di analizzare la tua applicazione, fare test delle prestazioni come quello che ho fatto qui e vedere se la differenza di prestazioni equivale a qualsiasi cosa con il tuo carico di lavoro.

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

sto valutando usando qualcosa come StackFrame StackFrame = new StackFrame (1) per registrare il metodo di esecuzione

Interesse: perché? Se si desidera solo il metodo corrente, quindi

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

sembra meglio. Forse non più performante (non ho confrontato, ma Reflection mostra che GetCurrentMethod() non crea semplicemente uno StackFrame ma fa un po 'di "magia"), ma è più chiaro nel suo intento.

Answer 5

Penso che Paul Williams abbia centrato la testa con il lavoro svolto. Se scorri più in profondità nello StackFrameHelper troverai che lo fNeedFileInfo è in realtà il killer delle prestazioni, specialmente in modalità di debug. Prova a impostarlo false se le prestazioni sono importanti. Non otterrai comunque molte informazioni utili in modalità di rilascio.

Se si passa falso qui ci si può comunque nomi di metodo quando si fa un ToString() e senza emettere alcuna informazione, semplicemente spostando i puntatori dello stack intorno, è molto veloce.

Answer 6

So cosa intendi, ma questo risultato di esempio è overshoot. L'esecuzione di GetCurrentMethod anche quando la registrazione è disattivata è uno spreco. Dovrebbe essere qualcosa di simile:

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

Oppure, se si desidera che il TraceCall sempre eseguita:

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

Answer 7

So che questo è un vecchio post, ma solo nel caso in cui qualcuno si imbatte in essa c'è un'altra alternativa se si sta prendendo di mira. Net 4.5

È possibile utilizzare l'attributo CallerMemberName per identificare il nome del metodo di chiamata. È molto più veloce del riflesso o StackFrame. Ecco i risultati di un rapido test che itera un milione di volte. StackFrame è estremamente lento rispetto al riflesso e il nuovo attributo fa sembrare entrambi immobili. Questo è stato eseguito nell'IDE.

Riflessione Risultato: 00: 00: 01,4098808

StackFrame Risultato 00:00:06.2002501

CallerMemberName attributo Risultato: 00: 00: 00,0042708

Fatto

Il seguente è dalla exe compilato: Riflessione risultati: 00: 00: 01,2136738 StackFrame Risultato 00: 00: 03.6343924 Attributo CallerMemberName Risultato: 00: 00: 00.0000947 Fine

 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 = "") 
    { 

    }