4

Problem

We are trying to understand why executing the same code by calling an stored procedure versus executing the store procedure contents in a query window is showing very different execution times but returns exactly the same result set of 183 rows.

Test1

Executing the following SP from SSMS takes 5 minutes to return the results.

EXEC uspFleetSummaryReportSelectByDateCommand @UserID = 1468, @Date = '2015-09-28'

For reference this is the SP detail:

    CREATE PROCEDURE [dbo].[uspFleetSummaryReportSelectByDateCommand]
    (
      @UserID int,
      @Date DateTime
      )
    AS

    DECLARE @CustomerID int
    SET @CustomerID = (Select CustomerID FROM [User] WHERE UserID = @UserID)

    SELECT  j.JourneyID,
            j.DeviceID,
            j.StartDate,
        j.EndDate,
        ISNULL(JourneyDistance, 0.0) AS [JourneyDistance],
        CONVERT(VARCHAR(8), DATEADD(SECOND, DATEDIFF(SECOND, j.StartDate, j.EndDate), 0), 114) AS [Duration],
        v.Registration,
        v.InitOdometer,
        jt.Name AS [JourneyType],
        dt.Name AS [DeviceType],
        PrivateJourney = (dbo.fxIsPrivateJourney(j.JourneyTypeID, j.DeviceID, @UserID)),
        CONVERT(VARCHAR(8), DATEADD(SECOND, ISNULL(e.IdleTime, 0), 0), 114) AS [IdleTime]
FROM Journey j WITH (NOLOCK) 
INNER JOIN Vehicle v WITH (NOLOCK) ON v.DeviceID = j.DeviceID
INNER JOIN JourneyType jt WITH (NOLOCK) ON jt.JourneyTypeID = j.JourneyTypeID
INNER JOIN Device d WITH (NOLOCK) ON d.DeviceID = j.DeviceID
    INNER JOIN Configuration config WITH (NOLOCK) ON config.ConfigurationID = d.ConfigurationID
INNER JOIN DeviceType dt WITH (NOLOCK) ON dt.DeviceTypeID = config.DeviceTypeID
LEFT OUTER JOIN (
    SELECT 
    e.JourneyId,
    SUM(DATEDIFF(SECOND, e.StartDateTime, e.EndDateTime)) AS [IdleTime]
    FROM [Event] e WITH (NOLOCK)
    WHERE e.JourneyId = JourneyID AND e.EventType = 4/*Idle Event*/
    GROUP BY e.JourneyId
) e ON e.JourneyId = j.JourneyID
WHERE   j.StartDate BETWEEN @Date AND DATEADD(DAY,1,@Date)
        AND (j.JourneyDistance IS NOT NULL)
        AND DATEDIFF(MINUTE,j.StartDate,ISNULL(j.EndDate,getdate())) > 0
        AND j.DeviceID IN (Select v.DeviceID 
                                    FROM Vehicle v WITH (NOLOCK)
                                INNER JOIN Customer c WITH (NOLOCK) ON         c.CustomerID = v.CustomerID
                                INNER JOIN [User] u ON u.CustomerID = c.CustomerID
                                WHERE   v.CustomerID = @CustomerID AND u.UserID = @UserID
                                        AND (v.LevelOneID = u.LevelOneID Or u.LevelOneID is null) 
                                        AND (v.LevelTwoID = u.LevelTwoID Or u.LevelTwoID is null) 
                                        AND (v.LevelThreeID = u.LevelThreeID Or u.LevelThreeID is null) 
                                        AND (v.LevelFourID = u.LevelFourID Or u.LevelFourID is null) 
                                        AND (v.LevelFiveID = u.LevelFiveID Or u.LevelFiveID is null) 
                                        AND (v.DriverID = u.LevelSixID Or u.LevelSixID is null)
                                        AND ISNULL(v.HideFromCustomer,0) != 1
                             )
ORDER BY Registration,j.JourneyID

Test2

But executing the same SP code and setting the variables take 10 seconds to return the results.

Please find below the same SP with the variables set. The following script is executed from SSMS query window.

DECLARE @UserID INT = 13651
DECLARE @Date DATETIME = '2015-09-28'

DECLARE @CustomerID int
SET @CustomerID = (Select CustomerID FROM [User] WHERE UserID = @UserID)

SELECT    j.JourneyID,
        j.DeviceID,
        j.StartDate,
        j.EndDate,
       ISNULL(JourneyDistance, 0.0) AS [JourneyDistance],
       CONVERT(VARCHAR(8), DATEADD(SECOND, DATEDIFF(SECOND, j.StartDate, j.EndDate), 0), 114) AS [Duration],
       v.Registration,
       v.InitOdometer,
       jt.Name AS [JourneyType],
       dt.Name AS [DeviceType],
        PrivateJourney = (dbo.fxIsPrivateJourney(j.JourneyTypeID, j.DeviceID, @UserID)),
        CONVERT(VARCHAR(8), DATEADD(SECOND, ISNULL(e.IdleTime, 0), 0), 114) AS [IdleTime]
FROM Journey j WITH (NOLOCK) 
INNER JOIN Vehicle v WITH (NOLOCK) ON v.DeviceID = j.DeviceID
INNER JOIN JourneyType jt WITH (NOLOCK) ON jt.JourneyTypeID = j.JourneyTypeID
INNER JOIN Device d WITH (NOLOCK) ON d.DeviceID = j.DeviceID
INNER JOIN Configuration config WITH (NOLOCK) ON config.ConfigurationID =     d.ConfigurationID
INNER JOIN DeviceType dt WITH (NOLOCK) ON dt.DeviceTypeID = config.DeviceTypeID
LEFT OUTER JOIN (
    SELECT 
    e.JourneyId,
    SUM(DATEDIFF(SECOND, e.StartDateTime, e.EndDateTime)) AS [IdleTime]
    FROM [Event] e WITH (NOLOCK)
    WHERE e.JourneyId = JourneyID AND e.EventType = 4/*Idle Event*/
    GROUP BY e.JourneyId
) e ON e.JourneyId = j.JourneyID
    WHERE    j.StartDate BETWEEN @Date AND DATEADD(DAY,1,@Date)
       AND (j.JourneyDistance IS NOT NULL)
       AND DATEDIFF(MINUTE,j.StartDate,ISNULL(j.EndDate,getdate())) > 0
       AND j.DeviceID IN (Select v.DeviceID 
                                    FROM Vehicle v WITH (NOLOCK)
                                   INNER JOIN Customer c WITH (NOLOCK) ON     c.CustomerID = v.CustomerID
                                    INNER JOIN [User] u ON u.CustomerID =     c.CustomerID
                                   WHERE    v.CustomerID = @CustomerID AND u.UserID = @UserID
                                            AND (v.LevelOneID = u.LevelOneID Or u.LevelOneID is null) 
                                           AND (v.LevelTwoID = u.LevelTwoID Or u.LevelTwoID is null) 
                                           AND (v.LevelThreeID =     u.LevelThreeID Or u.LevelThreeID is null) 
                                           AND (v.LevelFourID =     u.LevelFourID Or u.LevelFourID is null) 
                                           AND (v.LevelFiveID =     u.LevelFiveID Or u.LevelFiveID is null) 
                                           AND (v.DriverID = u.LevelSixID Or u.LevelSixID is null)
                                            AND ISNULL(v.HideFromCustomer,0) != 1
                            )
ORDER BY Registration,j.JourneyID

Debugging to date

Comparing the two statements side by side they are identical bar the setting of the variables.

Comparing the result sets side by side they are identical.

Selecting the variable CUSTOMERID in isolation takes milliseconds.

Dates variables passed are in the same format.

We have run this test multiple times to rule out cache related issue.

Query execution plan was examined on both tests. When executing the SP it was clear an index was missing on table EVENT when executing TEST1.

Index added

   CREATE NONCLUSTERED INDEX [290915_EventTypeJourneyID, EventTypeJID,>] ON     [dbo].[Event] 
(
    [EventType] ASC,
    [JourneyId] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, SORT_IN_TEMPDB =     OFF, IGNORE_DUP_KEY = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS  =     ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
GO

Result

Execution time for TEST1 dropped to 1 second.

Question

Ok so the principle issue was resolved but fundamentally I don't understand why the performance gap between the two tests that essentially are running the same code ? its same same code , should be using the same indexes , execution times should be similar.

Thank you for any insights into this behaviour.

Reference

Sql server 2008 64bit standard edition.

Table.JOURNEY (350m rows)

CREATE TABLE [dbo].[Journey](
    [JourneyID] [int] IDENTITY(1,1) NOT NULL,
    [StartAddress] [varchar](500) NULL,
    [StartPostcode] [varchar](50) NULL,
    [EndAddress] [varchar](500) NULL,
    [EndPostcode] [varchar](50) NULL,
    [JourneyTypeID] [int] NULL,
    [Comment] [varchar](500) NULL,
    [DriverID] [int] NULL,
    [StartDate] [datetime] NULL,
    [EndDate] [datetime] NULL,
    [IdleTimeEngineOn] [int] NULL,
    [TimeSinceLastJourney] [int] NULL,
    [JourneyDistance] [decimal](8, 2) NULL,
    [DeviceID] [int] NOT NULL,
    [tempJourneyID] [int] NULL,
    [tempCustomerID] [int] NULL,
 CONSTRAINT [Journey_PK] PRIMARY KEY CLUSTERED 
(
    [JourneyID] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
) ON [PRIMARY]

GO

SET ANSI_PADDING OFF
GO

ALTER TABLE [dbo].[Journey]  WITH CHECK ADD  CONSTRAINT [Device_Journey_FK1]     FOREIGN KEY([DeviceID])
REFERENCES [dbo].[Device] ([DeviceID])
GO

ALTER TABLE [dbo].[Journey] CHECK CONSTRAINT [Device_Journey_FK1]
GO

ALTER TABLE [dbo].[Journey]  WITH CHECK ADD  CONSTRAINT [Driver_Journey_FK1]     FOREIGN KEY([DriverID])
REFERENCES [dbo].[Driver] ([DriverID])
GO

ALTER TABLE [dbo].[Journey] CHECK CONSTRAINT [Driver_Journey_FK1]
GO

ALTER TABLE [dbo].[Journey]  WITH NOCHECK ADD  CONSTRAINT [JourneyType_Journey_FK1] FOREIGN KEY([JourneyTypeID])
REFERENCES [dbo].[JourneyType] ([JourneyTypeID])
GO

ALTER TABLE [dbo].[Journey] CHECK CONSTRAINT [JourneyType_Journey_FK1]
GO

Table.EVENT (36m rows)

CREATE TABLE [dbo].[Event](
    [EventID] [int] IDENTITY(1,1) NOT NULL,
    [StartDateTime] [datetime] NULL,
    [EndDateTime] [datetime] NULL,
    [StartLocationID] [int] NOT NULL,
    [EndLocationID] [int] NULL,
    [AlertRaised] [bit] NULL,
    [EventRuleID] [int] NULL,
    [DeviceID] [int] NOT NULL,
    [EventMessage] [varchar](max) NULL,
    [TopSpeed] [decimal](4, 1) NULL,
    [SpeedZone] [int] NULL,
    [EventType] [int] NULL,
    [ImpactId] [int] NULL,
    [NotificationStatus] [bit] NULL,
    [CableBreakZone0] [int] NULL,
    [CableBreakDistance0] [int] NULL,
    [CableBreakZone1] [int] NULL,
    [CableBreakDistance1] [int] NULL,
    [AdValue] [int] NULL,
    [DriverId] [int] NULL,
    [VehicleId] [int] NULL,
    [JourneyId] [int] NULL,
 CONSTRAINT [Event_PK] PRIMARY KEY CLUSTERED 
(
    [EventID] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY =     OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
) ON [PRIMARY]

GO

SET ANSI_PADDING OFF
GO

ALTER TABLE [dbo].[Event]  WITH CHECK ADD  CONSTRAINT [Device_Event_FK1]     FOREIGN KEY([DeviceID])
REFERENCES [dbo].[Device] ([DeviceID])
GO

ALTER TABLE [dbo].[Event] CHECK CONSTRAINT [Device_Event_FK1]
GO

ALTER TABLE [dbo].[Event]  WITH CHECK ADD  CONSTRAINT [Event_Impact_FK]     FOREIGN KEY([ImpactId])
REFERENCES [dbo].[Impact] ([ImpactID])
GO

ALTER TABLE [dbo].[Event] CHECK CONSTRAINT [Event_Impact_FK]
GO

ALTER TABLE [dbo].[Event]  WITH CHECK ADD  CONSTRAINT [EventRule_Event_FK1]     FOREIGN KEY([EventRuleID])
REFERENCES [dbo].[EventRule] ([EventRuleID])
GO

ALTER TABLE [dbo].[Event] CHECK CONSTRAINT [EventRule_Event_FK1]
GO

ALTER TABLE [dbo].[Event]  WITH CHECK ADD  CONSTRAINT [FK_Event_Driver]     FOREIGN KEY([DriverId])
REFERENCES [dbo].[Driver] ([DriverID])
GO

ALTER TABLE [dbo].[Event] CHECK CONSTRAINT [FK_Event_Driver]
GO

ALTER TABLE [dbo].[Event]  WITH CHECK ADD  CONSTRAINT [FK_Event_Journey]     FOREIGN KEY([JourneyId])
REFERENCES [dbo].[Journey] ([JourneyID])
ON DELETE CASCADE
GO

ALTER TABLE [dbo].[Event] CHECK CONSTRAINT [FK_Event_Journey]
GO

ALTER TABLE [dbo].[Event]  WITH CHECK ADD  CONSTRAINT [FK_Event_Vehicle]     FOREIGN KEY([VehicleId])
REFERENCES [dbo].[Vehicle] ([VehicleID])
ON DELETE CASCADE
GO

ALTER TABLE [dbo].[Event] CHECK CONSTRAINT [FK_Event_Vehicle]
GO
scott_lotus
  • 3,171
  • 22
  • 51
  • 69
  • 1
    you have analyzed so much and the way of asking question is clear cut ..very explantive – mohan111 Sep 29 '15 at 08:52
  • 1
    You might want to read about parameter sniffing – Shnugo Sep 29 '15 at 08:58
  • Another idea (especially if your database is a little older...) could be ARITHABORT, which is also known to cause strange performance differences... – Shnugo Sep 29 '15 at 09:02
  • 1
    Thanks for the comments. Regarding Parameter Sniffing , we tried to add the following on to the end of the SP "WITH RECOMPILE" to force an new execution plan but the results were the same. Sorry , should have added this into DEBUGGING section. – scott_lotus Sep 29 '15 at 09:04
  • Did you compare execution plans? – Shnugo Sep 29 '15 at 09:06
  • @ Shnugo , the clue will be in the execution plan as you say , a comparison was attempted using the large plan diagram (and indeed this is what highlighted the missing index). Maybe viewing in execution plan as XML is a more appropriate way to achieve this accurately. With the addition of the index to resolve TEST1 the results wont be as obvious. – scott_lotus Sep 29 '15 at 09:18
  • possible duplicate of [SQL Server: Query fast, but slow from procedure](http://stackoverflow.com/questions/440944/sql-server-query-fast-but-slow-from-procedure) – shA.t Sep 29 '15 at 09:27
  • @Shnugo The issue you're talking about is not really related to ARITHABORT, it is a general issue with session settings and re-usability of plans – James Z Sep 29 '15 at 14:00

3 Answers3

2

There's several things that affect query plan creation in SQL Server which might cause really strange things seem to happen.

  1. The plan for stored procedure is (normally) created in the first execution, using the parameters from that time. That plan is saved and used for all the future executions, even if the parameters change.

    • The procedure can get a new plan if for example statistics change.

    • If the procedure is such that the optimal plan is totally different depending on the values that are passed in or the procedure for example has a lot of so called optional parameters (for example field = @variable or @variable is NULL -style of coding) -- this can lead to really bad situations and this is usually what is referred as parameter sniffing.

    • The parameters used to compile the plan can be seen in the properties of the leftmost object in the plan.

  2. If you run the same statement in management studio, but the parameters are local variables that are assigned in the beginning, the statement will be optimized with unknown values, because the values are not known at that point, even if it seems obvious what the values will be.

    • This is the same thing with procedures that use local variable defined inside the procedure.
  3. If you are running applications that have different session settings, the plans created in step 1. might not be usable, and a different plan will be stored and used. This can cause a situation where it seems that the same procedure behaves different when executed with the same parameters in the application and management studio.

For more details, you could check out for example Slow in the Application, Fast in SSMS? Understanding Performance Mysteries by Erland Sommarskog.

Edit: And to understand what's happening, always look at both actual execution plan and statistics IO output. Those should tell you why something is slower than the other (unless it's blocking, waiting etc related)

James Z
  • 12,209
  • 10
  • 24
  • 44
1

Difference between running a query in a batch of scripts in SSMS vs running a query in a Stored Procedure is at least in two way:

  1. Before creating your SP use SET ANSI_NULLS ON.
  2. Use inner variable instead arguments of SP in your query like this:

    DECLARE @pUserID INT, @pDate DATETIME;
    SELECT @pUserID = @UserID, @pDate = @Date;
    
    SELECT ... @pUserID ...;
    
Community
  • 1
  • 1
shA.t
  • 16,580
  • 5
  • 54
  • 111
0

Had the same problem on an sql server 2008 Running this once fixed it for me :

USE master
ALTER DATABASE [dbname] SET ARITHABORT ON WITH NO_WAIT;

ssms always sets ARITHABORT on, clients written in dotnet do not, that is why both are using a different plan with different statistics.

GuidoG
  • 11,359
  • 6
  • 44
  • 79