在《dotnet程序优化心得》一文中我主要采用DateTime.Now.Ticks来测量时间,文中我说DateTime.Now.Ticks能够得到精确的时间,
Ninputer
指出这是一个错误的说法,DateTime.Now测不准ms级时间。我测试了一下,结果确实如此。测试代码如下:
1
2
static
void
Main(
string
[] args)
3
{
4
long start,end;
5
6
start = DateTime.Now.Ticks;
7
end = DateTime.Now.Ticks;
8
9
while(start==end)
10
{
11
end = DateTime.Now.Ticks;
12
}
13
14
Console.WriteLine("DateTime.Now.Ticks时间精度:{0}ms",(end-start)/10000);
15
}
16
运行结果:DateTime.Now.Ticks时间精度:10ms
yinh找到了一个程序QueryPerfCounter,可以进行精确的时间测量。代码如下:
1
using
System;
2
using
System.ComponentModel;
3
using
System.Runtime.InteropServices;
4

5
public
class
QueryPerfCounter
6
{
7
[DllImport("KERNEL32")]
8
private static extern bool QueryPerformanceCounter(
9
out long lpPerformanceCount);
10
11
[DllImport("Kernel32.dll")]
12
private static extern bool QueryPerformanceFrequency(out long lpFrequency);
13
14
private long start;
15
private long stop;
16
private long frequency;
17
Decimal multiplier = new Decimal(1.0e9);
18
19
public QueryPerfCounter()
20
{
21
if (QueryPerformanceFrequency(out frequency) == false)
22
{
23
// Frequency not supported
24
throw new Win32Exception();
25
}
26
}
27
28
public void Start()
29
{
30
QueryPerformanceCounter(out start);
31
}
32
33
public void Stop()
34
{
35
QueryPerformanceCounter(out stop);
36
}
37
38
public double Duration(int iterations)
39
{
40
return ((((double)(stop - start)* (double) multiplier) / (double) frequency)/iterations);
41
}
42
}
43
我搜了一下,该程序原出处应该是http://channel9.msdn.com/wiki/default.aspx/PerformanceWiki.HowToTimeManagedCode
采用以下代码测试其时间精度:
1
static
void
Main(
string
[] args)
2
{
3
QueryPerfCounter q = new QueryPerfCounter();
4
5
q.Start();
6
q.Stop();
7
8
Console.WriteLine("QueryPerfCounter时间精度:{0}ns",q.Duration(1));
9
}
结果:
QueryPerfCounter时间精度:3911.1116077602ns
如果测试之前这么来一下:
// Call the object and methods to JIT before the test run
QueryPerfCounter myTimer = new QueryPerfCounter();
myTimer.Start();
myTimer.Stop();
结果大概是1微妙。
也就是说QueryPerfCounter的测试精度是1微妙,这主要是因为方法调用和执行要花去一些时间。为了得到更精确的时间测量,必须对此进行时间校准,扣除方法调用和执行的时间.我在构造函数里面加了校准项。完整代码如下:
1
using
System;
2
using
System.ComponentModel;
3
using
System.Runtime.InteropServices;
4

5
public
class
QueryPerfCounter
6
{
7
[DllImport("KERNEL32")]
8
private static extern bool QueryPerformanceCounter(
9
out long lpPerformanceCount);
10
11
[DllImport("Kernel32.dll")]
12
private static extern bool QueryPerformanceFrequency(out long lpFrequency);
13
14
private long check;
15
private long start;
16
private long stop;
17
private long frequency;
18
Decimal multiplier = new Decimal(1.0e9);
19
20
public QueryPerfCounter()
21
{
22
if (QueryPerformanceFrequency(out frequency) == false)
23
{
24
// Frequency not supported
25
throw new Win32Exception();
26
}
27
28
check = 0;
29
30
QueryPerformanceCounter(out start);
31
QueryPerformanceCounter(out stop);
32
33
QueryPerformanceCounter(out start);
34
QueryPerformanceCounter(out stop);
35
check+=stop-start;
36
}
37
38
public void Start()
39
{
40
QueryPerformanceCounter(out start);
41
}
42
43
public void Stop()
44
{
45
QueryPerformanceCounter(out stop);
46
}
47
48
public double Duration(int iterations)
49
{
50
return ((((double)(stop - start-check)* (double) multiplier) / (double) frequency)/iterations);
51
}
52
}
53
采用下面这个方法测试校准效果:
1
static
void
TestCheckPrecision()
2
{
3
QueryPerfCounter q;
4
5
int loop = 10000;
6
int exCount = 0;
7
8
for (int i=0;i<loop;i++)
9
{
10
q = new QueryPerfCounter();
11
q.Start();
12
q.Stop();
13
if(q.Duration(1)!=0)
14
{
15
exCount++;
16
Console.WriteLine("QueryPerfCounter时间精度异常:{0}ns",q.Duration(1));
17
}
18
}
19
20
Console.WriteLine("共进行{0}次QueryPerfCounter的时间精度测试",loop);
21
Console.WriteLine("其中{0}次QueryPerfCounter的时间精度异常",exCount);
22
Console.WriteLine("时间校准有效性{0}%",100-(100.0*exCount)/loop);
23
}
24
运行结果:
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-558.730229680029ns
QueryPerfCounter时间精度异常:-558.730229680029ns
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-558.730229680029ns
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-558.730229680029ns
QueryPerfCounter时间精度异常:-558.730229680029ns
QueryPerfCounter时间精度异常:-838.095344520044ns
QueryPerfCounter时间精度异常:-345854.012171938ns
QueryPerfCounter时间精度异常:279.365114840015ns
QueryPerfCounter时间精度异常:-55314.2927383229ns
QueryPerfCounter时间精度异常:279.365114840015ns
QueryPerfCounter时间精度异常:5307.93718196028ns
QueryPerfCounter时间精度异常:279.365114840015ns
QueryPerfCounter时间精度异常:279.365114840015ns
QueryPerfCounter时间精度异常:279.365114840015ns
共进行10000次QueryPerfCounter的时间精度测试
其中22次QueryPerfCounter的时间精度异常
时间校准有效性99.78%
也就是说99.78%情况下都得到了很好的校准,只有极少数情况校准会出现异常现象不为零,有时这一波动甚至很大,到了5.3微妙。这个结果很满意了,因为异常的测试结果可以很简单的发现出来。但是是不是说明,校准后的类的测量误差就差不多就是纳秒级的呢?我后来又做了一个测试发现不是这样,测试代码如下:
1
static
void
TestPrecision()
2
{
3
QueryPerfCounter q;
4
5
for(int j=0;j<200;j++)
6
{
7
q = new QueryPerfCounter();
8
9
q.Start();
10
q.Stop();
11
12
Console.WriteLine("");
13
14
Console.WriteLine("QueryPerfCounter时间精度:{0}ns",q.Duration(1));
15
16
q.Start();
17
int i=0;
18
for(i=0;i<j;i++)
19
{
20
int l;
21
}
22
q.Stop();
23
24
Console.WriteLine("第{0}次循环,耗时{1}ns",i,q.Duration(1));
25
}
26
}
27
对于循环
for(i=0;i<j;i++)
{
int l;
}
当j很小的时候,耗时为0ns,随着n逐渐增大,耗时会一下子跳到279.365114840015ns,然后是558.730229680029ns。我摘几条结果:
QueryPerfCounter时间精度:0ns
第73次循环,耗时0ns
QueryPerfCounter时间精度:0ns
第74次循环,耗时279.365114840015ns
QueryPerfCounter时间精度:0ns
第75次循环,耗时0ns
QueryPerfCounter时间精度:0ns
第76次循环,耗时279.365114840015ns
QueryPerfCounter时间精度:0ns
第88次循环,耗时558.730229680029ns
QueryPerfCounter时间精度:0ns
第89次循环,耗时279.365114840015ns
也就是说,对我的机器现在配置来说(1.5G迅驰,2003 server,.net framework 1.1),测量的最基本时间单位是279.365114840015ns,不能得出更精确的时间了。
因此,推荐的测试方法是采用校对后的QueryPerfCounter,多测量几次,去掉最高值,去掉最低值(这两个一定要去掉),然后取平均值,这样能够得到非常精确的测量结果,测量误差约为0.3微妙。
本文转自xiaotie博客园博客,原文链接http://www.cnblogs.com/xiaotie/archive/2005/08/16/216015.html如需转载请自行联系原作者
xiaotie 集异璧实验室(GEBLAB)