Question about slow application RPC time-- Bizzare

I am currently working on a Windows Form application that connects to a SQL database that will be hosted on the clients PC. I am in charge of creating the actual windows application within VS2005 while a team member of mine is in charge of creating the database tables and stored proceedures. Recently, we have started to run into a very interesting phenomenon. I can not tell if my application is causing the problem or if it is SQL Server 2005.

Here is what happens. We have a parameterized stored procedure that if we execute through the SQL Server Management Studio, takes only about 300 milliseconds, according to the SQL Server Profiler. Now, if I call that same procedure through my application, it takes 20 seconds to execute.

I've inserted breakpoints up to the point of the stored procedure execution in my application and I am positive, the slow down does not occur until the .NET DataAdapter launches the stored proceedure. Also, the profiler specifically shows the number of milliseconds it takes to launch the query. If we copy and paste the exact same EXEC line of code from the profiler into the Management Studio, it executes exponentially faster.

What might cause this? I know there might actually be many answers but this just started to happen and some times when I execute this SP with different parameters it actually executes at normal speeds. Other times there is a slow down if it is launched from the application.

Any thoughts? We are completely stumped.

One question to clarify...
Are you running your application on other computer, while executing the stored procedure through the SQL Server Management Studio at the machine where the database site in?

use profiler to capture the performance->statistics profile,
then compare the details in each

Sorry for the late repsonse. I posted at the end of the work day and I couldn't check my email yesterday evening.

The database is located on the computer that the application runs on. The stored procedure are also compiled and have been tested thoroughly before I integrated the calls to it into my application.

The guy on the team that I am working with is actually my boss. So, this morning, he and I have been looking at this. (He stopped me after I started typing the first sentence of this post to try some different things!)

Anyways, today I extracted the code that executes the stored procedure and hard coded the parameter values. I also hard coded the database connection string. I put the block of code into a simple console application in C# and, sure enough, if I call this stored procedure it takes forever to execute. If I select the exec text from the SQL Server Profiler and paste it into a new query window of the Managment Studio, it takes less than half a second.

I have worked with databases for about five years but have only within the last five months begun to work with SQL Server. Before I've worked mostly with Access and MySQL. SQL Server is a much more complex and different beast and in this case I have no clue where to begin to troubleshoot. My boss, however, has worked with SQL Server for years and is very knowledgeable. He has never seen anything like this and is about as stumped as I am.

quote:Originally posted by joechang

use profiler to capture the performance->statistics profile,
then compare the details in each

Sorry about having to ask a stupid follow-up question. When using the profiler, I usually start a new trace based on the default settings. If I create a new template, go to the Event Selection tab, and then Click on Performance, I see 'Auto Stats' and 'Showplan Profile' options. IS that what you are talking about?

Yeah, we've been trying to solve this together. He's out of the office now, though.

Nope. I also ran the profiler with the specified settings from above and both queries are returning the same results, including estimated CPU usage statistics and other time related estimations. Also, now nothing is appearing in the Duration column. I don't think that is a problem, but that's what I've been looking at in the profiler to get the exact time of the execution process.

yes, showplan statistics is what i meant, you need to include the binary field

but from your C# program,
when you call the stored proc,
i assume your sql command object is declared as a stored proc, possibly with parameters
if so, try declaring it as text, build the full string of parameter values, but do not use the append parameters features, just build the entire sql as a single string
try that

Ah, I see what you're saying. I'll give that a try.

Ok, I created the exec statement with the parameters and then tried to execute it from my app. This is it:


exec PS_cboMiniPS '', 10, 0, 10, 10, '*', '*'

If I execute that line of code as a Text type, it is still slow. It also doesn't matter if I pass the parameters names also. It's always slow. Right now I'm try to dump the entire SP to a string with the parameters coded in the string. I've save this very long SP to a text file and I dump the contents to a string that I am using as me command text. I'm trying to work out the bugs of my parameter declarations now. I hope this provides some clues.

Did you mean for me to try that too? Also, my boss is back in the office. He is going to drop the database and rebuild/re-add the data. We are working under test conditions so it's no big deal. When he's done he saves out a back-up and I restore it to my PC. We have both been getting this type trouble on both of our systems. Earlier satya mentioned clearing the cache. Do you mean in memory, or is there something else I can try? I have restarted the server and computer since this has started to happen with no change in results.

What login do you use to run the sp from query analyzer and from .Net code? I mean is it the same?
I guess not, so two execution plans are created and stored in sp cache. Obviously they are different for some reason. A few times I had to solve it, I decided to use query hints to force one I found more efficient.

Here is the connection string:


Data Source=.\sqlexpress;Initial Catalog=BOSS_Quote_V40_Local;Integrated Security=True;

Because of the integrated security my network login valids my connection to SQL Server. This is also the case when I start the Managment Studio-- my login is my network login. In other words, I don't see how they could be different. Also, the application that I am writing relies heavily on connecting to our DB. We currently have about 50 SPs and all of them are acting normally with the exeception of two of them that are giving us this problem. They are basically the same thing, except one returns more specific information and has one additional parameter.

Oops, sorry. Read the double slash as a single. I took it from a C# string.

next then, while running profiler,
execute the sp from QA,
execute from app

forget duration, what is the difference in CPU? (as read from profiler)

The Query from QA show a 68 under the CPU column and an 815 under the Reads column.

When I execute it in the app CPU is 27375 and the Reads is 1318215. I'm sure that CPU is some sort of measurement of CPU usage and I'm not sure what the reads column is for. I would assume that's how many times it's tried to read information from a table. Is that correct?

ignore the reads, it has no useful meaning

now run profiler with the performance -> showplan statistics, include the binary data column

compare the 2 plans

quote:Originally posted by rhartness

Here is the connection string:


Data Source=.\sqlexpress;Initial Catalog=BOSS_Quote_V40_Local;Integrated Security=True;

Because of the integrated security my network login valids my connection to SQL Server. This is also the case when I start the Managment Studio-- my login is my network login. In other words, I don't see how they could be different. Also, the application that I am writing relies heavily on connecting to our DB. We currently have about 50 SPs and all of them are acting normally with the exeception of two of them that are giving us this problem. They are basically the same thing, except one returns more specific information and has one additional parameter.

Ok, it is not the scenario i mentioned.

The binary columns are slightly different. The slow one begins with: 0x140000000A, and ends with 9A02, the faster one begins with 0x1400000008 and ends with 5803. Other than that the binary strings are the exact same.

I should also point out that it returns two lines every time a stored procedure is executed. The differences in the binary data were taken from the second line of both the slow and fast executions. The binary data for first row of each is exactly the same.

save the trace as a file and email it to me, jchang6@yahoo.com

Ah! Actually I can't now. I just left my bosses office about ten minutes ago and we've decided to take a different direction in handling the data. It's not the best way possible but we've been stumped on this for a week and it's been to long of a hold up. I hate conceeding on this type of stuff, but it's not my choice. The SP has already been changed significantly. (A lot was cut out.)
Thanks for all your help. I wish I could have solved the problem and not had to have run away.