April 22, 2003 at 8:58 am
Yet another newcomer to the forum...here's my problem. I've been writing some code for an insert trigger and was getting variable execution times with the slow time being about ten times slower than the fast time. When I checked using the profiler I found that two different execution plans were being used. In each case the number of logical reads was similar but one was using a lot more CPU time. I assume that compared to the weighting given to disk reads the CPU time is considered to be minimal BUT the table was sitting almost totally in the cache so that mostly no physical disk reads occurred. Just to give SQL Server a chance I tried pinning the table explicitly but it still on occasions chose the slow execution plan. Is there any way to force the optimizer to take into account either the cache hit ratio for a table or be aware of tables being pinned or am I just going to have to pepper my SQL code with hints? It seems the optimizer is doing all the hard work with regards to choosing indices to use etc. but missing what seems on the face of it to be an 'easy' check. I already have got automatic statistics gathering set on but I'd be grateful to know if there's anything else I can do. Thanks in anticipation.
April 22, 2003 at 11:15 am
If you update the stats manually when you see the slowdown does the problem go away?
Andy
April 23, 2003 at 2:58 am
Thanks for response. The code was written into an insert trigger and subjected to repetitive soak testing (5-10 mins) for a range of initial record numbers (1000-100,000). At the start of each test session the tables were cleared out and the test data reloaded from scratch in theory giving each test the same start conditions. Each execution of the fast response averaged about 12mS while the slow response was about 120mS for 10,000 initial records. It was therefore not feasible to manually force statistics to be gathered during the testing. Because the trigger code was using the INSERTED table I could not directly examine its identical operation using the Query Analyzer, I did however create an alternative user table and used that instead of the INSERTED table with slightly modified code. In that case I did use UPDATE STATISTICS before the one shot executions and used SET STATISTICS IO ON, SET STATISTICS TIME ON and SET STATISTICS PROFILE ON to investigate what was happening. With this set up I still got variable execution plans and times. It may be of interest that during the soak testing which comprised continuous inserts from an external test application, the times were consistent i.e. if at the start of a soak test it chose the 'slow' execution plan then that was used for all subsequent inserts in that test session and vica versa.
Just to set this in context what I'm trying to do is use SQL Server as the store for acquired real time data which will be displayed at operator positions. As the data changes in tables that are being displayed I want to check the changed data (insert, delete or update) against the display applications SQL request (e.g. SELECT TOP <display lines> FROM <table names> WHERE <selection clauses> ORDER BY <order clause> ) and determine if the operation on the table would effect the result of that query.
April 23, 2003 at 4:36 am
Can you capture both execution plans in text form and post so we can see the differences. I use them myself a lot and have gotten used to reading them. Maybe someone here will see in them a why. Just need the plan text and the query if possible that is being run.
April 23, 2003 at 9:23 am
you can set showplan_text on and post that. I'd be intersted to see as well. Pls include table DDL, insert trigger, indexes.
Steve Jones
April 24, 2003 at 2:29 am
Sorry about delay responding but I had some difficulty getting the profiler execution plans...there's a lot of information here. Suggest copying the profiler data and viewing under notepad in courier font.
The following ctreated the tables for the tests...
IF exists (SELECT * FROM dbo.sysobjects WHERE id = object_id(N'[dbo].[rem_Test_table1]') AND OBJECTPROPERTY(id, N'IsUserTable') = 1)
DROP TABLE [dbo].[rem_Test_table1]
GO
CREATE TABLE [dbo].[rem_Test_table1] (
[ID] [uniqueidentifier] NOT NULL ,
[Search1] [int] NULL ,
[Search2] [int] NULL ,
[Order1] [int] NULL ,
[Order2] [int] NULL ,
[Shared1] [uniqueidentifier] NULL ,
[Display1] [varchar] (50) COLLATE SQL_Latin1_General_CP1_CI_AS NULL ,
[Display2] [varchar] (50) COLLATE SQL_Latin1_General_CP1_CI_AS NULL ,
[Display3] [int] NULL ,
[Not used] [int] NULL ,
[Test key] [int] IDENTITY (1, 1) NOT NULL
) ON [PRIMARY]
GO
ALTER TABLE [dbo].[rem_Test_table1] WITH NOCHECK ADD
CONSTRAINT [rem_Test_table1_constraint1] DEFAULT (newid()) FOR [ID],
CONSTRAINT [rem_Test_table1_constraint2] DEFAULT (0) FOR [Not used]
GO
CREATE INDEX [rem_Test_table11] ON [dbo].[rem_Test_table1]([Order1], [Order2]) ON [PRIMARY]
GO
CREATE UNIQUE INDEX [IX_rem_Test_table1] ON [dbo].[rem_Test_table1]([Test key]) ON [PRIMARY]
GO
CREATE UNIQUE INDEX [IX_rem_Test_table1_1] ON [dbo].[rem_Test_table1]([ID]) ON [PRIMARY]
GO
=================================================
IF exists (SELECT * FROM dbo.sysobjects WHERE id = object_id(N'[dbo].[rem_Test_table2]') AND OBJECTPROPERTY(id, N'IsUserTable') = 1)
DROP TABLE [dbo].[rem_Test_table2]
GO
CREATE TABLE [dbo].[rem_Test_table2] (
[ID] [uniqueidentifier] NOT NULL ,
[Search1] [int] NULL ,
[Order1] [int] NULL ,
[Display1] [varchar] (50) COLLATE SQL_Latin1_General_CP1_CI_AS NULL ,
[Display2] [int] NULL ,
[Not used] [int] NULL ,
[Test key] [int] IDENTITY (1, 1) NOT NULL
) ON [PRIMARY]
GO
ALTER TABLE [dbo].[rem_Test_table2] WITH NOCHECK ADD
CONSTRAINT [rem_Test_table2_constraint1] DEFAULT (newid()) FOR [ID],
CONSTRAINT [rem_Test_table2_constraint2] DEFAULT (0) FOR [Not used]
GO
CREATE UNIQUE INDEX [IX_rem_Test_table2] ON [dbo].[rem_Test_table2]([Test key]) ON [PRIMARY]
GO
=================================================
IF exists (SELECT * FROM dbo.sysobjects where id = object_id(N'[dbo].[rem_RandomTable]') AND OBJECTPROPERTY(id, N'IsUserTable') = 1)
DROP TABLE [dbo].[rem_RandomTable]
GO
CREATE TABLE [dbo].[rem_RandomTable] (
[Seed] [int] NOT NULL
) ON [PRIMARY]
GO
=================================================
This was the insert code used with ODBC based test application, obviously the "?"'s are placeholders for the actual inserted data which was generated in the program:
INSERT [rem_Test_table1] (Search1,Search2,Order1,Order2,Shared1,Display1,Display2,Display3,[Not used]) VALUES (?,?,?,?,?,?,?,?,?)
This was the trigger code:
IF exists (SELECT * FROM dbo.sysobjects WHERE id = object_id(N'[dbo].[rem_trg_rem_Test_table1_INSERT]') AND OBJECTPROPERTY(id, N'IsTrigger') = 1)
DROP TRIGGER [dbo].[rem_trg_rem_Test_table1_INSERT]
GO
CREATE TRIGGER rem_trg_rem_Test_table1_INSERT ON rem_Test_table1 FOR INSERT AS
SELECT INSERTED.[ID] FROM INSERTED WHERE INSERTED.[ID] IN
(SELECT TOP 40 T1.[ID] FROM rem_Test_table1 AS T1, rem_Test_table2 AS T2
WHERE ((T1.Search1>0) AND (T1.Search2<10)) AND (T1.Shared1=T2.ID)
ORDER BY T1.Order1 ASC, T1.Order2 ASC)
IF @@ROWCOUNT>0
BEGIN
INSERT rem_Error_log_table (Severity,Message) VALUES (1,'rem_Test_table1 INSERT trigger-notify')
END
GO
=================================================
The following was extracted from the profiler for test program runs. Note that I've had to recreate part of this from printouts so although I've checked it twice I might have introduced typos.
THIS WAS THE FASTER TO EXECUTE:
Rows Executes StmtText StmtId NodeId Parent PhysicalOp LogicalOp Argument DefinedValues EstimateRows EstimateIO EstimateCPU AvgRowSize TotalSubtreeCost OutputList Warnings Type Parallel EstimateExecutions
---- -------- -------- ------ ------ ------ ---------- --------- -------- ------------- ------------ ---------- ----------- ---------- ---------------- ---------- -------- ---- -------- ------------------
1 1 INSERT[rem_Test_table1]([Search1],[Search2],[Order1],[Order2],[Display1],[Display2],[Display3],[Not used]) VALUES (@1,@2,@3,@4,@5,@6,@7,@8) 1 1 0 NULL NULL NULL NULL 1 NULL NULL NULL 1.01E-02 NULL NULL INSERT 0 NULL
1 1 |--Table Insert(OBJECT:([Timings_test2].[dbo].[rem_Test_table1]),SET:([rem_Test_table1].[Test key]=RaiseIfNull([Expr1003]),[rem_Test_table1 1 2 1 Table Insert Insert OBJECT:([Timings_test2].[dbo].[rem_Test_table1]),SET:([rem_Test_table1].[Test_key]=RaiseIfNull([E [Expr1000]=Convert([@5]),[Expr1001]=Convert([@6 1 1.01E-02 0.000001 4 1.01E-02 NULL NULL PLAN_ROW 0 1
0 1 SELECT INSERTED.[ID] FROM INSERTED WHERE INSERTED.[ID] IN (SELECT TOP 40 T1.[ID] FROM rem_Test_table1 AS T1, rem_Test_table2 AS T2 WHERE ((T1 2 1 0 NULL NULL NULL NULL 1 NULL NULL NULL 0.30780268 NULL NULL SELECT 0 NULL
0 1 Nested Loops(Left Semi Join, OUTER REFERENCES:([INSERTED].[ID])) 2 3 1 Nested Loops Left Semi Join OUTER REFERENCES:([INSERTED].[ID]) NULL 1 0 4.18E-06 59 0.30780259 [INSERTED].[ID] NULL PLAN_ROW 0 1
1 1 |--Inserted Scan(OBJECT:([Timings_Test2].[dbo].[rem_Test_table1] AS [INSERTED])) 2 4 3 Inserted Scan Inserted Scan OBJECT:([Timings_Test2].[dbo].[rem_Test_table1] AS [INSERTED]) NULL 1 0.2338748 7.96E-05 59 0.2339544 [INSERTED].[ID] NULL PLAN_ROW 0 1
0 1 |--Filter(WHERE:([INSERTED].[ID]=[T1].[ID])) 2 5 3 Filter Filter WHERE:([INSERTED].[ID]=[T1].[ID]) NULL 1 0 1.92E-06 31 7.38E-02 NULL NULL PLAN_ROW 0 1
40 1 |--Top(40) 2 6 5 Top Top NULL NULL 40 0 0.000004 31 7.38E-02 [T1].[ID] NULL PLAN_ROW 0 1
40 1 |--Nested Loops(Inner Join, WHERE:([T2].[ID]=([T1].[Shared1])) 2 8 6 Nested Loops Inner Join WHERE:([T2].[ID]=[T1].[Shared1] NULL 40 0 7.38E-02 94 7.38E-02 [T1].[Order2], [T1].[Order1], [T1].[ID] NULL PLAN_ROW 0 1
40 1 |--Filter(WHERE:([T1].[Search1]>0 AND [T1].[Search2]<10)) 2 9 8 Filter Filter WHERE:([T1].[Search1]>0 AND [T1].[Search2]<10) NULL 41 0 1.11E-02 67 1.11E-02 [T2].[Shared1],[T1].[Order2],[T1].[Order1],[T1].[ID] NULL PLAN_ROW 0 1
40 1 | |--Bookmark Lookup(BOOKMARK:([Bmk1001]),OBJECT:([Timings_test2].[dbo].[rem_Test_table1] AS [T1])) 2 10 9 Bookmark Lookup Bookmark Lookup BOOKMARK:([Bmk1001]),OBJECT:([Timings_test2].[dbo].[rem_Test_table1] AS [T1]) [T1].[Shared1],[T1].[Search2],[T1].[Search1],[T1 44.530502 4.35E-03 4.90E-05 67 1.11E-02 [T1].[Shared1], [T1].[Search2], [T1].[Search1], [T1].[Order2], [T1].[Order1], [T1].[ID] NULL PLAN_ROW 0 1
72 1 | |--Index Scan(OBJECT:(Timings_test2].[dbo].[rem_Test_table1].[rem_Test_table11] AS [T1]),ORDERED FORWARD) 2 12 10 Index Scan Index Scan OBJECT:([Timings_test2].[dbo].[rem_Test_table1].[rem_Test_table11] AS [T1]), ORDERED FORWA [Bmk1001],[T1].[Order2],[T1].Order1] 44.530502 3.33E-03 3.33E-03 23 6.66E-03 [Bmk1001],[T1].[Order2],[T1].[Order1] NULL PLAN_ROW 0 1
2994 40 |--Table Scan(OBJECT:(Timings_test2].[dbo].[rem_Test_table2 AS [T2])) 2 20 8 Table Scan Table Scan OBJECT:([Timings_test2].[dbo].[rem_Test_table2] AS [T2]) [T2].[ID] 75 3.98E-02 0.000161 35 4.98E-02 [T2].ID NULL PLAN_ROW 0 41.999195
THIS WAS THE SLOWER TO EXECUTE:
Rows Executes StmtText StmtId NodeId Parent PhysicalOp LogicalOp Argument DefinedValues EstimateRows EstimateIO EstimateCPU AvgRowSize TotalSubtreeCost OutputList Warnings Type Parallel EstimateExecutions
---- -------- -------- ------ ------ ------ ---------- --------- -------- ------------- ------------ ---------- ----------- ---------- ---------------- ---------- -------- ---- -------- ------------------
1 1 INSERT[rem_Test_table1]([Search1],[Search2],[Order1],[Order2],[Display1],[Display2],[Display3],[Not used]) VALUES (@1,@2,@3,@4,@5,@6,@7,@8) 3 1 0 NULL NULL NULL NULL 1 NULL NULL NULL 1.01E-02 NULL NULL INSERT 0 NULL
1 1 |--Table Insert(OBJECT:([Timings_test2].[dbo].[rem_Test_table1]),SET:([rem_Test_table1].[Test key]=RaiseIfNull([Expr1003]),[rem_Test_table1 3 2 1 Table Insert Insert OBJECT:([Timings_test2].[dbo].[rem_Test_table1]),SET:([rem_Test_table1].[Test_key]=RaiseIfNull([E [Expr1000]=Convert([@5]),[Expr1001]=Convert([@6 1 1.01E-02 0.000001 4 1.01E-02 NULL NULL PLAN_ROW 0 1
0 1 SELECT INSERTED.[ID] FROM INSERTED WHERE INSERTED.[ID] IN (SELECT TOP 40 T1.[ID] FROM rem_Test_table1 AS T1, rem_Test_table2 AS T2 WHERE ((T1 4 1 0 NULL NULL NULL NULL 1 NULL NULL NULL 0.53789753 NULL NULL SELECT 0 NULL
0 1 Nested Loops(Left Semi Join, OUTER REFERENCES:([INSERTED].[ID])) 4 3 1 Nested Loops Left Semi Join OUTER REFERENCES:([INSERTED].[ID]) NULL 1 0 4.18E-06 59 0.53789747 [INSERTED].[ID] NULL PLAN_ROW 0 1
1 1 |--Inserted Scan(OBJECT:([Timings_Test2].[dbo].[rem_Test_table1] AS [INSERTED])) 4 4 3 Inserted Scan Inserted Scan OBJECT:([Timings_Test2].[dbo].[rem_Test_table1] AS [INSERTED]) NULL 1 0.19091183 7.96E-05 59 0.19099143 [INSERTED].[ID] NULL PLAN_ROW 0 1
0 1 |--Filter(WHERE:([INSERTED].[ID]=[T1].[ID])) 4 5 3 Filter Filter WHERE:([INSERTED].[ID]=[T1].[ID]) NULL 1 0 3.65E-06 31 0.34690183 NULL NULL PLAN_ROW 0 1
40 1 |--Sort(TOP 40, ORDER BY:([T1].[Order1] ASC, [T1].[Order2] ASC)) 4 6 5 Sort TopN Sort TOP 40, ORDER BY:([T1].[Order1] ASC, [T1].[Order2] ASC) NULL 7.5977144 1.13E-02 1.35E-04 31 0.34689742 [T1].[Order2], [T1].[Order1], [T1].[ID] NULL PLAN_ROW 0 1
9941 1 |--Hash Match(Inner Join, HASH:([T2].[ID])=([T1].[Shared1]), RESIDUAL:([T2].[ID]=[T1].[Shared1])) 4 8 6 Hash Match Inner Join HASH:([T2].[ID])=([T1].[Shared1]), RESIDUAL:([T2].[ID]=[T1].[Shared1]) NULL 7.5977144 0 0.08384078 63 0.33550069 [T1].[Order2], [T1].[Order1], [T1].[ID] NULL PLAN_ROW 0 1
75 1 |--Table Scan(OBJECT:([Timings_Test2].[dbo].[rem_Test_table2] AS [T2])) 4 9 8 Table Scan Table Scan OBJECT:([Timings_Test2].[dbo].[rem_Test_table2] AS [T2]) [T2].[ID] 75 1.99E-02 8.05E-05 35 4.00E-02 [T2].[ID] NULL PLAN_ROW 0 1
9942 1 |--Table Scan(OBJECT:([Timings_Test2].[dbo].[rem_Test_table1] AS [T1]), WHERE:([T1].[Search1]>0 AND [T1].[Search2]<10)) 4 10 8 Table Scan Table Scan OBJECT:([Timings_Test2].[dbo].[rem_Test_table1] AS [T1]), WHERE:([T1].[Search1]>0 AND [T1].[Search2]<10) [T1].[Shared1],[T1].[Search2],[T1].[Search1],[T1 9858.6836 0.19091183 0.0115812 67 0.20249303 [T1].[Shared1], [T1].[Search2], [T1].[Search1], [T1].[Order2], [T1].[Order1], [T1].[ID] NULL PLAN_ROW 0 1
The following was produced under the Query Analyzer when I used a user table instead of the INSERTED table to check the performance:
FASTER CASE:
IO Statistics
Table 'rem_Test_table1'. Scan count 0, logical reads 7, physical reads 0, read-ahead reads 0.
Table 'rem_Test_table2'. Scan count 40, logical reads 157, physical reads 0, read-ahead reads 0.
Table 'rem_Test_table1'. Scan count 1, logical reads 44, physical reads 0, read-ahead reads 0.
(0 row(s) affected)
(1 row(s) affected)
Time statistics
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 parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 30 ms, elapsed time = 32 ms.
SQL Server Execution Times:
CPU time = 7 ms, elapsed time = 7 ms.
(0 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
(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 = 7 ms.
SLOWER CASE:
IO Statistics
Table 'rem_Test_table1'. Scan count 0, logical reads 7, physical reads 0, read-ahead reads 0.
Table 'rem_Test_table1'. Scan count 1, logical reads 207, physical reads 0, read-ahead reads 0.
Table 'rem_Test_table2'. Scan count 1, logical reads 4, physical reads 0, read-ahead reads 0.
(0 row(s) affected)
(1 row(s) affected)
Time statistics
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 parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 119 ms, elapsed time = 119 ms.
(0 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
(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 = 4 ms.
April 24, 2003 at 5:29 am
Returning to the theory that SQL Server may not be appraising the number of Logical IO's which cause Physical IO accurately I came accross the following.
According to “SQL Server Quantitative Performance Analysis” on “SQL-Server-Performance.com” by Joe Chang (http://www.sql-server-performance.com/jc_sql_server_quantative_analysis1.asp), the IO costs depend only on whether you have more or less than 1Gbyte of memory while the CPU cost is independent of the actual CPU speed! This seems bizarre. I have not found any independent confirmation of this information however.
April 24, 2003 at 10:24 am
Try changing your trigger to match the updated syntax for joins to see what happens.
CREATE TRIGGER rem_trg_rem_Test_table1_INSERT ON rem_Test_table1 FOR INSERT AS
SELECT INSERTED.[ID] FROM INSERTED WHERE INSERTED.[ID] IN (
SELECT TOP 40
T1.[ID]
FROM
rem_Test_table1 AS T1
INNER JOIN
rem_Test_table2 AS T2
ON
T1.Shared1 = T2.[ID]
WHERE
T1.Search1 > 0 AND T1.Search2 < 10
ORDER BY
T1.Order1 ASC,
T1.Order2 ASC)
IF
@@ROWCOUNT > 0
BEGIN
INSERT rem_Error_log_table (Severity,Message) VALUES (1,'rem_Test_table1 INSERT trigger-notify')
END
GO
April 25, 2003 at 7:58 am
Yes this does seem to force the execution plan to the 'quick' mode and for that I am grateful but...does anyone know the answer to the question about SQL Server's asessment of IO overheads with reference to caching and pinned tables?
April 25, 2003 at 9:08 am
I have played with and tested many things with SQL and they seem to have optimized the engine when using SQL92 Syntax of INNER/LEFT/RIGHT/OUTER as opposed to , seperated and join in WHERE.
As to the extenet of the difference I have no idea.
Viewing 10 posts - 1 through 9 (of 9 total)
You must be logged in to reply to this topic. Login to reply