【问题标题】:Can anyone help me explain these method timings?谁能帮我解释一下这些方法时间?
【发布时间】:2010-07-11 17:55:02
【问题描述】:

此代码对两种方法的 n 调用进行计时,这两种方法均不执行任何操作(MyMethod1MyMethod2)但使用不同的属性(MyAspect1MyAspect2)进行装饰。

MyAspect1 除了让MyMethod1 运行(Proceed())之外,不包含任何逻辑。

MyAspect2MyMethod2 执行相同操作,但还会创建一个任务,提供一个匿名委托来运行,这意味着 CPU 的工作量接近于零(修剪字符串)。

我希望 MyMethod1MyMethod2 上的迭代时间大致相同。

实际时间如下;它们似乎与直觉相悖,MyMethod1 开始时明显较慢(与我的预期相反),最终从 10000 次迭代开始显着输掉比赛。谁能帮我解释一下?

Test results (average of 3 runs per iteration value):

No. of iterations  |          Ticks 
                      Method 1  |  Method 2
       5                 25282        6999
       100               22128        8176 
       1000              22982        23720
       10000             25995        265621
       1000000           994359       25125076

---------------------------------------------------

public class TestClass2
{ 
    public void MyTest()
    {
        const int iterations = 100;
        var stopWatch = new Stopwatch();
        stopWatch.Start();
        for (int x = 0; x < iterations; x++)
        {
            MyMethod1();
        }
        stopWatch.Stop();
        Console.WriteLine("Method1 calls duration: " + stopWatch.ElapsedTicks);            
        stopWatch.Reset();
        stopWatch.Start();
        for (int x = 0; x < iterations; x++)
        {
             MyMethod2();
        }
        stopWatch.Stop();
        Console.WriteLine("Method2 calls duration: " + stopWatch.ElapsedTicks);                        
    }

    [MyAspect1]
    private void MyMethod1() {}
    [MyAspect2]
    private void MyMethod2() {}
}

[Serializable]
public class MyAspect1 : AsynchronousMetricsAspect
{
    public override void OnInvoke(MethodInterceptionArgs args)
    {
        args.Proceed();
    }
}

//NOTE: this type is the same as MyAspect1, but adds a Task creation
[Serializable]
public class MyAspect2 : AsynchronousMetricsAspect
{
    public override void OnInvoke(MethodInterceptionArgs args)
    {
        args.Proceed();
        Task.Factory.StartNew(() => "bleh".Trim()); //invoke the logging method asynchronously           
    }
}

更多信息:正在从 ReSharper NUnit VS 插件调用测试,属性为 PostSharp MethodInterceptionAspects。

Edit: Updated figures for when the methods are pre-invoked before the tests, to ensure any JIT compilation has occurred. 

Test results (ballpark):

No. of iterations  |          Ticks 
                      Method 1  |  Method 2
       5                 22          437
       100               37          2204 
       1000              192         24476
       10000             7931        286403
       100000            115451      2862439
       1000000           695950      29049021
       10000000          8347867     275777590

【问题讨论】:

  • 您能否在分析器(nProf、EQATEC 等)中调用测试?
  • 我已经下载了dot trace,当我弄清楚如何使用它时会报告我的发现。
  • 查看 PostSharp 使用 Reflector 生成了哪些代码。
  • 好的,我已经对这个感兴趣了。 J Skeet 对 PostSharp 基础设施的 JIT 处理是正确的——预运行代码,从结果中移除了大部分“固定”成本。将属性代码从 PostSharp 属性中移出对 Method1 产生了重大影响 - 怀疑那里正在进行严重的编译器优化。这样做改进了 Method2,但不是按 mag 的顺序。这个实验只是为了展示影响性能的众多因素。代码 - 决定某事是否高性能并不简单。

标签: c# performance


【解决方案1】:

好吧,首先我会尝试确定这是否与 PostSharp 有关。我会尝试在不涉及任何 AOP 的情况下调用相同的方法。

以下是我的怀疑:

  • 25000 个滴答声(请注意,时间很短)是由于 PostSharp 基础设施的 JITting 位。因此,它们是固定成本,不必通过第二种方法再次支付。您可以通过切换测试顺序来验证这一点。但是,考虑到这些数字,我怀疑设置任务工厂等会产生另一个不变的成本......这可以解释为什么方法 2 的 100 次迭代不会超过 5 次迭代。 p>

  • 创建任务不是免费的,我也不希望它免费。您正在创建一个对象这一事实意味着正在进行工作......然后是跨任务和线程的调度和协调。 Parallel Extensions 很好,但它不能创造奇迹。我不知道 PFX 将如何分散工作,但有可能生成的一些额外工作(任务很短,但仍然必须执行)最终与主线程在同一个核心上。您正在非常快速地创建大量任务。

  • 这两种方法之间的差异可能足以改变它们是否可以内联。这在某种程度上被 PostSharp 的使用混淆了,但我不会完全惊讶地发现是这种情况。

  • 在方法 2 的情况下,缩放并不是完全线性的,但也相距不远。如果您将 6000 + 23 * N 的公式作为一个快速而肮脏的近似值,您会期望值 6115、8300、29000、236000 和 23006000 - 相差不远。

  • 我强烈怀疑上次测试中第一个方法的巨大数字是由于垃圾收集和堆增长造成的。您在这里创建了大量对象,我怀疑它正在执行完整的 GC 并适当地扩展各个代 - 同一测试中的方法 2 然后利用了更大的堆。

这些实际上只是猜测,但它们为您所看到的一切提供了某种解释:)

【讨论】:

  • 谢谢乔恩。没想到男人自己的回答!我目前正在尝试破译 DotTrace 输出。您的回答对我有很大启发,谢谢。
  • @Ben:当心假设这个答案中的任何一个实际上都是准确的。这些想法可能会帮助您进一步诊断,但它们都不应该被认为是正确的:)(最简单的检查是我怀疑 JIT 编译器负责第一种方法,尽管少量迭代需要更长的时间。)
猜你喜欢
  • 2017-03-24
  • 1970-01-01
  • 2011-12-05
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 2017-04-22
相关资源
最近更新 更多