Why do I get strange timings when tracking my workflow?

Question

I have a tracking participant which, when called, fires off a new thread to do the tracking work. The tracking work eventually does this:

private static readonly ConcurrentDictionary<string, DateTime> TimingsDictionary = new ConcurrentDictionary<string, DateTime>();
private static readonly ConcurrentDictionary<Guid, DateTime> WorkflowTimingsDictionary = new ConcurrentDictionary<Guid, DateTime>();

private void TimeActivityRecord(TrackingRecord record)
{
    var activityStateRecord = record as ActivityStateRecord;
    if (activityStateRecord != null)
    {
        if (activityStateRecord.State == ActivityStates.Executing)
        {
            if (!TimingsDictionary.TryAdd(GetActivityId(activityStateRecord), activityStateRecord.EventTime))
            {}
        }

        if (activityStateRecord.State == ActivityStates.Closed
            || activityStateRecord.State == ActivityStates.Faulted
            || activityStateRecord.State == ActivityStates.Canceled)
        {
            DateTime startTime;
            if (TimingsDictionary.TryRemove(GetActivityId(activityStateRecord), out startTime))
            {
                timer.TimeAction("Executing workflow step " + activityStateRecord.Activity.Name, activityStateRecord.InstanceId, activityStateRecord.EventTime.Subtract(startTime));
            }
        }
    }
}

private void TimeWorkflowRecords(TrackingRecord record)
{
    var workflowInstanceRecord = record as WorkflowInstanceRecord;
    if (workflowInstanceRecord != null)
    {
        if (workflowInstanceRecord.State == WorkflowInstanceStates.Started)
        {                    
            if (!WorkflowTimingsDictionary.TryAdd(workflowInstanceRecord.InstanceId, workflowInstanceRecord.EventTime))
            {}
        }

        if (workflowInstanceRecord.State == WorkflowInstanceStates.Completed
            || workflowInstanceRecord.State == WorkflowInstanceStates.Aborted
            || workflowInstanceRecord.State == WorkflowInstanceStates.UnhandledException
            || workflowInstanceRecord.State == WorkflowInstanceStates.Terminated
            || workflowInstanceRecord.State == WorkflowInstanceStates.Canceled)
        {
            DateTime startTime;
            if (WorkflowTimingsDictionary.TryRemove(workflowInstanceRecord.InstanceId, out startTime))
            {
                timer.TimeAction("Executing workflow", workflowInstanceRecord.InstanceId, workflowInstanceRecord.EventTime.Subtract(startTime));
            }
        }
    }
}

to track the entire workflow time and the times of the configured activities. however I get strange results with the workflow instance itself always seeming to take less time than the longest activity. sometimes I get the workflow taking 16ms and the 6 activities within it taking 625ms, 150ms, 125ms, 93ms, 17ms, 78ms.

Am I doing something very wrong? I feel like I must be missing something very obvious but can't for the life of me see what it is.

Answer 1

of course I was doing something stupid. When I logged the time taken from the timespan I was using

timespan.Milliseconds

rather than

timespan.TotalMilliseconds

back to school for me. Or maybe just some sleep.