question

Wong-3375 avatar image
0 Votes"
Wong-3375 asked ·

Stored procedure called once, but executed twice.

I'm using System.Data.SqlClient.SqlCommand.ExecuteNonQuery() to execute a stored procedure in SQL Server 2012.
From my application log, this execution has been called only once (it writes log for each calls), but, I realized the store procedure executed twice in database, and both execution were running in parallel which started at almost the same time (just few milliseconds different).
I know the execution time because the store procedure insert GETDATE() into a table and also update GETDATE() in another column of the table before it ends.

This happens very rarely. The store procedure is being called around 5 million times in a year and there are only 3 cases. This 3 cases are causing troubles.

Below is how my code looks like...

 using (SqlConnection conn = new SqlConnection())
 {
  conn.ConnectionString = "connectionstring";
  conn.Open();
    
  SqlCommand cmd = new SqlCommand();
  cmd.Connection = conn;
  cmd.CommandType = CommandType.StoredProcedure;
  cmd.CommandText = "a_stored_procedure";
  cmd.CommandTimeout = 60 * 60 * 2; //giving the execution running maximum 2 hours long
  cmd.Parameters.AddWithValue("@param1", 1);
  cmd.ExecuteNonQuery();
 }
 //write log here after the query execution

Anyone knows why is this happening?
The application is running in .Net 4.6.1.

sql-server-generalsql-server-transact-sqldotnet-csharpdotnet-runtime-frameworkdotnet-adonet
· 3
10 |1000 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

Is there any kind of retry logic in the application?

0 Votes 0 ·

Thank you for your comment, but there is no retry logic in the application.

0 Votes 0 ·

cmd.CommandTimeout = 60 * 60 * 2; //giving the execution running maximum 2 hours long

Your code suggests that:
1. You are calling a sql stored procedure synchronously
2. There is a reasonable expectation the sproc could run for 2 hours

It's no wonder you are experiencing errors.







0 Votes 0 ·
Viorel-1 avatar image
3 Votes"
Viorel-1 answered ·

Maybe it happened because of switching from summer time?

· 2 ·
10 |1000 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

Yup the code seems to be okay, DST switch is likely to cause the problem.

The other possible reason is that your system clock ticks faster than it should be (or I should say it runs at irregular clock speed), so from time to time it'll skew forward from normal time and need the NTP to bring it backward. In this case you'll have multiple occurrence of same time. (If this is the reason, you should be able to find some W32Time events in event log like EventId 0, 33, 52)

Regardless of the cause, the fix is to add some locking mechanism to prevent reentrancy .

1 Vote 1 ·

Thanks for mentioning about this one. I will have a check on it.

0 Votes 0 ·
MrioMonteiro-4211 avatar image
0 Votes"
MrioMonteiro-4211 answered ·
· 1 ·
10 |1000 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

Thanks for the suggestion, but there's no error being thrown out from my case.

1 Vote 1 ·
TomPhillips-1744 avatar image
0 Votes"
TomPhillips-1744 answered ·

The code you posted does not run it twice.

It is much more likely it was already running when it was started again, probably due to being blocked or a client failure or something.

· 2 ·
10 |1000 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.

I understand what you mean, but I need to pin point the issue before thinking about the solution.

0 Votes 0 ·

There is no way to figure this out after the fact. You would have to detect it when it happens.

There are several possible answers, in addition to mine.

The most basic is you are using GETDATE() which has a 3ms resolution. So it is possible if you called it several time very quickly you could get the same GETDATE().

It is also possible you have your server setup to get sync to an external clock which changed the clock value back some seconds. This is common and expected behavior. The clock on the server can be wrong for many reasons.

0 Votes 0 ·
ErlandSommarskog avatar image
3 Votes"
ErlandSommarskog answered ·

In addition to what other people have said: there is much to work from in your post.

I can tell you what did not happen: the piece of code you posted did not on its own account decide to run the procedure twice. That did simply not happen. So the cause is elsewhere. Since we don't know anything about your system, we can only speculate. For all I care, it could be as simple as that were two instances of your application running at the same time.

You have a command timeout of two hours, which makes me think that it is a long-running procedure, and in such case the milliseconds will not matter. But if there can also be very short executions, they can. It is perfectly possible for time to go backwards in a modern computer, so that getdate() at point B returns an earlier value than at point A, although A was before B in real-world time. (I believe this is due to that the time may be gotten from different CPUs. Balanced power plans may also have to do with it.) Thus, you cannot trust timestamps on that granularity fully. But if all executions are several seconds this is not the issue.

By the way, I think that for recording timestamps, the best data type is datetime2(3) and use the function sysdatetime() which has an accuracy of 1 ms. Although, that does of course not happen when time goes backwards.

·
10 |1000 characters needed characters left characters exceeded

Up to 10 attachments (including images) can be used with a maximum of 3.0 MiB each and 30.0 MiB total.