65.9K
CodeProject 正在变化。 阅读更多。
Home

性能测试：使用 System.Diagnostics.Stopwatch 进行精确运行时间测量

Thomas Maierhofer (Tom)
starIconstarIconstarIconstarIcon
emptyStarIcon
starIcon

4.95/5 (51投票s)

2010年2月28日

BSD

3分钟阅读

viewsIcon

200541

如何使用 .NET Framework 的 Stopwatch 类来高精度地测量和比较算法的运行时间

引言

任何进行性能优化的程序员或多或少都会遇到 `System.Diagnostics` 命名空间下的 `Stopwatch` 类。而大家也可能注意到，在同一台电脑上对同一函数进行的测量，其运行时间可能会有 25%-30% 的差异。本文将介绍如何设计单线程测试程序，以达到 `Stopwatch` 类 0.1%-0.2% 的精度。有了这样的精度，就可以测试和比较算法了。

背景

现代 CPU 拥有多核、大缓存、指令流水线以及许多其他会影响特定测试场景下算法运行时间的因素。白盒测试技术（如附加调试器或性能分析器）会破坏 CPU 的缓存行、流水线等。真实的运行时间被隐藏了，导致一个为这些现代超标量 CPU 优化的算法（因为指令更多）反而会比一个未优化的算法在附加性能分析器时运行得更慢。黑盒测试（运行时间测量），在不附加调试器或性能分析器的情况下，能够发现算法的真实性能，从而完成算法的性能分析。

设置测试场景

最重要的一点是防止 CPU 核心或处理器之间的切换。切换会破坏缓存等，并对测试产生巨大的性能影响。这可以通过设置进程的 `ProcessorAffinity` 掩码来实现。

Process.GetCurrentProcess().ProcessorAffinity = new IntPtr(2); // Use only the second core

为了更专心地使用 CPU 核心，我们必须阻止其他线程占用该 CPU 核心。为此，我们将进程和线程的优先级设置为最高。

Process.GetCurrentProcess().PriorityClass = ProcessPriorityClass.High;
Thread.CurrentThread.Priority = ThreadPriority.Highest;

最后但同样重要的是，我们的测试需要一个预热阶段。在我的系统上，预热 1000-1500 毫秒后，结果会趋于稳定。我们可以使用 Stopwatch 本身来控制预热（此处至少 1200 毫秒）。

stopwatch.Start();
while (stopwatch.ElapsedMilliseconds < 1200)
{
    result = TestFunction(seed, count); 
}
stopwatch.Stop();

以下是完整的示例代码

 using System;
using System.Diagnostics;
using System.Threading;

namespace PreciseMeasure
{
    class Program
    {
        static void Main(string[] args)
        {
            Stopwatch stopwatch = new Stopwatch();

            long seed = Environment.TickCount; 	// Prevents the JIT Compiler 
					// from optimizing Fkt calls away
            long result = 0;
            int count = 100000000;

            Console.WriteLine("20 Tests without correct preparation"); 
            Console.WriteLine("Warmup");
            for (int repeat = 0; repeat < 20; ++repeat)
            {
                stopwatch.Reset();
                stopwatch.Start();
                result ^= TestFunction(seed, count);
                stopwatch.Stop();
                Console.WriteLine("Ticks: " + stopwatch.ElapsedTicks + 
				" mS: " +stopwatch.ElapsedMilliseconds);
            }

            Process.GetCurrentProcess().ProcessorAffinity = 
		new IntPtr(2); // Uses the second Core or Processor for the Test
            Process.GetCurrentProcess().PriorityClass = 
		ProcessPriorityClass.High;  	// Prevents "Normal" processes 
					// from interrupting Threads
            Thread.CurrentThread.Priority = 
		ThreadPriority.Highest;  	// Prevents "Normal" Threads 
					// from interrupting this thread
    
            Console.WriteLine();
            Console.WriteLine();
            Console.WriteLine("20 Tests with correct preparation"); 
            Console.WriteLine("Warmup");
            stopwatch.Reset();
            stopwatch.Start();
            while (stopwatch.ElapsedMilliseconds < 1200)  // A Warmup of 1000-1500 mS 
					// stabilizes the CPU cache and pipeline.
            {
                result = TestFunction(seed, count); // Warmup
            }
            stopwatch.Stop();

            for (int repeat = 0; repeat < 20; ++repeat)
            {
                stopwatch.Reset();
                stopwatch.Start();
                result ^= TestFunction(seed, count);
                stopwatch.Stop();
                Console.WriteLine("Ticks: " + stopwatch.ElapsedTicks + 
				" mS: " + stopwatch.ElapsedMilliseconds);
            }
            Console.WriteLine(result); // prevents optimizations (current compilers are 
		// too silly to analyze the dataflow that deep, but we never know )
        }

        public static long TestFunction(long seed, int count)
        {
            long result = seed;
            for (int i = 0; i < count; ++i)
            {
                result ^= i ^ seed; // Some useless bit operations
            }
            return result;
        }
    }
}

结果

未经正确准备

  1. Ticks: 1580367 mS: 572 <-- 最高值
  2. Ticks: 1577003 mS: 571
  3. Ticks: 1576140 mS: 571
  4. Ticks: 1560964 mS: 565
  5. Ticks: 1351663 mS: 489
  6. Ticks: 1248383 mS: 452
  7. Ticks: 1115361 mS: 404
  8. Ticks: 1112813 mS: 403
  9. Ticks: 1113112 mS: 403
  10. Ticks: 1112012 mS: 402 <-- 最低值
  11. Ticks: 1330444 mS: 482
  12. Ticks: 1558493 mS: 564
  13. Ticks: 1501097 mS: 543
  14. Ticks: 1517796 mS: 549
  15. Ticks: 1542712 mS: 558
  16. Ticks: 1574959 mS: 570
  17. Ticks: 1483975 mS: 537
  18. Ticks: 1390578 mS: 503
  19. Ticks: 1546904 mS: 560
  20. Ticks: 1349507 mS: 488

运行时间在 402 毫秒到 572 毫秒之间变化。差异为 170 毫秒，即 42%。这些结果是无用的。

经过正确准备

  1. Ticks: 1110518 mS: 402
  2. Ticks: 1110540 mS: 402
  3. Ticks: 1110543 mS: 402
  4. Ticks: 1110684 mS: 402 <-- 最高值
  5. Ticks: 1110508 mS: 402
  6. Ticks: 1110553 mS: 402
  7. Ticks: 1110600 mS: 402
  8. Ticks: 1110433 mS: 402 <-- 最低值
  9. Ticks: 1110509 mS: 402
  10. Ticks: 1110508 mS: 402
  11. Ticks: 1110489 mS: 402
  12. Ticks: 1110568 mS: 402
  13. Ticks: 1110503 mS: 402
  14. Ticks: 1110566 mS: 402
  15. Ticks: 1110625 mS: 402
  16. Ticks: 1110474 mS: 402
  17. Ticks: 1110571 mS: 402
  18. Ticks: 1110448 mS: 402
  19. Ticks: 1110555 mS: 402
  20. Ticks: 1110495 mS: 402

这 20 个样本产生了相同的 402 毫秒结果，只能通过 Ticks 数（内部 CPU 性能计数器值）来区分。差异为 251 Ticks，或 0.02%。在我的系统上，`Stopwatch` 的频率为每秒 2760029 Ticks。测试运行之间的差异仅为 0.09 毫秒。这非常好，可以用于测量和比较算法的运行时间。

关注点

有一点非常重要需要牢记。未经准备的最好（最低）值不如经过准备的最差值。CPU 上下文和核心切换对应用程序的运行时间有巨大影响。

链接和附加资源

本文是可以在 benchmarks.codeplex.com 上找到的性能测试之一。这些是为 “Second WAF” Web 应用程序框架 进行的研究。

历史

  • 2010年2月28日：初始发布
© . All rights reserved.