KiMoGiGi 技术文集

不在乎选择什么,而在乎坚持多久……

IT博客 首页 联系 聚合 管理
  185 Posts :: 14 Stories :: 48 Comments :: 0 Trackbacks
摘至: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时钟周期,以及各代垃圾收集的回收次数。具体实现分几个步骤,如下:

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

  与传统计数方法相比,这段代码还输出了更多信息: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"1new TestSleep3000());
            CodeTimer.Time(
"Thread Sleep"10000000new TestEmptyMethod());
            CodeTimer.Time(
"String Concat"100000new 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"1delegate() { Thread.Sleep(3000); });
CodeTimer.Time(
"Empty Method"10000000delegate() { });

string a = "";

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

StringBuilder s 
= new StringBuilder();
CodeTimer.Time(
"StringBuilder Conca"100000delegate() { 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

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

 

posted on 2009-09-17 13:19 KiMoGiGi 阅读(614) 评论(0)  编辑 收藏 引用 所属分类: C# / Winforms
只有注册用户登录后才能发表评论。