.Net DateTime Precision

Question

within my .net domain object I am tracking each state transition. This is done by putting the state set into a state history collection. So later on, one can see an desc ordered list to find out which state was changed at what time.

So there is a method like this:

private void SetState(RequestState state)
{
    var stateHistoryItem = new RequestStateHistoryItem(state, this);

    stateHistoryItems.Add(stateHistoryItem);
}

When a new RequestStateHistoryItem is instantiated, the current date is automatically assigned. Like this:

protected IdentificationRequestStateHistoryItem()
{
    timestamp = EntityTimestamp.New();
}

The EntityTimestamp object is an object containing the appropiate user and created and changed date.

When listing the state history, I do a descending order with Linq:

public virtual IEnumerable<RequestStateHistoryItem> StateHistoryItems
{
    get { return stateHistoryItems.OrderByDescending(s => s.Timestamp.CreatedOn.Ticks); }
}

Now when a new Request is instantiated the first state Received is set in the constructor SetState(RequestState.Received). Then, without any delay and depending on some conditions, a new state Started is set. After some time (db operations) the state Finished is set.

Now when performing the descending ordering, the Received always is AFTER the Started state. When I am debugging slowly, or when putting a System.Threading.Thread.Sleep(1000) before setting the state to Started, the ordering works. If not, as told above, the Started state's CreatedOn is OLDER then the Received CreatedOn date?!

TimeOfDay   {17:04:42.9430318} FINSHED
Ticks   634019366829430318

TimeOfDay   {17:04:39.5376207} RECEICED
Ticks   634019366795376207

TimeOfDay   {17:04:39.5367815} STARTED
Ticks   634019366795367815

How can that be? I would understand if the received and start date is exactly the same, but I don't understand how it can even be BEFORE the other one?

I already tried new DateTimePrecise().Now, (see DateTimePrecise class) I found in another question. Same result.

Anyone knows what that could be?

Update

public virtual bool Finish()
{
    // when I put the SetState(State.Received) from the constructor into here, the timestamp of finish still is BEFORE received
    SetState(IdentificationRequestState.Received); 
    SetState(IdentificationRequestState.Finished);        

    // when I put the SetState(State.Received) after Finished, then the Received timestamp is BEFORE Finished  
    SetState(IdentificationRequestState.Finished);        
    SetState(IdentificationRequestState.Received); 

    var match = ...

    if (match != null)
    {
        ...
    }
    else
    {
        ...
    }
}

Answer 1

DateTime.Now is not accurate to the millisecond. It is only updated at larger intervals, something like 30 or 15 milliseconds (which is just the way Window's internal clock works, IIRC).

System.Diagnostics.Stopwatch is a more accurate way to measure time differences. It also doesn't have the overhead of UTC to local time conversions etc. The DateTimePrecise class uses a combination of DateTime and Stopwatch to give a more accurate time than DateTime.Now does.

Answer 2

You are retrieving the timestamp at an undetermined time before you add it to your collection.

The delay between retrieving it and adding it to the collection is variable - for example your thread may be pre-empted by the scheduler after getting the timestamp and before adding to the collection.

If you want strict ordering, you need to use synchronisation, something like the following every time you instantiate a history item:

lock(syncLock)
{
    // Timestamp is generated here...
    var stateHistoryItem = new RequestStateHistoryItem(state, this);
    // ... but an indeterminate time can pass before ...
    ...
    // ... it's added to the collection here.
    stateHistoryItems.Add(stateHistoryItem);
}