Concurrency-Issue using ExecuteNonQuery

Question

I'm writing simple text log Entries to an SQL-table like so:

private SqlConnection sqlcon;

// ...

try {
    sqlcon.Open();

    SqlCommand cmd = sqlcon.CreateCommand();
    cmd.CommandText = this.logString;

    cmd.ExecuteNonQuery();
} 
/* catch SqlException, InvalidOperationException, Exception */ 
/* finally sqlcon.Close() */

Asynchronous Processing is set to false, so i thought the log entries would appear in the table in the order of execution. But that is not the case, if 2 or more log entries are fired in about less than 5ms.

So my guess is that ExecuteNonQuery runs on a different thread and somehow the different events get mixed up. I've already tried using Asynchronous Processing with BeginExecuteNonQuery and EndExecuteNonQuery, but it messes up my code and is not really working anyway.

So my question is: Is there any way to ensure, that the nonQueries are being executed in exactly the order they were triggered?

edit: Maybe it's important, i'm using a timestamp like so

cmd.Parameters.Add("timestamp", SqlDbType.DateTime ).Value = System.DateTime.Now;

Answer 1

Asynchronous?

If you open/close the connection each time you can't be really sure of that, it's somehow equivalent (please forgive me, I know this isn't really exact) to call BeginExecuteNonQuery (it was the method used before MARS). Actually each request is synchronous but, if you log something with a 5 ms interval, you can't be sure about the order SQL Server will serve that requests (DB guys here will think about the old problem of IDENTITY columns).

TimeStamp

Then the solution should be to use a TimeStamp column and to order results based on that column (write order doesn't matter). It's the perfect solution (as pointed by other answers do not forget to use the right data type to store the data).

How to get the actual time? You can do it on client-side (as in your example) using DateTime.Now function or on server-side using SYSDATETIME (as pointed by @PetrAbdulin). It's a perfect solution if you do not need high resolution.

PRECISION

Both functions rely on Windows system timer and it's resolution isn't granted to be more than 10 ms (then, if you really need 5 ms granularity, you should avoid them).

On MSDN you can read that DateTime.Now on Windows NT has a resolution of 10 ms, the SYSDATETIME calls GetSystemTimeAsFileTime, the FILETIME structure has a 100 ms precision but the timer itself isn't granted to achieve that result!!! In some conditions you may even get a 1 ms tick but it's not reliable at all. In the documentation about the StopWatch timer you can read:

The timer used by the Stopwatch class depends on the system hardware and operating system. IsHighResolution is true if the Stopwatch timer is based on a high-resolution performance counter. Otherwise, IsHighResolution is false, which indicates that the Stopwatch timer is based on the system timer.

What does it mean? A system timer is never granted to have a high resolution (do not be confused by the precision of the structure used to store the time).

It could be a problem or not, it depends for what you'll use your logs. If you have to log the list of file copied from one folder to another during a backup then you may not need such precision. If your logs may be used for legal stuffs (yes, I know they should not have any legal value) or to debug a subtle threading issue then you'll need it.

SOLUTIONS

If you need a high resolution timer (and, on Windows, you may consider anything < 10 ms as high resolution) you have to deal with Performance Counters. Take a look at this great article about timing. Of course you do not need all that stuff but it points the problem.

In .NET you may use DateTime.Now with a StopWatch (checking the IsHighResolution property). Read this good post here on SO about the use of the StopWatch to increase the precision of DateTime.Now.

COMMON ERRORS

First do not confuse the precision of the data type used to store the time with the resolution of the timer. It doesn't matter how much your timer is precise if you store that value in a low resolution field but to use a high resolution field doesn't transform your coarse timer into a high resolution one.

Moreover you should not use the local time as TimeStamp, you'll confuse your logs when the system time will change because of daylight saving. Think about this:

               00:00   02:00   02:01   03:00   02:00
Log              #1      #2      #3              #4
System time                             -1

Now when'll you read your log you'll get this order: 1, 2, 4, 3. For this reason you should NEVER use DateTime.Now and SYSDATETIME for your logs, you should always prefer the DateTime.UtcNow and SYSUTCDATETIME functions (moreover performances of DateTime.UtcNow are a little bit better).

Answer 2

What if you use SQL Server SYSDATETIME to insert timestamps? I think that ExecuteNonQuery is synchronous, but maybe something wrong with your timestamp.

There is a good document about time resolution in Windows.

Answer 3

SQL Server has a datetime precision of 3 milliseconds. Do those entries that's listed out-of-order have the same timestamp? (With milliseconds ending with 0, 3 or 7).

You need a field with higher precision, like the datetime2 data type (available from SQL Server 2008), or an incremental counter for the items to be correctly sorted.

Answer 4

Why aren't you using transactions? if the data is important then you should use SqlTransaction.

Why do you need ordering? Do you have a pk on your table? how is it inserted, or is the timestamp your pk?

By the way, please don't cache the connections. .net is doing that for you better. use using like in this msdn example.