donaldwyatt
asked on
Slow speed when retrieving large number of rows from database (ASP.NET 2.0 / SQL 2005)
I have a web application that has a dashboard-like main menu. When the user first logs in, we do a database pull from SQL Server 2005 and then store the resulting DataTable in a Cache object. The page then displays the dashboard results from the cached data. As long as the cache is there, we do not pull the data from the database again. Certain events that would cause a refresh of the dashboard simply clear the cache, and that way the data is up to date, but with minimal database interaction.
Many times the query only returns 10 rows, but in cases where there are 500 rows, the page on our production server can take almost 8 seconds to load if we have to do the database pull. That 8 seconds is calculated from the time taken field in our logs in IIS, so it accounts for the latency of the data transmission.
However, if we load that same page after the data is cached, it takes less than a second. Again, this number comes from the server logs, showing a 7 second performance hit when we do the database call. The obvious answer is that the stored procedure is slow, but using SQL Server Management Studio, if we run that exact query on the production server, it returns results in less than 500 milliseconds.
So, I have a page that executes 7 seconds slower when there is a database call, but that call only takes .5 seconds. Where is that other 6.5 of additional time coming from?
Our theory is that because we are putting the data into a DataTable, we are taking a hit from .net loading the query results into the table. Heres what we found as we tried to test that&
If I watch the performance monitor on the production server when we simply run the query from SQL Server Management Studio, we get a slight increase in CPU utilization for a moment. But if we run the web page that has the database call in it, the CPU utilization maxes out for about twice the time. That would imply the problem is in the .net processing, as suspected.
If I run that same test where I watch the CPU utilization on the Processes tab in the Task Manager on the production server, when we load the web page that has the database call, we see the CPU utilization for SQL Server increase substantially, but the CPU utilization for the .net worker process does not noticeably increase. I would have thought that if the problem was .net straining to create the DataTable, the .net worker process would jump in CPU utilization, not SQL Servers process.
Any ideas on what is happening or how to narrow down the problem would be greatly appreciated.
Thanks!
Many times the query only returns 10 rows, but in cases where there are 500 rows, the page on our production server can take almost 8 seconds to load if we have to do the database pull. That 8 seconds is calculated from the time taken field in our logs in IIS, so it accounts for the latency of the data transmission.
However, if we load that same page after the data is cached, it takes less than a second. Again, this number comes from the server logs, showing a 7 second performance hit when we do the database call. The obvious answer is that the stored procedure is slow, but using SQL Server Management Studio, if we run that exact query on the production server, it returns results in less than 500 milliseconds.
So, I have a page that executes 7 seconds slower when there is a database call, but that call only takes .5 seconds. Where is that other 6.5 of additional time coming from?
Our theory is that because we are putting the data into a DataTable, we are taking a hit from .net loading the query results into the table. Heres what we found as we tried to test that&
If I watch the performance monitor on the production server when we simply run the query from SQL Server Management Studio, we get a slight increase in CPU utilization for a moment. But if we run the web page that has the database call in it, the CPU utilization maxes out for about twice the time. That would imply the problem is in the .net processing, as suspected.
If I run that same test where I watch the CPU utilization on the Processes tab in the Task Manager on the production server, when we load the web page that has the database call, we see the CPU utilization for SQL Server increase substantially, but the CPU utilization for the .net worker process does not noticeably increase. I would have thought that if the problem was .net straining to create the DataTable, the .net worker process would jump in CPU utilization, not SQL Servers process.
Any ideas on what is happening or how to narrow down the problem would be greatly appreciated.
Thanks!
ASKER
>> 1. Is the data retrieved via a stored procedure or with embedded sql in the .net application?
It is pulled via a stored procedure
>> 2. What is the record size of the table/tables that the data is being drawn from?
The procedure is a join between a number of tables of varying sizes.
However, users who may only have 5 rows returned from this procedure have very fast response times, so Im doubtful that the underlying size of the tables is the culprit. Otherwise, everyones call to the procedure would be slow.
Along those lines, when we test the execution time in SQL Server Management Studio between a call to that procedure that returns just 5 rows vs. 500 rows, theres only about 200ms difference (the 500 row query takes about 570ms). So, the execution time on SQL Servers part doesnt seem to be impacted much by the number of rows returned from the stored procedure. Its when we send it over to .net that the row count appears to impact performance.
I hope that addresses your underlying question. If not, perhaps you could give me a little more detail to help me understand your thought process.
>> 3. Are you displaying all 500 records at once when displayed?
Yes.
>> 4. Also, if you refresh the data but DO NOT display the data, is there still a delay for the page to load? (This will help determine if the delay is in the building of the HTML for display or the return of the data from SQL.)
Excellent question. Unfortunately, we cannot recreate this speed problem in our test environment, and we dont have any way to run the query and have the page not show the data in production. However, I think the key difference is in what happens in the pages:
Process if there is a database pull (8 seconds to complete):
1. Call the stored procedure and store results in a DataTable
2. Save the DataTable into the Cache object
3. Use the DataTable to generate the HTML and display the page
Process if there is no database pull (less than 1 second to complete):
1. Get the DataTable from the Cache object
2. Use the DataTable to generate the HTML and display the page
In both cases, the exact same amount of HTML is being written with the exact same data, but with wildly different execution times. Therefore, I think that narrows down the problem to somewhere in steps 1 or 2 in the first scenario.
Thanks.
It is pulled via a stored procedure
>> 2. What is the record size of the table/tables that the data is being drawn from?
The procedure is a join between a number of tables of varying sizes.
However, users who may only have 5 rows returned from this procedure have very fast response times, so Im doubtful that the underlying size of the tables is the culprit. Otherwise, everyones call to the procedure would be slow.
Along those lines, when we test the execution time in SQL Server Management Studio between a call to that procedure that returns just 5 rows vs. 500 rows, theres only about 200ms difference (the 500 row query takes about 570ms). So, the execution time on SQL Servers part doesnt seem to be impacted much by the number of rows returned from the stored procedure. Its when we send it over to .net that the row count appears to impact performance.
I hope that addresses your underlying question. If not, perhaps you could give me a little more detail to help me understand your thought process.
>> 3. Are you displaying all 500 records at once when displayed?
Yes.
>> 4. Also, if you refresh the data but DO NOT display the data, is there still a delay for the page to load? (This will help determine if the delay is in the building of the HTML for display or the return of the data from SQL.)
Excellent question. Unfortunately, we cannot recreate this speed problem in our test environment, and we dont have any way to run the query and have the page not show the data in production. However, I think the key difference is in what happens in the pages:
Process if there is a database pull (8 seconds to complete):
1. Call the stored procedure and store results in a DataTable
2. Save the DataTable into the Cache object
3. Use the DataTable to generate the HTML and display the page
Process if there is no database pull (less than 1 second to complete):
1. Get the DataTable from the Cache object
2. Use the DataTable to generate the HTML and display the page
In both cases, the exact same amount of HTML is being written with the exact same data, but with wildly different execution times. Therefore, I think that narrows down the problem to somewhere in steps 1 or 2 in the first scenario.
Thanks.
I am tending to agree with your assumption but I wanted to try to eliminate the things we can easily eliminate first.
Is there any sorting/filtering going on outside of the stored procedure?
Is there anyway to skip step 2 in the process and see if there is still a delay?
My feeling is that the delay is coming from the creation of the cache object. If that is the case, you may want to move step 2 to step 3 so that you store the datatable into the cache object after you've displayed the datatable.
Is there any sorting/filtering going on outside of the stored procedure?
Is there anyway to skip step 2 in the process and see if there is still a delay?
My feeling is that the delay is coming from the creation of the cache object. If that is the case, you may want to move step 2 to step 3 so that you store the datatable into the cache object after you've displayed the datatable.
ASKER
Thanks for the reply.
There is filtering going on, but, as with the other stuff, that happens both under the DB-pull and the cached scenarios, so it doesnt account for the speed difference between the two.
Thats an interesting idea that saving it into the cache could be the time-sucker. Im going to need a few days to try and test this in development, and if that fails, try to deploy another project into production to try it out. Ill get back to you as soon as I know something.
There is filtering going on, but, as with the other stuff, that happens both under the DB-pull and the cached scenarios, so it doesnt account for the speed difference between the two.
Thats an interesting idea that saving it into the cache could be the time-sucker. Im going to need a few days to try and test this in development, and if that fails, try to deploy another project into production to try it out. Ill get back to you as soon as I know something.
Let me know - this is an interesting issue.
ASKER
So this morning I was working on trying to test your idea about the cache being the slow point. At least in my tests in development using Trace.Write() statements, it looks like the vast majority of the time is spent on the DB portion. It took 0.446090 seconds to do the database call (including putting the data in a DataTable), but only .000084 to store it in the cache. Of course, I cant recreate the overall timing problem in my dev environment, so maybe those results are misleading.
Surprisingly though, I logged into our production site this morning under one of the users with the large data pull, and the page popped up within a second or two even though it did a database pull. I tried it several other times with other user accounts, and it was equally as fast.
So, I went back in the logs to examine the response times throughout the day and while they were high to start the day, they dramatically dropped down to the levels that I saw this morning. I plotted those response times, on an hourly basis against the overall page hits on the site, presuming that higher traffic caused slower response times. From the graph, there appears to be no relationship whatsoever. How strange.
OK, so heres a recap of what we know:
1. Under the "right" circumstances, the existing code can deliver acceptable performance.
2. Poor performance does not seem to be correlated with overall site traffic.
3. Even when poor performance occurs, the stored procedure runs quickly from SQL Server Management Studio, but when called from ASP.net, SQL Servers CPU utilization jumps much higher and it takes longer to respond.
Given that, it makes me wonder:
1. Could the number of DB connections in the connection pool to SQL server be the issue?
2. If there is some throughput or memory limitation holding back asp.net?
3. If there is a memory limitation on asp.net, then is adding or dropping items from the cache taxing the system?
Im no expert at using the performance monitor to do logging, but it seems picking some key metrics and recording them over a few days could help diagnose this. Do you have any suggestions on what to monitor and with what sample frequency?
Thanks.
Surprisingly though, I logged into our production site this morning under one of the users with the large data pull, and the page popped up within a second or two even though it did a database pull. I tried it several other times with other user accounts, and it was equally as fast.
So, I went back in the logs to examine the response times throughout the day and while they were high to start the day, they dramatically dropped down to the levels that I saw this morning. I plotted those response times, on an hourly basis against the overall page hits on the site, presuming that higher traffic caused slower response times. From the graph, there appears to be no relationship whatsoever. How strange.
OK, so heres a recap of what we know:
1. Under the "right" circumstances, the existing code can deliver acceptable performance.
2. Poor performance does not seem to be correlated with overall site traffic.
3. Even when poor performance occurs, the stored procedure runs quickly from SQL Server Management Studio, but when called from ASP.net, SQL Servers CPU utilization jumps much higher and it takes longer to respond.
Given that, it makes me wonder:
1. Could the number of DB connections in the connection pool to SQL server be the issue?
2. If there is some throughput or memory limitation holding back asp.net?
3. If there is a memory limitation on asp.net, then is adding or dropping items from the cache taxing the system?
Im no expert at using the performance monitor to do logging, but it seems picking some key metrics and recording them over a few days could help diagnose this. Do you have any suggestions on what to monitor and with what sample frequency?
Thanks.
SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
ASKER
I checked the event log and there were no entries of the worker processes restarting. I also believe that a worker process restart causes a new header line to be inserted into the IIS logs, and I didn't see that happen either.
While the response times were worse in the morning, they were consistently worse (not just once after a recompile), so given the repetition and lack of event log entries, I think we can rule out the worker process issue. Good thought, though. We've had that cause other problems for us back when we were in a shared hosting environment.
I pulled logs from another day that phas erformance issues and there was never a substantial drop in speed at any point in the day, so we're lacking a predictable pattern.
At this point, since we're an app mainly used during the business week and it's a Friday afternoon, I'm going to have to table the real-time analysis to next week. I've set up a variety of metrics that will be logged by the Performance Monitor throughout the day on Monday. Come Tuesday, hopefully I will have some more insight as to what is choking.
I'll keep you posted. Thanks.
While the response times were worse in the morning, they were consistently worse (not just once after a recompile), so given the repetition and lack of event log entries, I think we can rule out the worker process issue. Good thought, though. We've had that cause other problems for us back when we were in a shared hosting environment.
I pulled logs from another day that phas erformance issues and there was never a substantial drop in speed at any point in the day, so we're lacking a predictable pattern.
At this point, since we're an app mainly used during the business week and it's a Friday afternoon, I'm going to have to table the real-time analysis to next week. I've set up a variety of metrics that will be logged by the Performance Monitor throughout the day on Monday. Come Tuesday, hopefully I will have some more insight as to what is choking.
I'll keep you posted. Thanks.
ASKER
Ran the logs yesterday, but the slowdown wasn't happening at all. I'll take another sample next week and hopefully we'll get some useful data then. I'll let you know. Have a great Thanksgiving.
You too!
ASKER
Sorry for the delay, but examining the performance logs didn't reveal any issues (other than the high SQL Server CPU processing rates when the big query runs from the site, but not from SQL Management Studio). So, we created a test application where we could use Trace.Write() commands to see how long each line of code took to run.
I've attached a snippet below of what we tested.
Finding #1
What we found is that it took about 4.5 seconds to run the cmd.ExecuteReader() line when calling the procedure returning 568 rows. The puzzling thing is that if we run that exact same query from SQL Management Studio, it only takes about 540ms to execute (measured using the "Wait on server replies" line when displaying client statistics). Somehow we're losing about 4 seconds because the call is coming from ASP.net.
Measurement issue?
If I run the same scenario, but changing some of the WHERE clause values in the procedure so it only returns 9 rows (such in the case for another user), the procedure takes 340ms in SQL Management studio. However, the cmd.ExecuteReader() row takes .15 seconds to run. In this case. I mention this because those numbers don't seem possible. If it takes .34 seconds to run the procedure, it can't take only half that time to do the same thing, but calling from ASP.net. It makes me wonder if I'm somehow measuring this stuff wrong, but I can't figure out the flaw in my logic.
Finding #2
The other big finding is that it takes about 2.7 seconds to run the dt.Load(reader) line. I thought this is because of the processing time that it takes to put the 568 rows returned from the procedure into the DataTable. However, I ran the same code, but with a different, simpler query that also returned 568 rows (but had the same number of columns). In that test, it only took .012 seconds to load!
I have no idea why the exact same amount of data would take different times to load. Sure, the second query was much simpler (it had no joins in it), but my thought is that the penalty for a complex query should happen when you call cmd.ExecuteReader(), NOT when you're actually just pulling those results to put them in the table.
The tests also showed that saving the DataTable into the cache, once we had it, barely took any time at all. So, we've narrowed the culprit down to these two lines. I just have no idea how to account for the time problem.
Any thoughts? Thanks.
I've attached a snippet below of what we tested.
Finding #1
What we found is that it took about 4.5 seconds to run the cmd.ExecuteReader() line when calling the procedure returning 568 rows. The puzzling thing is that if we run that exact same query from SQL Management Studio, it only takes about 540ms to execute (measured using the "Wait on server replies" line when displaying client statistics). Somehow we're losing about 4 seconds because the call is coming from ASP.net.
Measurement issue?
If I run the same scenario, but changing some of the WHERE clause values in the procedure so it only returns 9 rows (such in the case for another user), the procedure takes 340ms in SQL Management studio. However, the cmd.ExecuteReader() row takes .15 seconds to run. In this case. I mention this because those numbers don't seem possible. If it takes .34 seconds to run the procedure, it can't take only half that time to do the same thing, but calling from ASP.net. It makes me wonder if I'm somehow measuring this stuff wrong, but I can't figure out the flaw in my logic.
Finding #2
The other big finding is that it takes about 2.7 seconds to run the dt.Load(reader) line. I thought this is because of the processing time that it takes to put the 568 rows returned from the procedure into the DataTable. However, I ran the same code, but with a different, simpler query that also returned 568 rows (but had the same number of columns). In that test, it only took .012 seconds to load!
I have no idea why the exact same amount of data would take different times to load. Sure, the second query was much simpler (it had no joins in it), but my thought is that the penalty for a complex query should happen when you call cmd.ExecuteReader(), NOT when you're actually just pulling those results to put them in the table.
The tests also showed that saving the DataTable into the cache, once we had it, barely took any time at all. So, we've narrowed the culprit down to these two lines. I just have no idea how to account for the time problem.
Any thoughts? Thanks.
Trace.Write("Open DB Connection");
conn.Open();
SqlCommand cmd;
cmd = new SqlCommand("TestQuery", conn);
cmd.CommandTimeout = 60;
cmd.CommandType = CommandType.StoredProcedure;
Trace.Write("Before execute");
SqlDataReader reader = cmd.ExecuteReader();
Trace.Write("Before creating table");
DataTable dt = new DataTable("Table");
Trace.Write("Before loading into table");
dt.Load(reader);
Trace.Write("Before closing reader");
reader.Close();
Trace.Write("Before inserting cache");
Cache.Insert("CacheTest", dt, null, DateTime.Now.AddMinutes(3), TimeSpan.Zero);
Trace.Write("After inserting cache");
ASKER CERTIFIED SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
1. Is the data retrieved via a stored procedure or with embedded sql in the .net application?
2. What is the record size of the table/tables that the data is being drawn from?
3. Are you displaying all 500 records at once when displayed?
4. Also, if you refresh the data but DO NOT display the data, is there still a delay for the page to load? (This will help determine if the delay is in the building of the HTML for display or the return of the data from SQL.)