一个简单的性能计数器：CodeTimer

摘至：http://www.cnblogs.com/JeffreyZhao/archive/2009/03/10/CodeTimer.html

有数据，有真相，相信大家在平时的工作或学习过程中，都需要比较几种不同方法或实现之间的性能差距。在这些时候，往往就需要我们不断地创建 Stopwatch，打开，关闭，然后打印时间。这种一遍又一遍的重复终有一天会让人忍无可忍，因此如果能有一个“标准”的性能计数器，那应该可以让生活轻松许多。这个性能计数器不用复杂，够用就好；也不需要考虑扩展性，要扩展时直接修改代码就够了；同样不需要考虑输出格式，直接打印在Console就行。

　　在上次的.NET技术大会中，Jeffrey Richter大叔在Keynote Session中进行了一个名为“The Performance of Everyday Things”的主题演讲，展示了各种常用编程元素之间的性能对比。在演示中他使用了一个名为CodeTimer的简单计数器，用于统计每种做法的性能。可惜翻遍了每个地方都没发现JR大叔在哪里公开了这个计数器的实现。算了，那么就凭着印象写一个出来吧，反正也不复杂。

　　总的来说，CodeTimer有两个公开方法，一个是Initialize，一个是Time：

public static class CodeTimer
{
public static void Initialize()
    {
Process.GetCurrentProcess().PriorityClass = ProcessPriorityClass.High;
Thread.CurrentThread.Priority = ThreadPriority.Highest;
        Time("", 1, () => { });
    }

public static void Time(string name, int iteration, Action action)
    {
        ...
    }
}

　　CodeTimer.Initialize方法应该在测试开始前调用。首先它会把当前进程及当前线程的优先级设为最高，这样便可以相对减少操作系统在调度上造成的干扰。然后调用一次Time方法进行“预热”，让JIT将IL编译成本地代码，让Time方法尽快“进入状态”。Time方法则是真正用于性能计数的方法，实现如下：

public static void Time(string name, int iteration, Action action)
{
if (String.IsNullOrEmpty(name)) return;

// 1.
ConsoleColor currentForeColor = Console.ForegroundColor;
Console.ForegroundColor = ConsoleColor.Yellow;
Console.WriteLine(name);

// 2.
GC.Collect(GC.MaxGeneration, GCCollectionMode.Forced);
int[] gcCounts = new int[GC.MaxGeneration + 1];
for (int i = 0; i <= GC.MaxGeneration; i++)
    {
        gcCounts[i] = GC.CollectionCount(i);
    }

// 3.
Stopwatch watch = new Stopwatch();
    watch.Start();
ulong cycleCount = GetCycleCount();
for (int i = 0; i < iteration; i++) action();
ulong cpuCycles = GetCycleCount() - cycleCount;
    watch.Stop();

// 4.
Console.ForegroundColor = currentForeColor;
Console.WriteLine("\tTime Elapsed:\t" + watch.ElapsedMilliseconds.ToString("N0") + "ms");
Console.WriteLine("\tCPU Cycles:\t" + cpuCycles.ToString("N0"));

// 5.
for (int i = 0; i <= GC.MaxGeneration; i++)
    {
int count = GC.CollectionCount(i) - gcCounts[i];
Console.WriteLine("\tGen " + i + ": \t\t" + count);
    }

Console.WriteLine();
}

private static ulong GetCycleCount()
{
ulong cycleCount = 0;
    QueryThreadCycleTime(GetCurrentThread(), ref cycleCount);
return cycleCount;
}

[DllImport("kernel32.dll")]
[return: MarshalAs(UnmanagedType.Bool)]
static extern bool QueryThreadCycleTime(IntPtr threadHandle, ref ulong cycleTime);

[DllImport("kernel32.dll")]
static extern IntPtr GetCurrentThread();

　　Time方法接受三个参数，名称，循环次数以及需要执行的方法体。打印出花费时间，消耗的CPU时钟周期，以及各代垃圾收集的回收次数。具体实现分几个步骤，如下：

保留当前控制台前景色，并使用黄色输出名称参数。
强制GC进行收集，并记录目前各代已经收集的次数。
执行代码，记录下消耗的时间及CPU时钟周期¹。
恢复控制台默认前景色，并打印出消耗时间及CPU时钟周期。
打印执行过程中各代垃圾收集回收次数。

　　与传统计数方法相比，这段代码还输出了更多信息：CPU时钟周期及各代垃圾收集回收次数。CPU时钟周期是性能计数中的辅助参考，说明CPU分配了多少时间片给这段方法来执行，它和消耗时间并没有必然联系。例如Thread.Sleep方法会让CPU暂时停止对当前线程的“供给”，这样虽然消耗了时间，但是节省了CPU时钟周期：

CodeTimer.Time("Thread Sleep", 1, () => { Thread.Sleep(3000); });
CodeTimer.Time("Empty Method", 10000000, () => { });

　　结果如下：

　　而垃圾收集次数的统计，即直观地反应了方法资源分配（消耗）的规模：

int iteration = 100 * 1000;

string s = "";
CodeTimer.Time("String Concat", iteration, () => { s += "a"; });

StringBuilder sb = new StringBuilder();
CodeTimer.Time("StringBuilder", iteration, () => { sb.Append("a"); });

　　结果如下：

　　老赵最近在研究一个问题的几种不同做法在性能上的优劣，其中CodeTimer起到了很重要的作用——这边也先卖个关子，接下来老赵也将会写几篇文章来讲解这个问题。

注1：统计CPU时钟周期时使用P/Invoke访问QueryThreadCycleTime函数，这是Vista和Server 2008中新的函数。感谢装配脑袋在这里提供的帮助。

注2：对于.NET 2.0及Vista以下操作系统，请参考《对老赵写的简单性能计数器的修改》

对老赵写的简单性能计数器的修改

早上看到老赵写的这个性能计数器，感觉很实用，不过老赵用了很多.C# 3.0 的新语法，还用了 VISTA 和 Server 2008 下特有的Win32 API，对于还在用C#2.0 或者还工作在 XP 或者 Server 2003 下的兄弟们，只能望代码心叹了。应老赵的要求，我修改了他的代码，增加了对低版本C# 和低版本windows 操作系统的支持。

老赵的原文：一个简单的性能计数器：CodeTimer

修改说明

1. 采用接口取代了原代码中的 Lambda 表达式

2. 采用 GetThreadTimes 这个API 函数替代了原代码中的 QueryThreadCycleTime

这里需要说明的是 GetThreadTimes 给出了线程在内核态和用户态占用的时间，单位是 100 ns。两个时间的总和就是线程占用的CPU时间。这个API的时间精度我看了一些资料似乎没有达到 100ns. 所以GetThreadTimes 这个API函数的进度没有 QueryThreadCycleTime 高。

下面是我修改后的代码

注释1: 2009-03-11 增加委托的调用，修改 GC.Collect 参数，兼容.Net 2.0. 增加每次调用时间统计

增加了委托调用后，我发现同样是测试空函数，采用接口比采用委托效率要略高一些，这和我的预计基本吻合，因为委托不是单纯的函数调用，具体原理超出本文范围，我就不多说了。

using System;

using System.Collections.Generic;

using System.Text;

using System.Diagnostics;

using System.Threading;

using System.Runtime.InteropServices;

public interface IAction

{

void Action();

}

public static class CodeTimer

{

[DllImport("kernel32.dll", SetLastError = true)]

static extern bool GetThreadTimes(IntPtr hThread, out long lpCreationTime,

out long lpExitTime, out long lpKernelTime, out long lpUserTime);

[DllImport("kernel32.dll")]

static extern IntPtr GetCurrentThread();

public delegate void ActionDelegate();

private static long GetCurrentThreadTimes()

{

long l;

long kernelTime, userTimer;

GetThreadTimes(GetCurrentThread(), out l, out l, out kernelTime,

out userTimer);

return kernelTime + userTimer;

}

static CodeTimer()

{

Process.GetCurrentProcess().PriorityClass = ProcessPriorityClass.High;

Thread.CurrentThread.Priority = ThreadPriority.Highest;

}

public static void Time(string name, int iteration, ActionDelegate action)

{

if (String.IsNullOrEmpty(name))

{

return;

}

if (action == null)

{

return;

}

//1. Print name

ConsoleColor currentForeColor = Console.ForegroundColor;

Console.ForegroundColor = ConsoleColor.Yellow;

Console.WriteLine(name);

// 2. Record the latest GC counts

//GC.Collect(GC.MaxGeneration, GCCollectionMode.Forced);

GC.Collect(GC.MaxGeneration);

int[] gcCounts = new int[GC.MaxGeneration + 1];

for (int i = 0; i <= GC.MaxGeneration; i++)

{

gcCounts[i] = GC.CollectionCount(i);

}

// 3. Run action

Stopwatch watch = new Stopwatch();

watch.Start();

long ticksFst = GetCurrentThreadTimes(); //100 nanosecond one tick

for (int i = 0; i < iteration; i++) action();

long ticks = GetCurrentThreadTimes() - ticksFst;

watch.Stop();

// 4. Print CPU

Console.ForegroundColor = currentForeColor;

Console.WriteLine("\tTime Elapsed:\t\t" +

watch.ElapsedMilliseconds.ToString("N0") + "ms");

Console.WriteLine("\tTime Elapsed (one time):" +

(watch.ElapsedMilliseconds / iteration).ToString("N0") + "ms");

Console.WriteLine("\tCPU time:\t\t" + (ticks * 100).ToString("N0")

+ "ns");

Console.WriteLine("\tCPU time (one time):\t" + (ticks * 100 /

iteration).ToString("N0") + "ns");

// 5. Print GC

for (int i = 0; i <= GC.MaxGeneration; i++)

{

int count = GC.CollectionCount(i) - gcCounts[i];

Console.WriteLine("\tGen " + i + ": \t\t\t" + count);

}

Console.WriteLine();

}

public static void Time(string name, int iteration, IAction action)

{

if (String.IsNullOrEmpty(name))

{

return;

}

if (action == null)

{

return;

}

//1. Print name

ConsoleColor currentForeColor = Console.ForegroundColor;

Console.ForegroundColor = ConsoleColor.Yellow;

Console.WriteLine(name);

// 2. Record the latest GC counts

//GC.Collect(GC.MaxGeneration, GCCollectionMode.Forced);

GC.Collect(GC.MaxGeneration);

int[] gcCounts = new int[GC.MaxGeneration + 1];

for (int i = 0; i <= GC.MaxGeneration; i++)

{

gcCounts[i] = GC.CollectionCount(i);

}

// 3. Run action

Stopwatch watch = new Stopwatch();

watch.Start();

long ticksFst = GetCurrentThreadTimes(); //100 nanosecond one tick

for (int i = 0; i < iteration; i++) action.Action();

long ticks = GetCurrentThreadTimes() - ticksFst;

watch.Stop();

// 4. Print CPU

Console.ForegroundColor = currentForeColor;

Console.WriteLine("\tTime Elapsed:\t\t" +

watch.ElapsedMilliseconds.ToString("N0") + "ms");

Console.WriteLine("\tTime Elapsed (one time):" +

(watch.ElapsedMilliseconds / iteration).ToString("N0") + "ms");

Console.WriteLine("\tCPU time:\t\t" + (ticks * 100).ToString("N0")

+ "ns");

Console.WriteLine("\tCPU time (one time):\t" + (ticks * 100 /

iteration).ToString("N0") + "ns");

// 5. Print GC

for (int i = 0; i <= GC.MaxGeneration; i++)

{

int count = GC.CollectionCount(i) - gcCounts[i];

Console.WriteLine("\tGen " + i + ": \t\t\t" + count);

}

Console.WriteLine();

}

测试类

    public class TestSleep3000 : IAction
    {
        #region IAction Members

        public void Action()
        {
            Thread.Sleep(3000);
        }

        #endregion
    }

    public class TestEmptyMethod : IAction
    {
        #region IAction Members

        public void Action()
        {
        }

        #endregion
    }

    public class TestStringConcat : IAction
    {
        string s = "";

        #region IAction Members

        public void Action()
        {
            s += "a";
        }

        #endregion
    }

    public class TestStringBuilderConcat : IAction
    {
        StringBuilder s = new StringBuilder();

        #region IAction Members

        public void Action()
        {
            s.Append ("a");
        }

        #endregion
    }

测试代码

采用接口

            CodeTimer.Time("Thread Sleep", 1, new TestSleep3000());
            CodeTimer.Time("Thread Sleep", 10000000, new TestEmptyMethod());
            CodeTimer.Time("String Concat", 100000, new TestStringConcat());
            CodeTimer.Time("StringBuilder Conca", 100000,
                 new TestStringBuilderConcat());

测试结果

Thread Sleep
        Time Elapsed:           2,997ms
        Time Elapsed (one time):2,997ms
        CPU time:               0ns
        CPU time (one time):    0ns
        Gen 0:                  0
        Gen 1:                  0
        Gen 2:                  0

Empty Method
        Time Elapsed:           138ms
        Time Elapsed (one time):0ms
        CPU time:               125,000,000ns
        CPU time (one time):    12ns
        Gen 0:                  0
        Gen 1:                  0
        Gen 2:                  0

String Concat
        Time Elapsed:           10,547ms
        Time Elapsed (one time):0ms
        CPU time:               10,546,875,000ns
        CPU time (one time):    105,468ns
        Gen 0:                  4102
        Gen 1:                  2661
        Gen 2:                  2545

StringBuilder Conca
        Time Elapsed:           4ms
        Time Elapsed (one time):0ms
        CPU time:               0ns
        CPU time (one time):    0ns
        Gen 0:                  0
        Gen 1:                  0
        Gen 2:                  0

采用委托

CodeTimer.Time("Thread Sleep", 1, delegate() { Thread.Sleep(3000); });

CodeTimer.Time("Empty Method", 10000000, delegate() { });

string a = "";

CodeTimer.Time("String Concat", 100000, delegate() { a += "a"; });

StringBuilder s = new StringBuilder();

CodeTimer.Time("StringBuilder Conca", 100000, delegate() { s.Append("a"); });

测试结果

Thread Sleep
        Time Elapsed:           2,989ms
        Time Elapsed (one time):2,989ms
        CPU time:               0ns
        CPU time (one time):    0ns
        Gen 0:                  0
        Gen 1:                  0
        Gen 2:                  0

Empty Method
        Time Elapsed:           156ms
        Time Elapsed (one time):0ms
        CPU time:               156,250,000ns
        CPU time (one time):    15ns
        Gen 0:                  0
        Gen 1:                  0
        Gen 2:                  0

String Concat
        Time Elapsed:           10,425ms
        Time Elapsed (one time):0ms
        CPU time:               10,406,250,000ns
        CPU time (one time):    104,062ns
        Gen 0:                  4102
        Gen 1:                  2661
        Gen 2:                  2545

posted on 2009-09-17 13:19 KiMoGiGi 阅读(613) 评论(0) 编辑收藏引用所属分类: C# / Winforms

只有注册用户登录后才能发表评论。

KiMoGiGi 技术文集

公告

常用链接

留言簿(10)

随笔分类(219)

随笔档案(185)

文章分类(25)

文章档案(14)

收藏夹

Friend 's Blog

My Step

技术崇拜

技術網站

搜索