September 16, 2013 at 8:37 am
Hi,
I've a table that has a trigger for insert that executes the flowing statement:
UPDATE ArtigoArmazem SET QtReservada = 0 FROM INSERTED I INNER JOIN LInhasdoc LD ON i.IdLinhasDoc = LD.Id WHERE ArtigoArmazem.Artigo = LD.Artigo
The table ArtigoArmazem also has a trigger for update that initially had a cursor to update stocks quantities but I changed it to a "simple" UPDATE:
-- OLD TRIGGER
ALTER TRIGGER [dbo].[GCP_STK_ArtigoArmazem_UPD] ON [dbo].[ArtigoArmazem] FOR UPDATE
AS
SET NOCOUNT ON
DECLARE @Artigo AS VARCHAR(50)
DECLARE @StkActual AS FLOAT
IF UPDATE(StkActual)
BEGIN
DECLARE curRegistos CURSOR LOCAL FORWARD_ONLY STATIC READ_ONLY FOR
SELECT Artigo, StkActual FROM Deleted WHERE StkActual <> 0
OPEN curRegistos
FETCH NEXT FROM curRegistos INTO @Artigo, @StkActual
WHILE @@FETCH_STATUS = 0
BEGIN
EXEC GCP_STK_ActualizaArtigo 'R', @Artigo, @StkActual
FETCH NEXT FROM curRegistos INTO @Artigo, @StkActual
END
CLOSE curRegistos
DEALLOCATE curRegistos
DECLARE curRegistos CURSOR LOCAL FORWARD_ONLY STATIC READ_ONLY FOR
SELECT Artigo, StkActual FROM Inserted
OPEN curRegistos
FETCH NEXT FROM curRegistos INTO @Artigo, @StkActual
WHILE @@FETCH_STATUS = 0
BEGIN
EXEC GCP_STK_ActualizaArtigo 'I', @Artigo, @StkActual
FETCH NEXT FROM curRegistos INTO @Artigo, @StkActual
END
CLOSE curRegistos
DEALLOCATE curRegistos
END
GO
---- The SP GCP_STK_ActualizaArtigo just does an UPDATE on @Artigo and sets StkActual to StkActual + @StkActual if 'I' or StkActual - @StkActual id 'D'
----- NEW TRIGGER----
CREATE TRIGGER [dbo].[GCP_STK_ArtigoArmazem_UPD] ON [dbo].[ArtigoArmazem] FOR UPDATE
AS
BEGIN
SET NOCOUNT ON
IF UPDATE(StkActual)
BEGIN
;WITH res AS
(
SELECT Artigo, -StkActual AS StkActual FROM DELETED WHERE StkActual <> 0
UNION ALL
SELECT Artigo, StkActual FROM INSERTED
), res1 AS (
SELECT Artigo, SUM(StkActual) Stk FROM res GROUP BY Artigo
)
UPDATE Artigo SET STKActual = STKActual + res1.Stk FROM res1 WHERE MovStock = 'S' AND Artigo.Artigo = res1.artigo
END
END
When I run a trace to see what's happening I get with the OLD trigger a duration of half the new trigger and 900 reads vs 4900 reads with the new trigger!!!
If I insert a RETURN statement just at the beginning of the new trigger the results are the same but if I let the RETURN and remove the rest of the SQL the result is the same as the old trigger.
What can be causing this? The trigger's code shouldn't even be executed case UPDATE(stkActual) is false...
Thanks,
Pedro
September 17, 2013 at 5:19 am
Just another strange thing happening with the triggers on the database....
The GCP_VND_ActualizaDocumentoVenda_LinhasDocStatus procedure has an INSERT on a table that has a trigger.
I start a server trace on the SP to monitor what's going on the database and get this:
INSERT INTO [dbo].[LinhasDocStatus] ([IDLinhasDoc], [Quantidade], [QuantReserv], [QuantTrans], [EstadoTrans], [Fechado]) SELECT [ID], [QT], [QTR], [QTS], [ET], [FE] FROM [dbo].[#TmpLinhas] WHERE ([EBD] = 2 OR ([EBD] = 3 AND @bitDocNovo = 1))
This statement takes 248ms to execute...
The trigger code "fired" by the INSERT has an IF EXISTS with a SELECT and two UPDATE...
* IF with SELECT: 0,169ms
* UPDATE: 1,071ms
* UPDATE: 7,287ms
The SUM from the trigger time is way less than the time the INSERT says it takes to execute..
So I disabled the trigger to see how long would the INSERT execute just by itself.... 13,39ms!!!
So, math made, the INSERT 13,39ms + SUM(Trigger) 9ms gives 23ms... but the INSERT with the trigger takes 248ms.. 10x more...
Can anyone tell me how to figure what's going on the database?!
The scenarios are the same on both cases since I restore the database and do an index rebuild and statistics update every time and clear the cache and buffers...
Thanks,
Pedro
September 17, 2013 at 6:01 am
I ran SQL Profiler on the GCP_VND_ActualizaDocumentoVenda_LinhasDocStatus procedure with all the events and data checked...
I've a big table to analyse but I don't know what to search for... It even has the execution plans...
But still I noticed:
The SUM of Duration inside the trigger is 440 (EventClass 45 and 43 for the INSERT) and the Duration of the INSERT that fires the trigger is 1173 (EventClass 45).
?!?!
With the trigger disabled the GCP_VND_ActualizaDocumentoVenda_LinhasDocStatus procedure duration is 188, that is "close" the the 200 from the duration with the trigger enabled.
Thanks,
Pedro
September 17, 2013 at 4:05 pm
It's difficult to say exactly what is going on without access to the database, but there is an overhead of putting the rows for inserted and deleted to the version store. I would not expect it to as high as in your examples, though.
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
September 18, 2013 at 2:36 am
I have the full trace from profiler with events 12, 41, 43, 45, 122, 146 and 168....
But dont say much... or at least I dont know how to look at them... just the times...
Thanks,
Pedro
September 18, 2013 at 4:34 am
I realiased that my post was a little terse, so I should try to qualify it a bit.
Say that you have a trace which captures SP:StmtCompleted. Say that you inside a stored procedure call a longer stored procedure that is not in the cache. Most likely you will find that StartTime for StmtCompleted for the EXEC statement and the first statement in the procedure will be quite a few milliseconds apart. This time span represents the overhead to call the procedure. This includes time for passing parameters, setting up table variables and most of all to compile the procedure.
The same applies for a trigger, but for a trigger there is also the overhead for setting up the inserted/deleted tables. This overhead can be seen in a trace as well, as the difference between StartTime for the statement that fires the trigger and the StartTime for the first statement in the trigger. However, if the statement that fires the trigger takes time to execute in itself, the waters get quite muddled.
Now, there is one more thing to notice about your trace: you include the events Showplan XML, Showplan XML Statistics Profile and Showplan XML For Query Compile, and if you include these events things like durations are distorted considerably, because they incur a very significant overhead. If you remove these events, you will see completely different numbers for duration.
You should use trace for these events in production evironments, except for very short periods. Tracing for these events can badly degrade the overall performance for your system. Note that even if you filter for a specifc spid, all processes start generating information for this event, and this is very costly. Believe me. I've sanka customer system that way. Very embarrassing.
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
September 18, 2013 at 4:44 am
But my "biggest" problem is the issue on the first post...
I have a trigger with a cursor that calls a procedure and changed it to an update statement...
The one with the cursor has less reads, way less, than the update statement even having the condition to exit if the field hasn't changed...
They both should do the same, nothing, just the IF UPDATE(StkActual) and exit but the one with the UPDATE statement is taking longer...
Thanks,
Pedro
September 18, 2013 at 6:24 am
Do you make the same observations, even if you do not include the showplan events in the trace?
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
September 18, 2013 at 7:48 am
Erland Sommarskog (9/18/2013)
Do you make the same observations, even if you do not include the showplan events in the trace?
Yep. The data from the first post only had event 12 and 45 (profiler's default for tuning).
Pedro
September 18, 2013 at 3:31 pm
I don't really have any more ideas that I have offered previously (and in which I don't believe fully). Did you compare StartTime for the INSERT statement with the StartTime for the first statement in the trigger? Also, in the trace where are the reads listed?
Could you attach the trace where this is happening?
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
September 19, 2013 at 1:53 pm
Hi,
Sorry, just saw the message now (spent the day at a MS workshop).
Tomorrow when I arrive at the office I'll post the 2 trace data:
1. Current trigger (that uses a cursor and calls an SP)
2. Updated trigger (uses SQL directly).
I'll just catch events 12 and 45. Are there any more necessary (43, 168, ...)?
Thanks,
Pedro
September 19, 2013 at 3:41 pm
10 and 41 are good to include as well.
Since you are tracing a single statement (plus triggers), sp_sqltrace can be useful. It's available on my web site:
http://www.sommarskog.se/sqlutil/sqltrace.html
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
September 20, 2013 at 4:15 am
Hi,
Just added an Excel file with the full trace with the original trigger and the changed trigger (that should be faster, and in "simple" UPDATE tests to the table it is much, much faster).
I also added a 3rd sheet with a side by side comparison of the code I find strange...
The statement UPDATE AA SET QtReservada = 0 FROM Inserted I INNER ... executes inside a trigger and fires another trigger, I don't know if this might be the problem source (trigger inside triggers is badddd).
But the truth is that with the slow ArtigoArmazem trigger (the 1st on the SQL script attachment) it's much faster than the improved trigger (2,25ms vs 55,7ms).
So I made a test... I changed the new trigger and added a RETURN statement right at the top.... same result...
The I removed the rest of the trigger code, just left the RETURN... fast again....
Does SQL have an issue with the WITH statement or something??! I made a test and removed the WITH and replaced it with a subquery but still slow...
It's the same database, I just keep changing the trigger code and executing the traces so nothing to do with indexes, or whatever... Statistics are updated, indexes full rebuild...
What can be causing this issue with the triggers?!
Further on the trace the trigger is used again and the new one is faster with less reads, since it's used... In this case it's used but does nothing since the StkActual column isn't updated...
Thanks,
Pedro
September 20, 2013 at 3:35 pm
If you look closer the in the after-trigger trace, you will find that it is only the first invocation that takes a longer time. Furthermore, if you look close at the times, you will find this:
This statement fires the trigger:
UPDATE AA SET QtReservada = 0 FROM Inserted I INNER JOIN LinhasDoc LD ON LD.Id=I.IdLinhasDoc INNER JOIN ArtigoArmazem AA ON AA.Artigo=LD.Artigo --BID: 583194
It starts executing at 2013-09-20 10:44:00.187
The first command in the contested trigger is SET NOCOUNT ON, and this command starts executing at 2013-09-20 10:44:00.240. (You need to look at the SET NOCOUNT ON that are a few lines above, since you have xxx:Completed events.
This is typically what you see when a module is compiled. Since the new trigger includes a more complex query than the old trigger it takes longer time to compile, but if the plan stays in cache, this overhead can be neglected.
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
September 21, 2013 at 1:23 am
Erland Sommarskog (9/20/2013)This is typically what you see when a module is compiled. Since the new trigger includes a more complex query than the old trigger it takes longer time to compile, but if the plan stays in cache, this overhead can be neglected.
Thanks, I noticed that when I removed the DBCC commands the execution with the new trigger was faster, but for performance measures I always do the DBCC... Or should I just do the DBCC for the data cache (if there's just that one)?
Maybe just http://technet.microsoft.com/en-us/library/ms187762.aspx.
Thanks,
Pedro
Viewing 15 posts - 1 through 15 (of 18 total)
You must be logged in to reply to this topic. Login to reply