Thursday, March 22, 2012

Data retrieval is much slower in RS than in management studio

A call to a stored procedure completes in 13 seconds when ran from within SQL Server Management Studio. A report whose data source uses the same stored procedure can take as long as 10 minutes to run. The same parameter values are used in both the direct call and the report. The execution log says almost all of that time is spent on data retrieval. How could that be? What might be the cause?If you didn't already, try profiling your sql instance right before you run your report. Have tsql statements shown so you can see a better breakdown of each command executing. This might show that the parameters used for the report are actually different than what you're expecting.|||I'll give it a try. However, looking at the Parameters column from the ExecutionLog table confirms that the values are the same. The report has the same parameters as the stored proc and simply passes the its parameter values along to the stored proc.|||

I set up a trace, launced the report and ran the SP from with SQL MS, then stopped the trace when the report came back. Instead of requesting a whole year's worth of data (which can take over 10 minute), I used a month. It takes about 15 times longer to run the report via RS than it does from within SQL MS.

When ran via RS, there are over 50x the number of reads.

From trace log:
This is the query ran from within MS:
exec SalesByDivision
@.beginDate='2006-12-31 00:00:00:000',
@.endDate='2007-02-03 00:00:00:000',
@.lyBeginDate='2006-01-01 00:00:00:000',
@.lyEndDate='2006-01-28 00:00:00:000',
@.storesListName=N'Comp stores',
@.departmentsListName=N'Owned merchandise',
@.storesCustomList=N'',
@.departmentsCustomList=N'',
@.delimiter=N',',
@.doNotRestate53WeekYear=N'0'
There were 10975 reads, 0 writes, and it took 1001 milliseconds

This is the query ran by the report server:
exec SalesByDivision
@.beginDate=''2006-12-31 00:00:00:000'',
@.endDate=''2007-02-03 00:00:00:000'',
@.lyBeginDate=''2006-01-01 00:00:00:000'',
@.lyEndDate=''2006-01-28 00:00:00:000'',
@.storesListName=N'Comp stores',
@.departmentsListName=N'Owned merchandise',
@.storesCustomList=N'',
@.departmentsCustomList=N'',
@.delimiter=N',',
@.doNotRestate53WeekYear=N'0'
There were 601409 reads, 0 writes, and it took 15326 milliseconds

|||

Did you try to just copy the exact text from the profiler? (to ensure that typo's and oversights aren't an issue)

Also, is the amount of system resources available possibly an issue?
Meaning, when running with just SQL MS, you are just using sql, but when you introduce RS, that's another program eating resources as well.

|||I notice you're not specifying a schema in your call to the stored procedure; do you have multiple versions of the SalesByDivision proc? If so, it might be defaulting to the one you want when you're connected in SQL Management Studio and an older or incorrect version when run under the context of the reporting services report. If not, I would trace the individual SQL statements as already mentioned and look for the statement(s) with highest reads to tune.|||

Thanks for the questions.

Yes, I copied the SQL from profiler then ran that in SQL MS.

These results are from a new production box. The system is consistently under load. Most reports that users are running are for very small date ranges and return within an acceptable time. However, reports with longer date ranges (the ones that managers and execs often run) are noticeby slower. Whether I run the SP from SQL MS or if I run a report, I assume the same resources are being used by RS.

|||There is only one version of the stored proc. For kicks I tried updating a report to include dbo. in front of the SP name. There was no noticable difference in load time.|||but add in t-sql commands to your trace. Do you know how to do this?|||

WITH RECOMPILE

Another one of our developers found a forum where someone had posted the same issue. Their suggestion was to add WITH RECOMPILE to our stored proc. After doing this we have experienced dramatic increases in performance with no unexplained slow periods. Also, before we added WITH RECOMPILE, the processing would occasionally be unevenly distributed between the eight CPUs on the SQL Server. One of the eight would get pegged while the otheres were not. After making the change we have seen an even distribution among all CPUs. Now it's taking the same amount of time to retrieve the data from the report - around 13 seconds.

|||Thanks for getting back with the solution buckenn. This was really helpful.|||

This is FANTASTIC!!

I was experiencing the same problem - the stored proc would run quickly, however, the report would take up to 15 minutes - and there wasn't much data being returned - fewer than 30 rows and only 15 columns. After adding WITH RECOMPILE to the proc, now the report generates in 15 seconds.

No comments:

Post a Comment