C# object creation much slower than constructor call

Question

Hello everyone,

For the life of my, I can't figure out this performance hit in my code. I have a container object where I measure how long it takes to run the constructor (object below), timing code in the public constructor

 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()
    {... }

}

Now, I'm measuring the total time it takes to create the object as

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

and I'm consistently getting the following performance numbers -

Constructor time - 47 ms

Object creation time - 387 ms

47 ms is acceptable, 387 is really bad. Taking out the logging negligibly changes these numbers. Does anyone have any idea why this is taking so long? My system is VS 2008 SP1, targeting .NET 3.5 SP1 on Windows XP. I would appreciate any explanation. I'll be breaking out the profiler shortly, but I feel that it won't be able to delve into the level I need to explain this behavior. Thanks for any help.

EDIT: I'm running in release

Answer 1

Time to bring out Red Gate Performance Profiler. Instead of asking us to guess what the issue might be...download a trial and let it tell you EXACTLY where your issue is.

Profilers are great tools. Any developer should be familiar with how to utilize them to pinpoint performance issues.

Answer 2

Do you know that the Console.WriteLine in the constructor is throwing of your timing hugely? Any IO op will throw off these timings.

If you want real numbers, store the durations in a global somewhere then print them out after you have recorded everything.

Answer 3

Steve,

Here are a couple of things to consider:

1. Switch from using DateTime to using a StopWatch. It is much more accurate for these types of situations.
2. Stop writing out to the console during the timing process. The IO is going to be significant, and impact your timings.
3. Make sure you're running in a release/optimized build, and not running under the Visual Studio Test Host. If you run from a default VS, switch to Release, build, and use Ctrl+F5 (instead of just F5) to run.

Given your timings, I'm guessing #2 is your issue. Visual Studio adds a lot of "hooks" that dramatically impact perf. timings when running inside of Visual Studio.

Answer 4

Are you sure what you're seeing is the object creation time and not the effects of the CLR starting up?

Try running the test 50 times in a loop and ignoring the first result.

Answer 5

First use the StopWatch class to measure time instead. The resolution of the system time is way too low to give any accurate results.

Try to create more than one instance of the class. The first time the assembly might not be JIT:ed, which of course takes some time.

Answer 6

The question contains its own answer; there's more to instantiating an object than just running its constructor. When you call new you're asking the runtime to allocate space for an object, handle whatever internal bookkeeping the runtime needs, call the constructors for each base type (in this case, just object), and finally call your constructor.

When you measure the total instantiation time you're measuring all of that; when you time the constructor alone you're only measuring a part. If the numbers didn't differ, that would be a cause for concern.

Answer 7

As others have suggested, first and foremost, definitely switch to using 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;
}

And then:

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;

The reason I advise switching to using TimeSpan objects instead of doing something like (DateTime.Now - startTime).TotalMilliseconds is that, although it should make very little difference, technically in the latter case you are first calling getting the time and then getting the TotalMilliseconds property, which I am almost certain is a calculated value, in the constructor. Which means there's actually a step between checking the time in your constructor and checking the time immediately afterward. Really, this should be basically negligible, but it's good to cover all your bases.