Commit, select or update duration time vary from short to long

Hi
I have a statement that normally takes a short time but sometimes
takes long. I think I have isolated the problem to being variations in
the time it takes to commit.
I have constructed a setup that somehow show my problem.
First execute the following script (45 lines):
use pubs
/****** Object: Stored Procedure dbo.spTestCommit Script Date:
16-05-2005 08:20:27 ******/
if exists (select * from dbo.sysobjects where id = object_id(N'[dbo].
[spTestCommit]') and OBJECTPROPERTY(id, N'IsProcedure') = 1)
drop procedure [dbo].[spTestCommit]
GO
/****** Object: StoredProcedure [dbo].[spTestCommit] Script Date:
05/16/2007 08:32:43 ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE PROCEDURE [dbo].[spTestCommit]
@.deltaValue int,
@.titleId varchar(50)
AS
declare @.tranCount int
select @.tranCount = @.@.trancount
if (@.tranCount = 0) begin
tran spTran
else begin
save tran spTran
end
UPDATE titles
SET ytd_sales = ytd_sales + @.deltaValue
WHERE title_id = @.titleId
if (@.tranCount = 0)
begin
commit tran
end
return 0
errorHandler:
rollback tran spTran
return 1
GO
Then start a trace enabling Execution plan and execute the statement.
I use the following:
exec spTestCommit 1, 'BU1032'
exec spTestCommit -1, 'BU1032'
(This will decrease and then increase some int value in the
pubs..titles table for a specific record)
Now my point is that when I execute those 2 lines, then they have a
duration of 10 or 20 ms most of the time. But all of the sudden I see
an entry with a duration of 210 ms.
Why does it take so much longer when that is the only thing I execute
on that entire database?!?
The output from my trace for the 210 ms run is:
Execution PlanExecution Tree
Clustered Index Update(OBJECT[pubs].[dbo].[titles].
[UPKCL_titleidind]), SET[titles].[ytd_sales]=[Expr1004]), DEFINE:
([Expr1004]=[titles].[ytd_sales]+[@.deltaValue]), WHERE[titles].
[title_id]=[@.titleId]))
SQL Query AnalyzerusrPC\usr2756552007-05-16 13:11:23.553
Execution PlanExecution Tree
Clustered Index Update(OBJECT[pubs].[dbo].[titles].
[UPKCL_titleidind]), SET[titles].[ytd_sales]=[Expr1004]), DEFINE:
([Expr1004]=[titles].[ytd_sales]+[@.deltaValue]), WHERE[titles].
[title_id]=[@.titleId]))
SQL Query AnalyzerusrPC\usr2756552007-05-16 13:11:23.703
SQL:BatchCompletedexec spTestCommit 1, 'BU1032'
exec spTestCommit -1, 'BU1032'
SQL Query AnalyzerusrPC\usr01802102756552007-05-16
13:11:23.5532007-05-16 13:11:23.763
In my real world setup I have a stored procedure that normally takes
0-20 ms but have been seen taking 30000 ms or even more... I would
very much apreciate some hints as to why it vary so much...
Thanks
Resist
> Now my point is that when I execute those 2 lines, then they have a
> duration of 10 or 20 ms most of the time. But all of the sudden I see
> an entry with a duration of 210 ms.
> Why does it take so much longer when that is the only thing I execute
> on that entire database?!?
SQL Server must wait until the COMMIT log write is physically complete
before completing the statement. If a CHECKPOINT is writing lots of data
and data and log files are on the same physical disk, this can prolong the
COMMIT statement duration. This is one reason why it's a Best Practice to
place data and log on different disks. You can monitor checkpoints in
perfmon to see the correlation.

> In my real world setup I have a stored procedure that normally takes
> 0-20 ms but have been seen taking 30000 ms or even more... I would
> very much apreciate some hints as to why it vary so much...
30+ seconds is excessive and probably due to a different reason, assuming
your I/O subsystem is adequately sized for your workload. A more likely
cause is blocking. Run sp_who at the time of the problem to see if that's
the case. An occasional long-running query or transaction may be the
culprit.
Hope this helps.
Dan Guzman
SQL Server MVP
"resist" <dba@.godhund.dk> wrote in message
news:1179315894.009631.298820@.y80g2000hsf.googlegr oups.com...
> Hi
> I have a statement that normally takes a short time but sometimes
> takes long. I think I have isolated the problem to being variations in
> the time it takes to commit.
> I have constructed a setup that somehow show my problem.
> First execute the following script (45 lines):
> use pubs
> /****** Object: Stored Procedure dbo.spTestCommit Script Date:
> 16-05-2005 08:20:27 ******/
> if exists (select * from dbo.sysobjects where id = object_id(N'[dbo].
> [spTestCommit]') and OBJECTPROPERTY(id, N'IsProcedure') = 1)
> drop procedure [dbo].[spTestCommit]
> GO
> /****** Object: StoredProcedure [dbo].[spTestCommit] Script Date:
> 05/16/2007 08:32:43 ******/
> SET ANSI_NULLS ON
> GO
> SET QUOTED_IDENTIFIER ON
> GO
> CREATE PROCEDURE [dbo].[spTestCommit]
> @.deltaValue int,
> @.titleId varchar(50)
>
> AS
> declare @.tranCount int
> select @.tranCount = @.@.trancount
> if (@.tranCount = 0) begin
> tran spTran
> else begin
> save tran spTran
> end
> UPDATE titles
> SET ytd_sales = ytd_sales + @.deltaValue
> WHERE title_id = @.titleId
>
> if (@.tranCount = 0)
> begin
> commit tran
> end
> return 0
> errorHandler:
> rollback tran spTran
> return 1
> GO
>
>
> Then start a trace enabling Execution plan and execute the statement.
> I use the following:
> exec spTestCommit 1, 'BU1032'
> exec spTestCommit -1, 'BU1032'
> (This will decrease and then increase some int value in the
> pubs..titles table for a specific record)
>
> Now my point is that when I execute those 2 lines, then they have a
> duration of 10 or 20 ms most of the time. But all of the sudden I see
> an entry with a duration of 210 ms.
> Why does it take so much longer when that is the only thing I execute
> on that entire database?!?
> The output from my trace for the 210 ms run is:
> Execution Plan Execution Tree
> --
> Clustered Index Update(OBJECT[pubs].[dbo].[titles].
> [UPKCL_titleidind]), SET[titles].[ytd_sales]=[Expr1004]), DEFINE:
> ([Expr1004]=[titles].[ytd_sales]+[@.deltaValue]), WHERE[titles].
> [title_id]=[@.titleId]))
> SQL Query Analyzer usr PC\usr 2756 55 2007-05-16 13:11:23.553
> Execution Plan Execution Tree
> --
> Clustered Index Update(OBJECT[pubs].[dbo].[titles].
> [UPKCL_titleidind]), SET[titles].[ytd_sales]=[Expr1004]), DEFINE:
> ([Expr1004]=[titles].[ytd_sales]+[@.deltaValue]), WHERE[titles].
> [title_id]=[@.titleId]))
> SQL Query Analyzer usr PC\usr 2756 55 2007-05-16 13:11:23.703
> SQL:BatchCompleted exec spTestCommit 1, 'BU1032'
> exec spTestCommit -1, 'BU1032'
> SQL Query Analyzer usr PC\usr 0 18 0 210 2756 55 2007-05-16
> 13:11:23.553 2007-05-16 13:11:23.763
>
> In my real world setup I have a stored procedure that normally takes
> 0-20 ms but have been seen taking 30000 ms or even more... I would
> very much apreciate some hints as to why it vary so much...
> Thanks
> Resist
>