7

Running the same Stored Procedure from C# .Net application over a network gets progressively slower with each subsequent execution. It appears to take twice the amount of time as the previous execution (up to a max value; read on). The execution time becomes progressively slower until 1 of 2 scenarios happens, at which point the first execution of the SPROC is "fast" again.

  1. If an SqlConnection is opened and remains open during all testing, the SPROC gets progressively slower until any other SPROC or query is run.
  2. If an SqlConnection is opened and closed around each execution, the SPROC gets progressively slower until at least 8 minutes has passed.

This only happens with a few Stored Procedures. One is a simple SELECT query with 2 JOINs, (SPROC 1) another is a massive 1600+ line SPROC (SPROC 2).

The execution times appear to never go beyond exactly 60 seconds for SPROC 1 and 67 seconds for SPROC 2. SPROC 1 takes less than a second to execute initially, and SPROC 2 takes 7 seconds initially.

This also only happens if the SPROC is run using the same SqlConnection in the application. As soon as 2 separate SqlConnection objects are used, they behave the same as stated above, but are independent. Running the SPROC multiple times on SqlConnection1 gets progressively slower, but the first time the same SPROC is run on SqlConnection2, it's "fast". It will then also get slower when run multiple times on SqlConnection2.

This does not happen if the application is run on the same computer with SQL Server 2008 R2 installed (running Windows Server 2008). The execution time is always consistent.

Running the Stored Procedure from within Management Studio also does not get slower with each execution; it is always consistent.

Clearing the execution plan cache (in SQL Server) has no effect on the observed behavior.

It has taken quite a few days to narrow down this issue originally observed in a much larger application, in order to create a test app to easily test/reproduce it.

From what I've read here, there is a timeout of between 4 and 8 minutes (after SqlConnection.Close() is called in code) at which point it closes the database connection to the data source. This appears to be in line with the scenario 2 I mentioned above.

This leads me to believe it is related to the SqlConnection used (and the underlying database connection to the data source) since connection pooling is enabled in my case, but why am I observing this behavior, and how do I fix it?

We are using the .Net 2.0 Framework, if that makes any difference.

There are many fine details listed above, so please let me know if I need to clarify anything.

The only Stack Overflow question with any similarities is this, but was unrelated to my issue.

Edit: The following code is executed in my WinForms test app on startup:

SqlConnectionStringBuilder connectionStringBuilder = new SqlConnectionStringBuilder();

connectionStringBuilder.DataSource = m_DataSource;
connectionStringBuilder.InitialCatalog = m_InitialCatalog;
connectionStringBuilder.UserID = m_UserID;
connectionStringBuilder.Password = m_Password;
connectionStringBuilder.IntegratedSecurity = false;
connectionString = connectionStringBuilder.ConnectionString;

m_DatabaseConnection = new SqlConnection(connectionString);

I then have 2 buttons; one of which calls SPROC 1 mentioned above, and the other calls a different SPROC which does not have the same slowdown issue. The following code is executed on either button click (only difference being the SPROC name):

m_DatabaseConnection.Open();
m_DatabaseCommand = new SqlCommand("GetCompanies", m_DatabaseConnection);
m_DatabaseCommand.Parameters.AddWithValue("@StatusID", StatusID);
m_DatabaseCommand.CommandType = CommandType.StoredProcedure;
m_DatabaseCommand.CommandTimeout = 0;

SqlDataAdapter databaseDataAdapter = new SqlDataAdapter(m_DatabaseCommand);
DataSet databaseDataSet = new DataSet();
databaseDataAdapter.Fill(databaseDataSet);
m_DatabaseConnection.Close();
Community
  • 1
  • 1
njb
  • 105
  • 1
  • 1
  • 7
  • 1
    This may be something better posted on [dba](http://dba.stackexchange.com/). – Oded Apr 11 '12 at 20:17
  • 1
    This must be due to your code. However, since you haven't shown us your code, we're not going to be able to help you. – John Saunders Apr 11 '12 at 20:24
  • @JohnSaunders - I can post the query for SPROC 1 if desired, but I don't think anyone will benefit from the 1600+ line SPROC 2. – njb Apr 11 '12 at 20:59
  • Can you upload SPROC2 on pastebin? That way we can at least scroll through to look for suspicious patterns. – usr Apr 11 '12 at 21:24
  • @usr - SPROC 2 can be found [here](http://pastebin.com/xKGhVARc). SPROC 1 can be found [here](http://pastebin.com/ZXaS6vbJ), which uses a view. Query for the view is found [here](http://pastebin.com/95muBw7G). – njb Apr 11 '12 at 21:58
  • @usr - Sorry, the view listed above was the fixed one, [here](http://pastebin.com/GhW8Qv9d) is the one that has the problem. Not much difference between them, but the originally posted one does not slow down with each execution. – njb Apr 11 '12 at 22:23
  • I see you don't have your `SqlConnection`, `SqlCommand` and `SqlDataAdapter` objects in `using` clauses. This is a very likely culprit of performance problems over time. – John Saunders Apr 11 '12 at 23:12
  • @JohnSaunders - True, I didn't add those into the test app. Does that explain the behavior though? I'll add them in to see if it makes a difference. – njb Apr 11 '12 at 23:18
  • It may explain the behavior. Whenever I hear, "performance of database gets worse over time", I wonder about Disposal of IDisposable instances. – John Saunders Apr 12 '12 at 00:31
  • @JohnSaunders - Unfortunately wrapping those in using clauses didn't fix it. – njb Apr 12 '12 at 14:15

1 Answers1

3

Here are my ideas to debug this problem:

  • Try calling SqlConnection.ClearAllPools() after Disposing the connection. If this fixes the problem, the problem is tied to a particular connection for sure.
  • Next, enclose the SPROC in an explicit transaction.
  • Next, call SqlConnection.ClearAllPools() before invoking the SPROC.
  • How much data does the SPROC return?
  • Please post the C# code you are using to open the connection and execute the SPROC.
  • Create a standalone console app that is reproducing the behavior you are seeing. This will (likely) prove that something in your app is the problem because the console app will run just fine.
usr
  • 168,620
  • 35
  • 240
  • 369
  • I will start trying your suggestions now, thanks. SPROC 1 returns 10 records at most, with 11 columns. SPROC 2 returns 2 records, with 15 columns. – njb Apr 11 '12 at 21:03
  • Calling ClearAllPools() after Disposing does fix the problem, as does calling it before invoking the SPROC. Enclosing the SPROC in an explicit transaction (in .Net - TransactionScope object) also fixes the problem. It "works", but what is really causing the issue? This is all tested in my standalone WinForms Test App. – njb Apr 11 '12 at 21:26
  • When a connection is returned to the pool the isolation level is not reset. This might be the problem. Try removing the tran, but execute "set transaction isolation level read committed" before executing the proc. Does this fix the problem? – usr Apr 11 '12 at 21:37
  • Having seen the long sproc the only thing I could find was that you are using table variables. These don't have statistics leading to extremely poor plans. I recommend to use temp tables. Maybe the perf will get more predictable that way. But I did not find any problems that could lead to "garbage" accumulating over time. Are you sure the problem happens with GetCompanies? It consist of a single select only. Try this: Delete stuff from this proc until it stops happening. – usr Apr 11 '12 at 22:13
  • I did have `transactionOptions.IsolationLevel = System.Transactions.IsolationLevel.ReadCommitted` using the `TransactionScope` previously. I removed the tran and executed that command before executing the SPROC and it also fixed the problem. – njb Apr 11 '12 at 22:15
  • Yes, it truly happens with GetCompanies, but look at my correction above. That is what has been driving me nuts, it's a very simple SPROC, and it has the same problem as an extremely large SPROC. – njb Apr 11 '12 at 22:25
  • I'd really love to debug this problem on premises. What a nice puzzle. Can you remove all the transaction stuff and execute this (http://stackoverflow.com/a/1038184/122718) query before running the sproc? What does it print? If it prints anything other than "read committed" we have found the problem: One of your procs, or any other part of the system, is changing the isolation level and it is leaking across pool connections (see my question: http://stackoverflow.com/questions/9851415/sql-server-isolation-level-leaks-across-pooled-connections). – usr Apr 11 '12 at 22:45
  • I ran that query and always get "Readcomitted". But since I'm running a different query on the same `SqlConnection`, it's eliminating the behavior. i.e. I'm essentially not running the same SPROC back-to-back anymore. I wonder if that's why executing the "set transaction isolation level read committed" command you had me run be executing the SPROC also "fixed" it? – njb Apr 11 '12 at 23:15
  • Yes. It seems the isolation level was set differently. I don't know at all why this would produce the slowing down effect you are seeing. You could also try printing the value of @@TRANCOUNT. Maybe there is some remnant tran open. You could also try to repro in a tiny console app. – usr Apr 11 '12 at 23:18
  • In any case it seems you have acceptable workarounds now. I recommend you use the TransactionScope solution. – usr Apr 11 '12 at 23:19
  • In further testing, if I execute `SELECT 1` before running the SPROC (on the same `SqlConnection`), this also fixes it. I will likely use TransactionScope for the solution, but will continue investigating the **why** if anyone has more suggestions to try. – njb Apr 12 '12 at 14:21