C#对象创建比构造函数调用慢得多

Question

就我个人而言，我无法弄清楚我的代码中的性能问题。我有一个容器对象，在其中测量运行构造函数（下面的对象）所需的时间，在公共构造函数中计时代码。

 public class WorkUnit : IWorkUnit
{
    private JobInformation m_JobInfo;
    private MetaInfo m_MetaInfo;
    private IPreProcJobInfo m_PreprocDetails;


    readonly private Guid m_ID;
    private Guid m_ParentID;
    private Guid m_MasterJobID;


    private string m_ErrorLog = string.Empty;
    private PriorityKeeper m_Priority;
    private WorkUnitClassification m_Classification;

    private IJobPayload m_CachedPayload;
    private IJobLogger m_Logger;
    private EventHandler<JobEventArgs> m_IsFinished;
    private ReaderWriterLockSlim m_Lock;

    public WorkUnit(string InputXML, Guid JobID, IJobLogger Logger)
    {
        DateTime overstarttime = DateTime.Now;

        try
        {
        ....Do Stuff....
        }
        catch(XMLException e)
        {...}
        catch(Exception e)
        {
         ...
         throw;
        }

        double time = (DateTime.Now - overstarttime).TotalMilliseconds
        Console.WriteLine("{0}", time);
    }

    /// <summary>
    /// Private Constructor used to create children
    /// </summary>
    private WorkUnit(Guid MasterID, Guid ParentID, WorkUnitClassification Classification, PriorityKeeper Keeper)
    {...}

    [OnDeserializing()]
    private void OnDeserialize(StreamingContext s)
    {...}

    public PriorityKeeper PriorityKey
    {...}

    public bool HasError
    {...}

    public bool Processing
    {...}

    public bool Splittable
    {...}

    public IEnumerable<IWorkUnit> Split(int RequestedPieces, int Bonds)
    {...}

    public void Merge(IResponse finishedjob)
    {...}

    public ReadOnlyCollection<IWorkUnit> Children
    {...}

    public bool IsMasterJob
    {...}

    public Guid MasterJobID
    {...}

    public Guid ID
    {...}

    public Guid ParentID
    {...}

    public EnumPriority Priority
    {...}

    public void ChangePriority(EnumPriority priority)
    {...}

    public string ErrorLog
    {...}

    public IMetaInfo MetaData
    {...}

    public IJobPayload GetProcessingInfo()
    {... }

    public IResponseGenerator GetResponseGenerator()
    {... }

}

现在，我正在测量创建对象所需的总时间。

DateTime starttime = DateTime.Now;
var test = new WorkUnit(temp, JobID, m_JobLogger);
double finished = (DateTime.Now - starttime).TotalMilliseconds;

我一直得到以下性能数据 -

构造函数时间 - 47毫秒

对象创建时间 - 387毫秒

47毫秒是可以接受的，387毫秒非常糟糕。去掉记录对这些数字没有实质性的变化。有人知道为什么需要这么长时间吗？我的系统是VS 2008 SP1，在Windows XP上针对.NET 3.5 SP1。感谢任何解释。我很快就会使用分析器，但我觉得它无法深入到我需要解释这种行为的水平。谢谢任何帮助。

编辑：我正在运行发布版

- Steve

---

没有 try 和 catch 块中的代码很难猜测。也许你可以发布更多的代码？异常是否被抛出（慢）？ - Cecil Has a Name

你是在测量特定代码路径下的第一次调用，还是后续调用的平均值？请记住，任何东西的第一次调用可能会更加昂贵，因为它需要加载它引用的所有DLL的传递闭包，在使用的类型的静态构造函数中运行所有代码，并jit编译所有未ngened的代码。第一次通过代码路径通常比每个后续调用要昂贵得多。 - Eric Lippert

Answer 1

您确定所看到的是对象创建时间而不是CLR启动的影响吗？

尝试在循环中运行测试50次并忽略第一个结果。

- Winston Smith

---

那就是它了，第一次运行速度真的很慢，之后就快多了。 - Steve

只是我的个人看法：我认为真正的罪魁祸首是DateTime.Now，因为第一次运行比随后的所有次数都要慢得多。(我知道；我已经对其进行了分析。)既然你在构造函数之前调用了它，那么那个就是缓慢的;然后构造函数中的两个和之后的一个应该是快速的。 - Dan Tao

这有一定的道理。DateTime.Now需要执行各种有趣的操作，例如确定我现在是否处于夏令时，我所在的时区等等。第一次加载所有代码是昂贵的；每个后续时间都很便宜，因为它只是调用“热”代码，而不是加载“冷”代码。 - Eric Lippert

Answer 2

Steve,

以下是需要考虑的几点:

1. 切换使用 StopWatch 代替 DateTime进行计时，它在这种情况下更加精确。
2. 在计时过程中停止向控制台输出。IO会对计时产生相当大的影响。
3. 确保您正在运行释放/优化版本，而不是在Visual Studio测试主机下运行。如果您从默认 VS 运行，请切换到Release，构建并使用Ctrl+F5（而不是仅仅F5）来运行。

根据您的计时，我猜测问题在于 #2。Visual Studio添加了很多“钩子”，在Visual Studio内部运行时会极大地影响性能计时。

- Reed Copsey

---

很遗憾，我正在运行发布版本。 - Steve

你是在Visual Studio里运行吗？仅仅切换到发布模式还不够，确保不要在测试主机内运行。 - Reed Copsey

听起来你遇到了一个问题，测试主机需要钩入每个对象，这会增加很大的开销。 - Reed Copsey

抱歉，也要在VS之外运行它。 - Steve

切换到秒表，并将IO调用移除。如果这还不明显，那么很可能是其他奇怪的事情发生了。对您的应用程序进行分析以查看可能出现的问题。 - Reed Copsey

@Steve：DateTime.Now既不快也不准确。当你像Reed和其他人建议的那样切换到Stopwatch并注释掉Console.WriteLine后，你有什么发现？ - Dan Tao

Answer 3

首先使用 StopWatch 类来计量时间。系统时间的分辨率太低，无法提供准确的结果。

尝试创建多个类的实例。首次加载可能不会进行 JIT 编译，这当然需要一些时间。

- Guffa

Answer 4

现在是时候使用Red Gate Performance Profiler了。不要让我们猜测问题所在，下载试用版并让它准确地告诉您问题出在哪里。

性能分析工具是非常好的工具。任何开发者都应该熟悉如何利用它们来定位性能问题。

- Justin Niessner

Answer 5

正如其他人建议的那样，首先，一定要切换到使用System.Diagnostics.Stopwatch：

public WorkUnit(string InputXML, Guid JobID, IJobLogger Logger, out TimeSpan elapsed)
{
    Stopwatch constructionStopwatch = Stopwatch.StartNew();

    // constructor logic

    constructionStopwatch.Stop();
    elapsed = constructionStopwatch.Elapsed;
}

然后：

TimeSpan constructionTime = TimeSpan.Zero;
Stopwatch creationStopwatch = Stopwatch.StartNew();

var test = new WorkUnit(temp, JobID, m_JobLogger, out constructionTime);

creationStopwatch.Stop();
TimeSpan creationTime = creationStopwatch.Elapsed;

double constructionMs = constructionTime.TotalMilliseconds;
double creationMs = creationTime.TotalMilliseconds;

我建议使用TimeSpan对象而不是像(DateTime.Now - startTime).TotalMilliseconds这样做的原因是，尽管差别非常小，但在后一种情况下，你实际上首先调用了获取时间的方法，然后再获取TotalMilliseconds属性，我几乎可以确定这是一个计算值，在构造函数中进行计算。这意味着在检查构造函数中的时间和立即之后检查时间之间实际上有一步。实际上，这应该基本可以忽略不计，但全面考虑总是好的。

- Dan Tao

Answer 6

问题包含了答案；实例化一个对象不仅仅是运行它的构造函数。当你调用new时，你要求运行时为对象分配空间，处理运行时需要的任何内部簿记，调用每个基类型的构造函数（在这种情况下，只有object），最后调用你的构造函数。

当你测量总实例化时间时，你测量所有这些内容；当你仅计时构造函数时，你只测量其中的一部分。如果数字没有不同，那将是一个值得关注的原因。

- Skirwan

Answer 7

你知道构造函数中的Console.WriteLine会严重影响你的时间吗？任何IO操作都会扰乱这些时间。

如果你想要真实的数字，请将持续时间存储在全局变量中，然后在记录完所有内容后再打印出来。

- Frank Krueger

---

如果我将其注释掉，构建对象的时间仍然大致相同。 - Steve