¿Cómo medir el rendimiento del código en .NET?

Estoy haciendo un benchmarking realmente rápido y sucio en una sola línea de código C # usando DateTime:

long lStart = DateTime.Now.Ticks; // do something long lFinish = DateTime.Now.Ticks; 

El problema está en los resultados:

 Hora de inicio [633679466564559902]
 Hora de finalización [633679466564559902]

 Hora de inicio [633679466564569917]
 Hora de finalización [633679466564569917]

 Hora de inicio [633679466564579932]
 Hora de finalización [633679466564579932]

…y así.

Dado que los tiempos de inicio y finalización son idénticos, Ticks obviamente no es lo suficientemente granular.

Entonces, ¿cómo puedo medir mejor el rendimiento?

La clase Stopwatch , disponible desde .NET 2.0, es la mejor forma de hacerlo. Es un contador de muy alto rendimiento con precisión de fracciones de milisegundos. Eche un vistazo a la documentación de MSDN , que es bastante clara.

EDITAR: Como se sugirió anteriormente, también es recomendable ejecutar su código varias veces para obtener un tiempo promedio razonable.

Ejecuta tu código repetidamente. El problema parece ser que su código se ejecuta mucho más rápido que la granularidad de su instrumento de medición. La solución más simple para esto es ejecutar su código muchas, muchas veces (miles, tal vez millones) y luego calcular el tiempo promedio de ejecución.

Editar: Además, debido a la naturaleza de los comstackdores de optimización actuales (y máquinas virtuales como CLR y JVM), puede ser muy engañoso medir la velocidad de ejecución de líneas únicas de código, ya que la medición puede influir bastante en la velocidad. . Un enfoque mucho mejor sería perfilar todo el sistema (o al menos bloques más grandes) y verificar dónde están los cuellos de botella.

Encuentro estos útiles

http://accelero.codeplex.com/SourceControl/changeset/view/22633#290971 http://accelero.codeplex.com/SourceControl/changeset/view/22633#290973 http://accelero.codeplex.com/SourceControl/ conjunto de cambios / view / 22633 # 290972

TickTimer es una copia reducida de Cronómetro que se inicia cuando se construye y no admite el reinicio. También le notificará si el hardware actual no es compatible con el tiempo de alta resolución (el cronómetro se traga este problema)

Así que esto

 var tickTimer = new TickTimer(); //call a method that takes some time DoStuff(); tickTimer.Stop(); Debug.WriteLine("Elapsed HighResElapsedTicks " + tickTimer.HighResElapsedTicks); Debug.WriteLine("Elapsed DateTimeElapsedTicks " + tickTimer.DateTimeElapsedTicks); Debug.WriteLine("Elapsed ElapsedMilliseconds " + tickTimer.ElapsedMilliseconds); Debug.WriteLine("Start Time " + new DateTime(tickTimer.DateTimeUtcStartTicks).ToLocalTime().ToLongTimeString()); 

dará salida a esto

 Elapsed HighResElapsedTicks 10022886 Elapsed DateTimeElapsedTicks 41896 Elapsed ElapsedMilliseconds 4.18966178849554 Start Time 11:44:58 

DebugTimer es un contenedor para TickTimer que escribirá el resultado en Debug. (nota: admite el patrón Desechable)

Así que esto

 using (new DebugTimer("DoStuff")) { //call a method that takes some time DoStuff(); } 

lo enviará a la ventana de depuración

 DoStuff: Total 3.6299 ms 

IterationDebugTimer es para cronometrar cuánto tiempo lleva ejecutar una operación varias veces y escribir el resultado en Debug. También realizará una ejecución inicial que no está incluida para ignorar el tiempo de inicio. (nota: admite el patrón Desechable)

Así que esto

 int x; using (var iterationDebugTimer = new IterationDebugTimer("Add", 100000)) { iterationDebugTimer.Run(() => { x = 1+4; }); } 

Producirá esto

 Add: Iterations 100000 Total 1.198540 ms Single 0.000012 ms 

Solo para agregar a lo que otros ya han dicho sobre el uso de Cronómetro y medición de promedios.

Asegúrese de llamar a su método antes de medir. De lo contrario, medirá el tiempo necesario para comstackr JIT también el código. Eso puede sesgar sus números de manera significativa.

Además, asegúrese de medir el código del modo de liberación ya que las optimizaciones están desactivadas de forma predeterminada para las comstackciones de depuración. Ajustar el código de depuración no tiene sentido.

Y asegúrese de medir lo que realmente quiere medir. Cuando las optimizaciones entran en juego, el comstackdor / comstackdor JIT puede reorganizar el código o eliminarlo por completo, por lo que puede terminar midiendo algo un poco diferente de lo previsto. Al menos eche un vistazo al código generado para asegurarse de que el código no se haya eliminado.

Dependiendo de lo que esté tratando de medir, tenga en cuenta que un sistema real acentuará el tiempo de ejecución de manera diferente que una aplicación de prueba típica. Algunos problemas de rendimiento se relacionan, por ejemplo, con la recolección de objetos como basura. Estos problemas generalmente no aparecerán en una aplicación de prueba simple.

En realidad, el mejor consejo es medir sistemas reales con datos reales, ya que las pruebas de espacio aislado pueden resultar muy imprecisas.

Use un generador de perfiles real como dotTrace.

Puede utilizar el Stopwatch , suponiendo que esté utilizando .NET 2.0 o posterior.

 System.Diagnostics.Stopwatch.StartNew(); 

La clase Stopwatch también tiene el campo público de solo lectura IsHighResolution que le permitirá saber si el cronómetro se basa en un contador de rendimiento de alta resolución. Si no es así, se basa en el temporizador del sistema.

No estoy seguro de qué se necesita para que el cronómetro se base en el contador de rendimiento de alta resolución. Hay algunas llamadas a la API, pero supongo que si el cronómetro no usa una resolución alta, entonces la API probablemente no esté allí.

Consulte la respuesta a ¿DateTime.Now es la mejor manera de medir el rendimiento de una función? para una explicación o leer mi blog sobre la medición de alto rendimiento

El problema es que DateTime tiene una resolución de aproximadamente 15 ms, no puede ser más preciso que eso. Cronómetro, sin embargo, puede.

Aquí hay una buena redacción en MSDN sobre cómo implementar un proveedor de tiempo de alta resolución y actualización continua para Windows

Aquí está el código fuente de muestra para el artículo (C ++).

Muestra para la clase Stopwatch

  using System.Diagnostics; ...... ... .. Stopwatch sw = new Stopwatch(); sw.Start(); //Your Code Here sw.Stop(); Console.WriteLine("Elapsed={0}",sw.Elapsed); 

https://andreyakinshin.gitbooks.io/performancebookdotnet/content/science/microbenchmarking.html

https://github.com/PerfDotNet/BenchmarkDotNet

“De hecho, la micro-identificación es muy difícil. Si una operación requiere de 10 a 100, la medición de la operación es un gran desafío. Le sugiero que use BenchmarkDotNet para sus puntos de referencia. Es una biblioteca que puede ayudarlo a establecer un punto de referencia honesto y obtener mediciones con buena precisión. Por supuesto, puede escribir su propio punto de referencia sin ninguna biblioteca adicional. En esta sección, hablamos sobre por qué es probablemente una mala idea y qué debe saber antes de comenzar “.

Este artículo de proyecto de código muestra cómo usar el temporizador de alto rendimiento para medir la velocidad de ejecución de su código:

http://www.codeproject.com/KB/cs/highperformancetimercshar.aspx

Aquí puede encontrar una cantidad de perfiladores de código abierto C #:

http://csharp-source.net/open-source/profilers

Otra opción es tener el código del temporizador insertado automáticamente con Fody . Esto hace que su código sea mucho más fácil de leer ya que separa sus preocupaciones transversales. Creo que esto es parecido a lo que se llama Progtwigción Orientada a Aspectos , pero se realiza en tiempo de comstackción posterior.

Consulte https://github.com/Fody/MethodTimer para el complemento de fody que mide el tiempo del método.

Citando del Léame:

Con un interceptor, en algún lugar de su conjunto:

 public static class MethodTimeLogger { public static void Log(MethodBase methodBase, long milliseconds) { //Do some logging here } } 

Tu codigo,

 public class MyClass { [Time] public void MyMethod() { //Some code u are curious how long it takes Console.WriteLine("Hello"); } } 

Está comstackdo a esto:

 public class MyClass { public void MyMethod() { var stopwatch = Stopwatch.StartNew(); try { //Some code u are curious how long it takes Console.WriteLine("Hello"); } finally { stopwatch.Stop(); MethodTimeLogger.Log(methodof(MyClass.MyMethod), stopwatch.ElapsedMilliseconds); } } } 

El Stopwatch estilo desechable funciona mejor para mí.

 class VWatch : IDisposable { Stopwatch watch = new Stopwatch(); public VWatch() { this.watch.Start(); } public void Dispose() { this.watch.Stop(); Console.WriteLine("Finished. Elapsed={0}", this.watch.Elapsed); } } 

Y entonces:

 using (new VWatch()) { /// do something for time measurement } 

A veces puede ser mejor ver por qué necesita sincronizar la operación? ¿Corre lento? ¿O solo tienes curiosidad? La primera regla de optimización es “No lo hagas”. Entonces, dependiendo de lo que realmente está midiendo, podría cambiar la opinión sobre qué herramienta es más adecuada para la tarea.

Es más fácil usar un generador de perfiles como ANTS Performance Profiler , o uno de los otros que están disponibles.

Hice una extensión que devuelve milisegundos de tics.

 public static int GetTotalRunningTimeInMilliseconds(this DateTime start) { var endTicks = DateTime.Now.Ticks - start.Ticks; return TimeSpan.FromTicks(endTicks).Milliseconds; } 

Uso:

  var start = DateTime.Now; //...your long running code here var endTime = start.GetTotalRunningTimeInMilliseconds(); 

He hecho un método muy simple que mide la velocidad de ejecución de una Acción , que tiene para mí el beneficio de poder reutilizarlo siempre que lo necesito y el código que tenga que medir.

Para mí, un DateTime fue suficiente, pero es fácilmente adaptable de DateTime a Stopwatch .

 public static TimeSpan MeasureTime(Action action) { DateTime start = DateTime.Now; if (action == null) { throw new ArgumentNullException("action"); } try { action(); } catch (Exception ex) { Debugger.Log(1, "Measuring",ex.ToString()); } return DateTime.Now - start; } 

¿Cómo usarlo?:

 private static void StressTest() { List tss = new List(); for (int i = 0; i < 100; i++) { // here is the measuring: var ts = MeasureTime(() => instance.Method("param1")); tss.Add(ts); } Console.WriteLine("Max: {0}", tss.Max()); Console.WriteLine("Min: {0}", tss.Min()); Console.WriteLine("Avg: {0}", TimeSpan.FromMilliseconds(tss.Average(i => i.TotalMilliseconds))); } 

o:

 var ts = MeasureTime(() => { // Some intensive stuff here int a = 1; // more here int b = 2; // and so on }); 

Para medir el rendimiento con la diferencia entre las mediciones, uso esta clase. La clase StopWatch no tiene el método Split .

 ///  /// Stopwatch like class that keeps track of timelapses. /// Probably low-res because of the usage of DateTime. ///  public class ChronoMeter { ///  /// The name given when the Chronometer was constructed. ///  public string Name { get; private set; } ///  /// The moment in time Start was called. ///  public DateTime Started { get; private set; } ///  /// All time recordings are added to this list by calling Split and Stop. ///  public List Records { get; private set; } private readonly Stopwatch _stopWatch = new Stopwatch(); private bool _hasBeenStopped = false; ///  /// Constrcutor ///  /// The name is used in logging /// The type of logging appriate for the information yielded by this time recording. public ChronoMeter(string pName) { Name = pName; Records = new List(); } ///  /// Not calling Stop is bad practise. Therefore a little safety net zo the end is still recorderd. /// Keep in mind that the garbase collector invokes the destructor, so the moment of time probably doesn't make much sense. /// It is more to notify that you should have used Stop for the latest split. ///  ~ChronoMeter() { if (!_hasBeenStopped) { Stop("Destructor safety net"); } } ///  /// TimeElapsedSinceStart of a ChronoRecord is relative to the moment ChronoMeter was started by calling this function. ///  public void Start() { _stopWatch.Start(); Started = DateTime.Now; } ///  /// Splits the timerecording and add a record of this moment to the list of split records. ///  ///  public void Split(string pSplitName) { _stopWatch.Stop(); var created = Started + _stopWatch.Elapsed; var previousRecord = Records.LastOrDefault(); Records.Add(new ChronoRecord(pSplitName, Started, created, previousRecord)); _stopWatch.Start(); } ///  /// Indicates you are done and the records will be written to the log. ///  public void Stop(string pSplitName) { Split(pSplitName); _stopWatch.Stop(); _hasBeenStopped = true; } public class ChronoRecord { public string Name { get; private set; } public TimeSpan TimeElapsedSinceStart { get; private set; } public TimeSpan TimeElapsedSincePrevious { get; private set; } public DateTime Start { get; private set; } public DateTime Created { get; private set; } public ChronoRecord(string pName, DateTime pStartDateTime, DateTime pCreated, ChronoRecord pPreviousRecord=null) { if (pCreated == default(DateTime)) //Ignore DefaultDateTimeComparison { pCreated = DateTime.Now; } Created = pCreated; Name = pName; Start = pStartDateTime; TimeElapsedSinceStart = Created - Start; if (pPreviousRecord != null) { TimeElapsedSincePrevious = Created - pPreviousRecord.Created; } else { TimeElapsedSincePrevious = TimeElapsedSinceStart; } } } }