Unexecuted statement in a proc causes significant perf change

Dan Holmes 2015-07-09 13:29:41

I have a 3300 line proc that was executing in ~200-300 ms. On an upgrade an IF section was added (below). Now this block could never be exercised by the application that was running. It was built for the next version. I proved this with Profiler. None of this ever ran. However just its existence in the proc caused a 10x perf degradation. Now the proc executed in 2.5-3 seconds. Profiler showed the CPU duration and reducing the filter to 5 microseconds returned almost every statement in the proc. Adding the time for each state never came close to the CPU time (nor Duration) of RPC:Completed event. There was time but it wasn't detectable anywhere. I had statement compilation on as well. That wasn't it.

in the block below, when i changed

INNER JOIN dbo.split(@param2, LEFT(@param2, 1)) t ON t.idx = a.idx

to

INNER JOIN dbo.splittext(@param2, LEFT(@param2, 1)) t ON t.id = a.idx

performance went back to normal. The two functions in play are both table valued functions that take a CSV string and return a two column dataset; the position and value. The split() function is inline and splittext is multi-statement.

Any idea of why this change would cause such a problem? I couldn't even find a way to measure this. I had to put the old code back and incrementally add the changes until i found the offending code (dangerous in a production system).

thanks for any insight.

Microsoft SQL Server 2008 R2 (SP2) – 10.50.4297.0 (X64)
Nov 22 2013 17:24:14
Copyright (c) Microsoft Corporation
Standard Edition (64-bit) on Windows NT 6.1 (Build 7601: Service Pack 1)

ELSE IF @MsgStatusID = @MESSAGE_STATUS_FRSTOP_FLEET_MAINTENANCE 
BEGIN
    IF EXISTS (SELECT * FROM dbo.split(@param2, LEFT(@param2, 1)) WHERE idx > 4)
        --only values 1-4 are defined.  Anything higher than that is an error.
        RAISERROR('The value for Param2 [%s] has undefined values (>4) for a MsgStatusID of [%d].', 16, 10, @Param2, @MsgStatusID);
 
    DECLARE @AssetPlannedEventID INT = (
        SELECT ape.AssetPlannedEventID
        FROM dbo.tblWorkOrderStopTaskAssetActual wsta
        INNER JOIN dbo.tblWorkOrderStopTaskAsset sta ON sta.workorderstoptaskassetid = wsta.WorkOrderStopTaskAssetID
        INNER JOIN dbo.tblAssetPlannedEvent ape ON ape.WorkOrderStopTaskID = sta.WorkOrderStopTaskID
        WHERE wsta.WorkOrderStopTaskActualID = @stopid 
        );
    DECLARE @FRSTOP_FLEET_MAINTENANCE TABLE ( AssetPlannedEventID INT NOT NULL PRIMARY KEY);
    MERGE dbo.tblAssetMaintenanceTask AS trgt
    USING (
        --1 parts, 2 labor, 3 comment, 4 is odometer
        SELECT p.[1] one, p.[2] two, p.[3] three, p.[4] four
        FROM (
            SELECT t.value task, v.value, ape.AssetPlannedEventID
            FROM dbo.tblWorkOrderStopTaskAssetActual wsta
            INNER JOIN dbo.tblWorkOrderStopTaskAsset sta ON sta.workorderstoptaskassetid = wsta.WorkOrderStopTaskAssetID
            INNER JOIN dbo.tblAssetPlannedEvent ape ON ape.WorkOrderStopTaskID = sta.WorkOrderStopTaskID
            INNER JOIN dbo.split(@param1, LEFT(@param1, 1)) a ON sta.assetid = CASE WHEN a.value = '0' THEN sta.assetid ELSE CAST(a.value AS INT) END
            INNER JOIN dbo.split(@param2, LEFT(@param2, 1)) t ON t.idx = a.idx
            INNER JOIN dbo.split(@param3, LEFT(@param3, 1)) v ON v.idx = a.idx
            WHERE wsta.WorkOrderStopTaskActualID = @stopid AND a.idx > 0
        ) d
        PIVOT (
            MAX(d.AssetPlannedEventID)
            FOR d.task IN ([1], [2], [3], [4])
        ) p
    ) src ON trgt.AssetPlannedEventID = @AssetPlannedEventID
    WHEN MATCHED THEN
        UPDATE SET ActualLaborCost = src.two, ActualPartsCost = src.one, Comment = src.three, Performed_mileage = src.four, EnteredDate = @ProcStartTime
    WHEN NOT MATCHED BY TARGET THEN
        INSERT (ActualLaborCost, ActualPartsCost, comment, performed_mileage, EnteredDate, AgencyID, ID)
        VALUES (src.one, src.two, src.three, src.four, @ProcStartTime, 1, 1)
    OUTPUT inserted.AssetPlannedEventID INTO @FRSTOP_FLEET_MAINTENANCE(AssetPlannedEventID)
    ;
    UPDATE dbo.tblAssetPlannedEvent SET EnteredDate = @ProcStartTime, Completed = 1, Performed_By = @DriverID, Performed_Date = @ProcStartTime
    FROM @FRSTOP_FLEET_MAINTENANCE m
    WHERE m.AssetPlannedEventID = tblAssetPlannedEvent.AssetPlannedEventID;
END
SQLkiwi 2015-07-09 20:13:18
Does that block of code take a while to compile (not necessarily run) when outside a procedure? When it is the only thing in a procedure? My money would be on the combination of MERGE/PIVOT/OUTPUT/2008 R2 and inline-TVFs taking a while to compile. I know you said "that wasn't it" but even so.
Dan Holmes 2015-07-09 21:31:12
i created this and it runs (and therefore compiles) subsecond.
(formatting keeps going wonky)

EXEC dbo.a NULL, NULL, NULL, 1, 0 , 1


ALTER proc dbo.a @param1 VARCHAR(MAX), @param2 VARCHAR(MAX), @param3 VARCHAR(MAX), @MsgStatusID INT, @stopid INT, @driverid INT
AS
 BEGIN
    IF @stopid = 1
    BEGIN
    DECLARE @procstarttime DATETIME = getdate();
     IF EXISTS (SELECT * FROM dbo.split(@param2, LEFT(@param2, 1)) WHERE idx > 4)
         --only values 1-4 are defined.  Anything higher than that is an error.
         RAISERROR('The value for Param2 [%s] has undefined values (>4) for a MsgStatusID of [%d].', 16, 10, @Param2, @MsgStatusID);

     DECLARE @AssetPlannedEventID INT = (
         SELECT ape.AssetPlannedEventID
         FROM dbo.tblWorkOrderStopTaskAssetActual wsta
         INNER JOIN dbo.tblWorkOrderStopTaskAsset sta ON sta.workorderstoptaskassetid = wsta.WorkOrderStopTaskAssetID
         INNER JOIN dbo.tblAssetPlannedEvent ape ON ape.WorkOrderStopTaskID = sta.WorkOrderStopTaskID
         WHERE wsta.WorkOrderStopTaskActualID = @stopid 
         );
     DECLARE @FRSTOP_FLEET_MAINTENANCE TABLE ( AssetPlannedEventID INT NOT NULL PRIMARY KEY);
     MERGE dbo.tblAssetMaintenanceTask AS trgt
     USING (
         --1 parts, 2 labor, 3 comment, 4 is odometer
         SELECT p.[1] one, p.[2] two, p.[3] three, p.[4] four
         FROM (
             SELECT t.value task, v.value, ape.AssetPlannedEventID
             FROM dbo.tblWorkOrderStopTaskAssetActual wsta
             INNER JOIN dbo.tblWorkOrderStopTaskAsset sta ON sta.workorderstoptaskassetid = wsta.WorkOrderStopTaskAssetID
             INNER JOIN dbo.tblAssetPlannedEvent ape ON ape.WorkOrderStopTaskID = sta.WorkOrderStopTaskID
             INNER JOIN dbo.split(@param1, LEFT(@param1, 1)) a ON sta.assetid = CASE WHEN a.value = '0' THEN sta.assetid ELSE CAST(a.value AS INT) END
             INNER JOIN dbo.split(@param2, LEFT(@param2, 1)) t ON t.idx = a.idx
             INNER JOIN dbo.split(@param3, LEFT(@param3, 1)) v ON v.idx = a.idx
             WHERE wsta.WorkOrderStopTaskActualID = @stopid AND a.idx > 0
         ) d
         PIVOT (
             MAX(d.AssetPlannedEventID)
             FOR d.task IN ([1], [2], [3], [4])
         ) p
     ) src ON trgt.AssetPlannedEventID = @AssetPlannedEventID
     WHEN MATCHED THEN
         UPDATE SET ActualLaborCost = src.two, ActualPartsCost = src.one, Comment = src.three, Performed_mileage = src.four, EnteredDate = @ProcStartTime
     WHEN NOT MATCHED BY TARGET THEN
         INSERT (ActualLaborCost, ActualPartsCost, comment, performed_mileage, EnteredDate, AgencyID, ID)
         VALUES (src.one, src.two, src.three, src.four, @ProcStartTime, 1, 1)
     OUTPUT inserted.AssetPlannedEventID INTO @FRSTOP_FLEET_MAINTENANCE(AssetPlannedEventID)
     ;
     UPDATE dbo.tblAssetPlannedEvent SET EnteredDate = @ProcStartTime, Completed = 1, Performed_By = @DriverID, Performed_Date = @ProcStartTime
     FROM @FRSTOP_FLEET_MAINTENANCE m
     WHERE m.AssetPlannedEventID = tblAssetPlannedEvent.AssetPlannedEventID;
     END
 END
July 9, 2015
No Comments