July 13, 2008 at 10:37 pm
Hi,
I am trying to run the following to determine the cause of SP slow performance. On this occasion it took 17 seconds to run, while normally it should be around 3 seconds.
SET STATISTICS TIME ON
SET STATISTICS IO ON
DECLARE @start datetime, @stop datetime
SET @start = GETDATE()
EXEC spAvaya_GetCustomerDetails '0755731644','',''
SET @stop = GETDATE()
SELECT 'The execution took ' + CONVERT(varchar(10), DATEDIFF(ms, @start, @stop)) + ' ms to finish'
SET STATISTICS TIME OFF
SET STATISTICS IO OFF
I get the following output:
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 16895ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
Table '#tempEntity_________________________________________________________________________________________________________000200349F5E'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0.
Table 'Worktable'. Scan count 1, logical reads 0, physical reads 0, read-ahead reads 0.
SQL Server Execution Times:
CPU time = 16 ms, elapsed time = 32 ms.
Table '#525BFFE0'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0.
Table 'Application_Customer'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0.
Table 'Customer'. Scan count 3, logical reads 9, physical reads 2, read-ahead reads 0.
Table 'ApplicationEntity'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0.
Table '#tempEntity_________________________________________________________________________________________________________000200349F5E'. Scan count 1, logical reads 0, physical reads 0, read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 17 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 20 ms.
(22 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 20 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
IsValid,Aggrement_Number,Application_Number,Customer_Type,Customer_Status,Pending_Payment,Customer_contracts,FolderID,TradeUp
0,,,,,,NONE,,No
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
The execution took 16956 ms to finish
(1 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
Attached are the screenshots for part of the execution plan, trace and stats in QA.
There is a query taking 100% of the time, however in the trace tab it only shows 15ms duration for the query. I can't see any blocking during the execution. The CPU time for the query is misarable: only 16ms. I can figure out why it takes so long to run. Any ideas?
Thanks.
July 14, 2008 at 1:28 am
That's a compile time of 16 sec! That's a little extreme.
Do you have contention for your procedure cache? (Are you seeing blocking with a [compile] description)
If you check perfmon, what values are you seeing for compiles/sec and recompiles/sec (under the SQL Statistics object)
How much memory do you have on this server?
Could you possibly post the code of the stored proc?
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
July 14, 2008 at 1:53 am
GilaMonster (7/14/2008)
That's a compile time of 16 sec! That's a little extreme.Do you have contention for your procedure cache? (Are you seeing blocking with a [compile] description)
If you check perfmon, what values are you seeing for compiles/sec and recompiles/sec (under the SQL Statistics object)
How much memory do you have on this server?
Could you possibly post the code of the stored proc?
1. Haven't seen much blocking related to compilation
2. At this time of the day (6pm - still business time) 3-5 compiles/sec average, no recompiles
3. 6GB
4. It calls another SP, which contains the heavy query:
BTW, how did you tell that it was compile time of 16 seconds?
CREATE Proc [dbo].[spAvaya_GetApplicationIDByCLI]
(
@Cli Varchar(10),
@CustomerContracts varchar (10) output ,
@ApplicationNumber varchar(10) output,
@ISBoth int output
)
AS
DECLARE @Row int
DECLARE @index int
DECLARE @ApplicationID varchar(10)
DECLARE @CustomerStatus varchar(10)
DECLARE @tmpStatus varchar (10)
DECLARE @isFirstTime bit
SET NOCOUNT ON
Declare @tmpAppID table (ApplicationID varchar(10),Rid int IDENTITY(1,1))
Create table #tempEntity (EntityID bigint)
Declare @strSQL nvarchar(4000)
SET @strSQL = N'(SELECT entityid
FROM FCM15.dbo.telecommunication with (nolock)
WHERE contactType in (21,23,24)
AND Replace(number,' + '''' + ' ' + '''' + ',' + '''' + '''' + ') = @CliIn)'
INSERT INTO #tempEntity (EntityID)
EXEC FCM.FCM15.dbo.sp_executesql @stmt = @strSQL,
@parms = N'@CliIn nvarchar(128)',
@CliIn = @Cli
INSERT INTO @tmpAppID
SELECT ApplicationID
FROM FlexirentApplication..ApplicationEntity fa
Inner join #tempEntity t ON fa.entityID = t.entityID
UNION
SELECT ApplicationID
FROM FlexirentApplication..application_customer ac
Inner join FlexirentApplication..customer fac
ON ac.customerID = fac.customerID
WHERE fac.cuContactHome =@Cli
OR fac.cuContactWork = @Cli
OR fac.cuContactMobile = @Cli
SET @Row = @@ROWCOUNT
SET @ISBoth = 0
IF @Row > 1
BEGIN
SET @CustomerContracts = 'MULTIPLE'
BEGIN
--For each application get status
SET @index = (select min(RID) from @tmpAppID)
SET @isFirstTime = 1
WHILE @index IS not null
BEGIN
SELECT @ApplicationID = ApplicationID
FROM @tmpAppID
WHERE Rid = @index
EXEC dbo.spAvaya_CustomerStatus @ApplicationID,@CustomerStatus output
IF(@tmpStatus <> @CustomerStatus AND @isFirstTime = 0)
BEGIN
SET @ISBoth = 1
BREAK
END
ELSE
BEGIN
SET @tmpStatus = @CustomerStatus
SET @isFirstTime = 0
IF @tmpStatus = 'EXISTING'
BEGIN
SET @ISBoth = 2
END
END
SET @index = (select min(RID) from @tmpAppID where RID > @index)
END
END
END
ELSE IF @Row = 1
BEGIN
--Select ApplicationID from @tmpAppID
SET @CustomerContracts = 'SINGLE'
SET @ApplicationNumber = (Select ApplicationID from @tmpAppID)
END
ELSE
SET @CustomerContracts = 'NONE'
SET NOCOUNT OFF
GO
July 14, 2008 at 3:31 am
Hmmm....
Has the slow execution reoccured? Is it happening regularly?
As more general comments:
Why are you using dynamic SQL in one place? I can't see anything in there that would need dynamic SQL
You're doing row by row processing with a while loop. Not ideal. Is there any way to get the customer status without checking 1 row at a time?
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
July 14, 2008 at 6:23 am
GilaMonster (7/14/2008)
Hmmm....Has the slow execution reoccured? Is it happening regularly?
As more general comments:
Why are you using dynamic SQL in one place? I can't see anything in there that would need dynamic SQL
You're doing row by row processing with a while loop. Not ideal. Is there any way to get the customer status without checking 1 row at a time?
No this is pretty random. At times it may take 2-3 seconds, but sometimes runs for up to 26 seconds. I have to make it run under 8 seconds stable.
As for the dynamic SQL, this is not my code, and the style is not a concern. According to the query plan (image attached) this is the killer:
INSERT INTO @tmpAppID
SELECT ApplicationID
FROM FlexirentApplication..ApplicationEntity fa
Inner join #tempEntity t ON fa.entityID = t.entityID
UNION
SELECT ApplicationID
FROM FlexirentApplication..application_customer ac
Inner join FlexirentApplication..customer fac
ON ac.customerID = fac.customerID
WHERE fac.cuContactHome =@Cli
OR fac.cuContactWork = @Cli
OR fac.cuContactMobile = @Cli
Why would this take 16 seconds to compile?
July 14, 2008 at 7:02 am
Off hand, I don't know. I don't think it's 16 sec to compile. That's well over the maximum amount of time the optimiser would be allowed to work. Most likely it's a wait on inserting into the cache
I would suggest that you monitor the compiles/sec and recompiles/sec and see if there's a spike when the proc goes slow.
Also maybe profiler and watch the cache miss, cache hit, cache remove and cache insert events, see if you can see anything out of the ordinary when the proc goes slow.
Last time I saw this on 2000 it was because of a bottleneck on inserting into the cache.
how many users would be runing this concurrently?
As for the dynamic SQL, this is not my code, and the style is not a concern
I'm not concerned with the style.
I'm just saying that those constructs could be causing or aggrevating the problem. In SQL 2000, when a recompile happens, the entire stored proc has to recompile. SQL 2005 has statement level recompile, SQL 2000 does not.
I would guess that the statement in question is causing the recompile, because the statistics on the temporary table has changed and hence the old plan is no longer valid.
Aprox how many rows get inserted into the temp table? How many into the table variable?
Since this proc is unlikely to have a reusable plan (because of the temp table) try marking it WITH RECOMPILE and see if things improve. No promices, it's just an ides.
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
July 15, 2008 at 12:26 am
GilaMonster (7/14/2008)
Off hand, I don't know. I don't think it's 16 sec to compile. That's well over the maximum amount of time the optimiser would be allowed to work. Most likely it's a wait on inserting into the cacheI would suggest that you monitor the compiles/sec and recompiles/sec and see if there's a spike when the proc goes slow.
Also maybe profiler and watch the cache miss, cache hit, cache remove and cache insert events, see if you can see anything out of the ordinary when the proc goes slow.
Last time I saw this on 2000 it was because of a bottleneck on inserting into the cache.
how many users would be runing this concurrently?
As for the dynamic SQL, this is not my code, and the style is not a concern
I'm not concerned with the style.
I'm just saying that those constructs could be causing or aggrevating the problem. In SQL 2000, when a recompile happens, the entire stored proc has to recompile. SQL 2005 has statement level recompile, SQL 2000 does not.
I would guess that the statement in question is causing the recompile, because the statistics on the temporary table has changed and hence the old plan is no longer valid.
Aprox how many rows get inserted into the temp table? How many into the table variable?
Since this proc is unlikely to have a reusable plan (because of the temp table) try marking it WITH RECOMPILE and see if things improve. No promices, it's just an ides.
If it is waiting for the cache, what could be a solution? If I put some more memory into the server, this will not necessary help the procedure cache, as it is allocated automatically and does not allow to reserve a certain amount for procedure cache only.
There are a lot of compiles and some recompiles spikes on the server from time to time. Cache hit ration is between 55-65%. Plenty of cache miss events all the time. The number of times the SP may be executed could be around 1000-2000 per day with some spikes and quite periods.
The number of rows inserted into both the temp table and table variable is under 10.
I will try using "with recompile" option, but it looks like without re-writing the entire SP there is no other solution. 🙁
July 15, 2008 at 12:50 am
I've tried running the SP using "with recompile" option and still got few instances of the execution taking longer than 8 seconds. 🙁
July 15, 2008 at 11:24 am
I see there is table scan operator in execution plan. Investigate for which table its doing table scan and why. Is that table missing the required index or is it a table with no index defined on it.
Manu
July 15, 2008 at 7:40 pm
Your cache hit ratio is pretty low. It should be above 90% at most of the time (mine is around 99% all times with 3 GB memory only). Your memory of 6 GB is large enough (depending on your database size). You should check the memory setting of your server, i.e. whether it is dynamically or manually allocated. Make sure that it is large enough. Well, it is true that the SQL Server will manage its own memory portion of the procedure cache, but you can always increase this size by increasing the global memory used by the Sql Server. Try to use more parameterized queries whenever possible and stored procedures to avoid recompiles. Hope that this will help.
Ivan Budiono
Ivan Budiono
July 15, 2008 at 8:10 pm
MANU (7/15/2008)
I see there is table scan operator in execution plan. Investigate for which table its doing table scan and why. Is that table missing the required index or is it a table with no index defined on it.Manu
It is a tiny temp table under 10 records.
July 15, 2008 at 8:21 pm
i6004835 (7/15/2008)
Your cache hit ratio is pretty low. It should be above 90% at most of the time (mine is around 99% all times with 3 GB memory only). Your memory of 6 GB is large enough (depending on your database size). You should check the memory setting of your server, i.e. whether it is dynamically or manually allocated. Make sure that it is large enough. Well, it is true that the SQL Server will manage its own memory portion of the procedure cache, but you can always increase this size by increasing the global memory used by the Sql Server. Try to use more parameterized queries whenever possible and stored procedures to avoid recompiles. Hope that this will help.Ivan Budiono
Are you talking about "Buffer cache hit ratio" or just "cache ratio"?
It is static set to use 5GB for SQL Server.
In fact I found that the plan for the SP was not showing correctly. For some reason it shows the plan of the last executed query saying this takes 100% of the entire SP execution time. It does not show any other query plans unless they are separated by "GO". The plan for the last query is pretty good and the only table scan is happening for a tiny temp table. I was trying to run other parts of the SP separately and found that this was the dynamic SQL query which was causing the problem:
SET @strSQL = N'(SELECT entityid
FROM FCM15.dbo.telecommunication with (nolock)
WHERE contactType in (21,23,24)
AND Replace(number,' + '''' + ' ' + '''' + ',' + '''' + '''' + ') = @CliIn)'
INSERT INTO #tempEntity (EntityID)
EXEC FCM.FCM15.dbo.sp_executesql @stmt = @strSQL,
@parms = N'@CliIn nvarchar(128)',
@CliIn = @Cli
I removed the "Replace" function from it changing it to "number in (precalculated vaules)" and it improved a lot.
Viewing 12 posts - 1 through 11 (of 11 total)
You must be logged in to reply to this topic. Login to reply