Tell me more ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.
up vote 12 down vote favorite
2

Thought this was solved with the link below - the work around works - but the patch doesn't. Working with Microsoft support to resolve.

http://support.microsoft.com/kb/2606883

Ok so I have an issue that I wanted to throw out to StackOverflow to see if someone has an idea.

Note this is with SQL Server 2008 R2

Issue: Deleting 3000 records from a table with 15000 records takes 3-4 minutes when a trigger is enabled and only 3-5 seconds when the trigger is disabled.

Table setup

Two tables we will call Main and Secondary. Secondary contains records of items I want to delete so when I perform the delete I join on to the Secondary table. A process runs prior to the delete statement to populate the secondary table with records to be deleted.

Delete Statement:

DELETE FROM MAIN 
WHERE ID IN (
   SELECT Secondary.ValueInt1 
   FROM Secondary 
   WHERE SECONDARY.GUID = '9FFD2C8DD3864EA7B78DA22B2ED572D7'
);

This table has a lot of columns and about 14 different NC Indexes. I tried a bunch of different things before I determined the trigger was the issue.

  • Turn on page locking (we have turned off by default)
  • Gathered Stats Manually
  • Disabled auto gathering of statistics
  • Verified Index health and fragmentation
  • Dropped the clustered index from the table
  • Examined the execution plan (nothing showing as missing indexes and the cost was 70 percent towards the actual delete with about 28 percent for the join / merge of the records

Triggers

The table has 3 triggers (one each for insert, update, and delete operations). I modified the code for the delete trigger to just return, then to select one to see how many times it is fired. It only fires one time during the entire operation (as expected). 

ALTER TRIGGER [dbo].[TR_MAIN_RD] ON [dbo].[MAIN]
            AFTER DELETE
            AS  
                SELECT 1
                RETURN

To Recap

  • With Trigger on - statement takes 3-4 minutes to complete
  • With Trigger off - statement takes 3-5 seconds to complete

Anyone have any ideas as to why?

Also note - not looking to change this architecture, add remove indexes, etc. as a solution. This table is the center piece for some major data operations and we had to tweak and tune it (indexes, page locking, etc) to allow for major concurrency operations to work without deadlocks.

Here is the execution plan xml (names were changed to protect the innocent)

<?xml version="1.0" encoding="utf-16"?>
<ShowPlanXML xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" Version="1.1" Build="10.50.1790.0" xmlns="http://schemas.microsoft.com/sqlserver/2004/07/showplan">
  <BatchSequence>
    <Batch>
      <Statements>
        <StmtSimple StatementCompId="1" StatementEstRows="185.624" StatementId="1" StatementOptmLevel="FULL" StatementOptmEarlyAbortReason="GoodEnoughPlanFound" StatementSubTreeCost="0.42706" StatementText="DELETE FROM MAIN WHERE ID IN (SELECT Secondary.ValueInt1 FROM Secondary WHERE Secondary.SetTMGUID = '9DDD2C8DD3864EA7B78DA22B2ED572D7')" StatementType="DELETE" QueryHash="0xAEA68D887C4092A1" QueryPlanHash="0x78164F2EEF16B857">
          <StatementSetOptions ANSI_NULLS="true" ANSI_PADDING="true" ANSI_WARNINGS="true" ARITHABORT="false" CONCAT_NULL_YIELDS_NULL="true" NUMERIC_ROUNDABORT="false" QUOTED_IDENTIFIER="true" />
          <QueryPlan CachedPlanSize="48" CompileTime="20" CompileCPU="20" CompileMemory="520">
            <RelOp AvgRowSize="9" EstimateCPU="0.00259874" EstimateIO="0.296614" EstimateRebinds="0" EstimateRewinds="0" EstimateRows="185.624" LogicalOp="Delete" NodeId="0" Parallel="false" PhysicalOp="Clustered Index Delete" EstimatedTotalSubtreeCost="0.42706">
              <OutputList />
              <Update WithUnorderedPrefetch="true" DMLRequestSort="false">
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_02]" IndexKind="Clustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[PK_MAIN_ID]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[UK_MAIN_01]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_03]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_04]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_05]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_06]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_07]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_08]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_09]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_10]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_11]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[UK_MAIN_12]" IndexKind="NonClustered" />
                <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[IX_MAIN_13]" IndexKind="NonClustered" />
                <RelOp AvgRowSize="15" EstimateCPU="1.85624E-05" EstimateIO="0" EstimateRebinds="0" EstimateRewinds="0" EstimateRows="185.624" LogicalOp="Top" NodeId="2" Parallel="false" PhysicalOp="Top" EstimatedTotalSubtreeCost="0.127848">
                  <OutputList>
                    <ColumnReference Column="Uniq1002" />
                    <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="RelationshipID" />
                  </OutputList>
                  <Top RowCount="true" IsPercent="false" WithTies="false">
                    <TopExpression>
                      <ScalarOperator ScalarString="(0)">
                        <Const ConstValue="(0)" />
                      </ScalarOperator>
                    </TopExpression>
                    <RelOp AvgRowSize="15" EstimateCPU="0.0458347" EstimateIO="0" EstimateRebinds="0" EstimateRewinds="0" EstimateRows="185.624" LogicalOp="Left Semi Join" NodeId="3" Parallel="false" PhysicalOp="Merge Join" EstimatedTotalSubtreeCost="0.12783">
                      <OutputList>
                        <ColumnReference Column="Uniq1002" />
                        <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="RelationshipID" />
                      </OutputList>
                      <Merge ManyToMany="false">
                        <InnerSideJoinColumns>
                          <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[Secondary]" Column="ValueInt1" />
                        </InnerSideJoinColumns>
                        <OuterSideJoinColumns>
                          <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="ID" />
                        </OuterSideJoinColumns>
                        <Residual>
                          <ScalarOperator ScalarString="[MyDatabase].[dbo].[MAIN].[ID]=[MyDatabase].[dbo].[Secondary].[ValueInt1]">
                            <Compare CompareOp="EQ">
                              <ScalarOperator>
                                <Identifier>
                                  <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="ID" />
                                </Identifier>
                              </ScalarOperator>
                              <ScalarOperator>
                                <Identifier>
                                  <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[Secondary]" Column="ValueInt1" />
                                </Identifier>
                              </ScalarOperator>
                            </Compare>
                          </ScalarOperator>
                        </Residual>
                        <RelOp AvgRowSize="19" EstimateCPU="0.0174567" EstimateIO="0.0305324" EstimateRebinds="0" EstimateRewinds="0" EstimateRows="15727" LogicalOp="Index Scan" NodeId="4" Parallel="false" PhysicalOp="Index Scan" EstimatedTotalSubtreeCost="0.0479891" TableCardinality="15727">
                          <OutputList>
                            <ColumnReference Column="Uniq1002" />
                            <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="ID" />
                            <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="RelationshipID" />
                          </OutputList>
                          <IndexScan Ordered="true" ScanDirection="FORWARD" ForcedIndex="false" ForceSeek="false" NoExpandHint="false">
                            <DefinedValues>
                              <DefinedValue>
                                <ColumnReference Column="Uniq1002" />
                              </DefinedValue>
                              <DefinedValue>
                                <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="ID" />
                              </DefinedValue>
                              <DefinedValue>
                                <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Column="RelationshipID" />
                              </DefinedValue>
                            </DefinedValues>
                            <Object Database="[MyDatabase]" Schema="[dbo]" Table="[MAIN]" Index="[PK_MAIN_ID]" IndexKind="NonClustered" />
                          </IndexScan>
                        </RelOp>
                        <RelOp AvgRowSize="11" EstimateCPU="0.00392288" EstimateIO="0.03008" EstimateRebinds="0" EstimateRewinds="0" EstimateRows="3423.53" LogicalOp="Index Seek" NodeId="5" Parallel="false" PhysicalOp="Index Seek" EstimatedTotalSubtreeCost="0.0340029" TableCardinality="171775">
                          <OutputList>
                            <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[Secondary]" Column="ValueInt1" />
                          </OutputList>
                          <IndexScan Ordered="true" ScanDirection="FORWARD" ForcedIndex="false" ForceSeek="false" NoExpandHint="false">
                            <DefinedValues>
                              <DefinedValue>
                                <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[Secondary]" Column="ValueInt1" />
                              </DefinedValue>
                            </DefinedValues>
                            <Object Database="[MyDatabase]" Schema="[dbo]" Table="[Secondary]" Index="[IX_Secondary_01]" IndexKind="NonClustered" />
                            <SeekPredicates>
                              <SeekPredicateNew>
                                <SeekKeys>
                                  <Prefix ScanType="EQ">
                                    <RangeColumns>
                                      <ColumnReference Database="[MyDatabase]" Schema="[dbo]" Table="[Secondary]" Column="SetTMGUID" />
                                    </RangeColumns>
                                    <RangeExpressions>
                                      <ScalarOperator ScalarString="'9DDD2C8DD3864EA7B78DA22B2ED572D7'">
                                        <Const ConstValue="'9DDD2C8DD3864EA7B78DA22B2ED572D7'" />
                                      </ScalarOperator>
                                    </RangeExpressions>
                                  </Prefix>
                                </SeekKeys>
                              </SeekPredicateNew>
                            </SeekPredicates>
                          </IndexScan>
                        </RelOp>
                      </Merge>
                    </RelOp>
                  </Top>
                </RelOp>
              </Update>
            </RelOp>
          </QueryPlan>
        </StmtSimple>
      </Statements>
    </Batch>
  </BatchSequence>
</ShowPlanXML>
share|improve this question
1  
what does the trigger do and how does it do it? – HLGEM Oct 13 '11 at 18:02
If you notice at the bottom of the post I changed the trigger to do nothing but select 1 and return. Same thing still occurs. – tsells Oct 13 '11 at 18:05
Capture the execution plan and post it if you can. – Thomas Stringer Oct 13 '11 at 18:25
I added the execution plan (XML) to the question. – tsells Oct 13 '11 at 18:33
@HLGEM - make sure that in this whole chain you are not doing something else on the backend when this trigger fires, like sending something through the dbmail system, etc. I have seen that cause delays. – Quantum Elf Oct 13 '11 at 19:02
show 8 more comments

migrated from stackoverflow.com Oct 25 '11 at 12:56

3 Answers

up vote 10 down vote

The row-versioning framework introduced in SQL Server 2005 is used to support a number of features, including the new transaction isolation levels READ_COMMITTED_SNAPSHOT and SNAPSHOT. Even when neither of these isolation levels are enabled, row-versioning is still used for AFTER triggers (to facilitate generation of the inserted and deleted pseudo-tables), MARS, and (in a separate version store) online indexing.

As documented, the engine may add a 14-byte postfix to each row of a table that is versioned for any of these purposes. This behaviour is relatively well-known, as is the addition of the 14-byte data to every row of an index that is rebuilt online with a row-versioning isolation level enabled. Even where the isolation levels are not enabled, one extra byte is added to non-clustered indexes only when rebuilt ONLINE.

Where an AFTER trigger is present, and versioning would otherwise add 14 bytes per row, an optimization exists within the engine to avoid this, but where a ROW_OVERFLOW or LOB allocation cannot occur. In practice, this means the maximum possible size of a row must be less than 8060 bytes. In calculating maximum possible row sizes, the engine assumes for example that a VARCHAR(460) column could contain 460 characters.

The behaviour is easiest to see with an AFTER UPDATE trigger, though the same principle applies to AFTER DELETE. The following script creates a table with a maximum in-row length of 8060 bytes. The data fits on a single page, with 13 bytes of free space on that page. A no-op trigger exists, so the page is split and versioning information added:

USE Sandpit;
GO
CREATE TABLE dbo.Example
(
    ID          integer NOT NULL IDENTITY(1,1),
    Value       integer NOT NULL,
    Padding1    char(42) NULL,
    Padding2    varchar(8000) NULL,

    CONSTRAINT PK_Example_ID
    PRIMARY KEY CLUSTERED (ID)
);
GO
WITH
    N1 AS (SELECT 1 AS n UNION ALL SELECT 1),
    N2 AS (SELECT L.n FROM N1 AS L CROSS JOIN N1 AS R),
    N3 AS (SELECT L.n FROM N2 AS L CROSS JOIN N2 AS R),
    N4 AS (SELECT L.n FROM N3 AS L CROSS JOIN N3 AS R)
INSERT TOP (137) dbo.Example
    (Value)
SELECT
    ROW_NUMBER() OVER (ORDER BY (SELECT 0))
FROM N4;
GO
ALTER INDEX PK_Example_ID 
ON dbo.Example 
REBUILD WITH (FILLFACTOR = 100);
GO
SELECT
    ddips.index_type_desc,
    ddips.alloc_unit_type_desc,
    ddips.index_level,
    ddips.page_count,
    ddips.record_count,
    ddips.max_record_size_in_bytes
FROM sys.dm_db_index_physical_stats(DB_ID(), OBJECT_ID(N'dbo.Example', N'U'), 1, 1, 'DETAILED') AS ddips
WHERE
    ddips.index_level = 0;
GO
CREATE TRIGGER ExampleTrigger
ON dbo.Example
AFTER DELETE, UPDATE
AS RETURN;
GO
UPDATE dbo.Example
SET Value = -Value
WHERE ID = 1;
GO
SELECT
    ddips.index_type_desc,
    ddips.alloc_unit_type_desc,
    ddips.index_level,
    ddips.page_count,
    ddips.record_count,
    ddips.max_record_size_in_bytes
FROM sys.dm_db_index_physical_stats(DB_ID(), OBJECT_ID(N'dbo.Example', N'U'), 1, 1, 'DETAILED') AS ddips
WHERE
    ddips.index_level = 0;
GO
DROP TABLE dbo.Example;

The script produces the output shown below. The single-page table is split into two pages, and the maximum physical row length has increased from 57 to 71 bytes (= +14 bytes for the row-versioning information).

Update example

DBCC PAGE shows that the single updated row has Record Attributes = NULL_BITMAP VERSIONING_INFO Record Size = 71, whereas all other rows in the table have Record Attributes = NULL_BITMAP; record Size = 57.

The same script, with the UPDATE replaced by a single row DELETE produces the output shown:

DELETE dbo.Example
WHERE ID = 1;

Delete example

There is one fewer row in total (of course!), but the maximum physical row size has not increased. Row versioning information is only added to rows needed for the trigger pseudo-tables, and that row was ultimately deleted. The page split remains, however. This page-splitting activity is responsible for the slow performance observed when the trigger was present. If the definition of the Padding2 column is changed from varchar(8000) to varchar(7999), the page no longer splits.

Also see this blog post by SQL Server MVP Dmitri Korotkevitch, which also discusses the impact on fragmentation.

share|improve this answer
1  
Ah, I asked a question about this on SO sometime ago and never got a definitive answer. – Martin Smith Jul 12 '12 at 7:17
@MartinSmith Aha! Yes this is the same issue. – Paul White Jul 12 '12 at 9:02
up vote 5 down vote accepted

Well here is the official response from Microsoft...which I think is a major design flaw.

11/14/2011 - Official response has changed. They are not using the transaction log as previously stated. The are using the internal store (row level) to copy the changed data into. They still can't determine why it's taken so long.

We decided to use Instead Of triggers in lieu of after delete triggers.

The AFTER part of the trigger causes us to have to read through the transaction log after the deletes complete and build the trigger inserted/deleted table. This is where we spend the vast amount of time and is by design for the AFTER part of the trigger. INSTEAD OF trigger would prevent this behavior of scanning the transaction log and building an inserted/deleted table. Also, as it was observed that things are much faster if we drop all columns with nvarchar(max), which makes sense due to the fact that it is considered LOB data. Please have alook at below article for more informaiton regarding In-Row data:

http://msdn.microsoft.com/en-us/library/ms189087.aspx

Summary: AFTER trigger requires scanning back through the transaction log after the delete finishes then we have to build and inserted/deleted table which requires more usage of the transaction log and time.

So as an action plan, this is what we suggest at this time:

A) Limit the number of rows deleted in each transaction or
B) Increase timeout settings or
C) Don't use AFTER trigger or trigger at all or
D) Limit usage of nvarchar(max) datatypes.
share|improve this answer
1  
Ah that's quite interesting. Not at all how I thought it worked. I thought they stopped scanning the log after SQL Server 2000 and that the deleted and inserted tables were populated directly in tempdb following the delete operator. – Martin Smith Nov 1 '11 at 15:07
1  
inserted and deleted are built from an internal version store in general, but LOB data could be 2GB per version, so that probably why pointers and log scanning is still used there. – Paul White Nov 3 '11 at 4:20
Well I just had another call with Microsoft and they are saying that they are not scanning the transaction logs. They are using the snapshot store. This still doesn't explain the slowness but we have a work around. – tsells Nov 14 '11 at 20:35
up vote 2 down vote

According to the plan everything is going correctly. You can try writing the delete as a JOIN instead of an IN which will give you a different plan.

DELETE m
FROM MAIN m
JOIN Secondary s ON m.ID = s.ValueInt1
AND s.SetTMGUID = '9DDD2C8DD3864EA7B78DA22B2ED572D7'

I'm not sure how much that will help however. When the delete is running with the triggers on the table what is the wait type for the session doing the delete?

share|improve this answer
2  
Denny - I have been working with MS support and they have determined for the most part it is an internal bug. Waiting on confirmation but it appears to be related to the NVCHAR(MAX) fields in the table. I am now awaiting the results of their investigation. – tsells Oct 27 '11 at 2:15

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.