如何在.NET中测量代码性能?
我使用DateTime在一行C#代码上做了一些真正的快速和肮脏的基准testing:
long lStart = DateTime.Now.Ticks; // do something long lFinish = DateTime.Now.Ticks;
问题在于结果:
开始时间[633679466564559902] 完成时间[633679466564559902] 开始时间[633679466564569917] 完成时间[633679466564569917] 开始时间[633679466564579932] 完成时间[633679466564579932]
…等等。
鉴于开始和结束时间是相同的,Ticks显然不够精细。
那么,我怎样才能更好地衡量performance呢?
从.NET 2.0开始可以使用的Stopwatch
类是最好的方法。 这是一个非常高的性能计数器精确到几分之一毫秒。 看看MSDN文档 ,这很清楚。
编辑:如以前所build议的,build议您多次运行您的代码以获得合理的平均时间。
重复执行您的代码。 问题似乎是你的代码比你的测量仪器的粒度要快得多。 最简单的解决scheme是执行你的代码许多次(数千甚至数百万次)然后计算平均执行时间。
编辑:另外,由于当前优化编译器(以及CLR和JVM等虚拟机)的性质,测量单行代码的执行速度可能是非常误导的,因为测量可能会影响速度。 更好的方法是分析整个系统(或者至less更大的块)并检查瓶颈在哪里。
我觉得这些很有用
http://accelero.codeplex.com/SourceControl/changeset/view/22633#290971 http://accelero.codeplex.com/SourceControl/changeset/view/22633#290973 http://accelero.codeplex.com/SourceControl/变更/视图/ 22633#290972
TickTimer是Stopwatch的一个简化副本,在构build时启动,不支持重新启动。 它也会通知你,如果当前的硬件不支持高分辨率的时间(秒表吞下这个问题)
所以这
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());
会输出这个
Elapsed HighResElapsedTicks 10022886 Elapsed DateTimeElapsedTicks 41896 Elapsed ElapsedMilliseconds 4.18966178849554 Start Time 11:44:58
DebugTimer是一个TickTimer的包装器,它将结果写入Debug。 (注意:它支持一次性模式)
所以这
using (new DebugTimer("DoStuff")) { //call a method that takes some time DoStuff(); }
将输出到debugging窗口
DoStuff: Total 3.6299 ms
IterationDebugTimer用于计算多次运行一个操作所需的时间,并将结果写入Debug。 它也会执行一个不包含的初始运行,以忽略启动时间。 (注意:它支持一次性模式)
所以这
int x; using (var iterationDebugTimer = new IterationDebugTimer("Add", 100000)) { iterationDebugTimer.Run(() => { x = 1+4; }); }
会输出这个
Add: Iterations 100000 Total 1.198540 ms Single 0.000012 ms
只是为了增加别人已经说过的使用秒表和测量平均值。
确保在测量之前调用您的方法。 否则,您将测量JIT编译代码所需的时间。 这可能会显着扭曲你的数字。
此外,请确保您测量释放模式代码,因为默认情况下为debugging版本closures了优化。 debuggingdebugging代码是毫无意义的。
并确保你正在测量你真正想要衡量的东西。 当优化启动时,编译器/ JIT编译器可能会重新排列代码或将其完全删除,因此您最终可能会测量出与预期略有不同的内容。 至less看看生成的代码,以确保代码没有被剥离。
请记住,根据您要测量的内容,真实的系统会比典型的testing应用程序强调运行时间。 一些性能问题与例如对象如何收集垃圾有关。 这些问题通常不会在简单的testing应用程序中显示出来。
实际上,最好的build议是用真实的数据来衡量真实的系统,因为沙盒testing结果可能非常不准确。
使用一个真正的分析器,如dotTrace。
您可以使用Stopwatch
,假设您使用的是.NET 2.0或更新版本。
System.Diagnostics.Stopwatch.StartNew();
Stopwatch
类还具有公共只读字段IsHighResolution
,可让您知道秒表是否基于高分辨率性能计数器。 如果不是,则基于系统定时器。
我不确定秒表是以高分辨率的性能计数器为基础的。 有一些API调用,但我想如果秒表不使用高分辨率,那么API可能不存在。
查看DateTime.Now是否是衡量函数性能的最佳方法? 作为解释或阅读我的博客文章有关高性能测量
问题是DateTime的分辨率大约是15ms,不能比这更精确。 秒表,但是,可以。
这里有一个很好的写在MSDN上如何实现Windows的不断更新,高分辨率的时间提供程序
这里是文章的示例源代码 (C ++)。
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
“事实上,microbencmarking是非常困难的,如果一个操作需要10-100ns,操作测量是一个很大的挑战,我build议你使用BenchmarkDotNet作为你的基准,这是一个图书馆,可以帮助你做一个诚实的基准和测量当然,你可以在没有任何附加库的情况下编写自己的基准testing,在本节中,我们将讨论为什么它可能是一个坏主意,在开始之前应该知道些什么。
此代码项目文章显示如何使用高性能计时器来衡量您的代码的执行速度:
http://www.codeproject.com/KB/cs/highperformancetimercshar.aspx
在这里你可以find一些开源的C#分析器:
另一种select是使用Fody自动插入计时器代码。 这使得你的代码更容易阅读,因为它分离你的交叉问题。 我认为这接近于所谓的面向方面编程 ,但在编译后的时间完成。
请参阅https://github.com/Fody/MethodTimer作为方法时间的fody插件。;
引用自述文件:
用一个拦截器,在你的程序集中的某个地方:
public static class MethodTimeLogger { public static void Log(MethodBase methodBase, long milliseconds) { //Do some logging here } }
你的代码,
public class MyClass { [Time] public void MyMethod() { //Some code u are curious how long it takes Console.WriteLine("Hello"); } }
被编译为:
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); } } }
有时候最好看看为什么你需要时间的手术? 它运行缓慢吗? 或者你只是好奇? 优化的第一条规则是“不要做”。 所以,取决于你实际测量的是什么,可以改变什么工具最适合这项任务的意见。
最简单的使用一个像ANTS Performance Profiler这样的分析器 ,或者其他可用的分析器之一。
我做了一个扩展,从ticks返回毫秒。
public static int GetTotalRunningTimeInMilliseconds(this DateTime start) { var endTicks = DateTime.Now.Ticks - start.Ticks; return TimeSpan.FromTicks(endTicks).Milliseconds; }
用法:
var start = DateTime.Now; //...your long running code here var endTime = start.GetTotalRunningTimeInMilliseconds();
为了测量不同测量之间的performance,我使用这个类。 StopWatch类没有Split
方法。
/// <summary> /// Stopwatch like class that keeps track of timelapses. /// Probably low-res because of the usage of DateTime. /// </summary> public class ChronoMeter { /// <summary> /// The name given when the Chronometer was constructed. /// </summary> public string Name { get; private set; } /// <summary> /// The moment in time Start was called. /// </summary> public DateTime Started { get; private set; } /// <summary> /// All time recordings are added to this list by calling Split and Stop. /// </summary> public List<ChronoRecord> Records { get; private set; } private readonly Stopwatch _stopWatch = new Stopwatch(); private bool _hasBeenStopped = false; /// <summary> /// Constrcutor /// </summary> /// <param name="pName">The name is used in logging</param> /// <param name="pLoggingType">The type of logging appriate for the information yielded by this time recording.</param> public ChronoMeter(string pName) { Name = pName; Records = new List<ChronoRecord>(); } /// <summary> /// 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. /// </summary> ~ChronoMeter() { if (!_hasBeenStopped) { Stop("Destructor safety net"); } } /// <summary> /// TimeElapsedSinceStart of a ChronoRecord is relative to the moment ChronoMeter was started by calling this function. /// </summary> public void Start() { _stopWatch.Start(); Started = DateTime.Now; } /// <summary> /// Splits the timerecording and add a record of this moment to the list of split records. /// </summary> /// <param name="pSplitName"></param> 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(); } /// <summary> /// Indicates you are done and the records will be written to the log. /// </summary> 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; } } } }