2

I've been doing some SQL Server procedures optimization lately and was looking for a testing pattern (time and result wise). I've came with this solution so far:

SET NOCOUNT ON;
----------------------------------------------------------------------------------------------------------------
-- Procedures data and performance testing pattern
----------------------------------------------------------------------------------------------------------------
-- Prepare test queries (most likely will be taken from Logs.ProcedureTraceData (DATAUK/DATAUS servers)
-- Procedures should insert records into Temporary table, so we can compare their results using EXCEPT
-- If result set columns are fixed (i.e. no Dynamic SQL is used), we can create Temporary tables inside script
--  and insert records in them to do comparison and just TRUNCATE them at the end of the loop.
--  example here: http://stackoverflow.com/a/654418/3680098
-- If there're any data discrepancies or record counts are different, it will be displayed in TraceLog table
----------------------------------------------------------------------------------------------------------------
-- Create your own TraceLog table to keep records
----------------------------------------------------------------------------------------------------------------
/*
CREATE TABLE Temporary._EB_TraceLog
(
    ID INT NOT NULL IDENTITY(1, 1) CONSTRAINT PK_Temporary_EB_TraceLog_ID PRIMARY KEY
    , CurrentExecutionTime INT
    , TempExecutionTime INT
    , CurrentExecutionResultsCount INT
    , TempExecutionResultsCount INT
    , IsDifferent BIT CONSTRAINT DF_Temporary_EB_TraceLog_IsDifferent DEFAULT 0 NOT NULL
    , TimeDiff AS CurrentExecutionTime - TempExecutionTime
    , PercentageDiff AS CAST(((CAST(CurrentExecutionTime AS DECIMAL)/ CAST(TempExecutionTime AS DECIMAL)) * 100 - 100) AS DECIMAL(10, 2))
    , TextData NVARCHAR(MAX)
);

SELECT *
FROM Temporary._EB_TraceLog;

TRUNCATE TABLE Temporary._EB_TraceLog;
*/

INSERT INTO Temporary._EB_TraceLog (TextData)
SELECT TextData
FROM Temporary._EB_GetData_Timeouts
EXCEPT
SELECT TextData
FROM Temporary._EB_TraceLog;

DECLARE @Counter INT;

SELECT @Counter = MIN(ID)
FROM Temporary._EB_TraceLog
WHERE CurrentExecutionTime IS NULL
    OR TempExecutionTime IS NULL
    OR CurrentExecutionResultsCount IS NULL
    OR TempExecutionResultsCount IS NULL;

WHILE @Counter <= (SELECT MAX(ID) FROM Temporary._EB_TraceLog)
BEGIN
    DECLARE @SQLStringCurr NVARCHAR(MAX);
    DECLARE @SQLStringTemp NVARCHAR(MAX);
    DECLARE @StartTime DATETIME2;
    SELECT @SQLStringCurr = REPLACE(TextData, 'dbo.GetData', 'Temporary._EB_GetData_Orig')
        , @SQLStringTemp = REPLACE(TextData, 'dbo.GetData', 'Temporary._EB_GetData_Mod')
    FROM Temporary._EB_TraceLog
    WHERE ID = @Counter;

    ----------------------------------------------------------------------------------------------------------------
    -- Drop temporary tables in script, so these numbers don't figure in SP execution time
    ----------------------------------------------------------------------------------------------------------------
    IF OBJECT_ID(N'Temporary._EB_Test_Orig') IS NOT NULL
        DROP TABLE Temporary._EB_Test_Orig;

    IF OBJECT_ID(N'Temporary._EB_Test_Mod') IS NOT NULL
        DROP TABLE Temporary._EB_Test_Mod;

    ----------------------------------------------------------------------------------------------------------------
    -- Actual testing
    ----------------------------------------------------------------------------------------------------------------
    -- Take time snapshot and execute original procedure, which inserts records into Temporary table
    -- When done - measurements will be updated on TraceLog table
    ----------------------------------------------------------------------------------------------------------------
    SELECT @StartTime = CURRENT_TIMESTAMP;
    EXECUTE sp_executesql @SQLStringCurr;

    UPDATE T
    SET T.CurrentExecutionTime = DATEDIFF(MILLISECOND, @StartTime, CURRENT_TIMESTAMP)
    FROM Temporary._EB_TraceLog AS T
    WHERE T.ID = @Counter;

    ----------------------------------------------------------------------------------------------------------------
    -- Take time snapshot and execute optimized procedure, which inserts records into Temporary table
    -- When done - measurements will be updated on TraceLog table
    ----------------------------------------------------------------------------------------------------------------
    SELECT @StartTime = CURRENT_TIMESTAMP;
    EXECUTE sp_executesql @SQLStringTemp;

    UPDATE T
    SET T.TempExecutionTime = DATEDIFF(MILLISECOND, @StartTime, CURRENT_TIMESTAMP)
    FROM Temporary._EB_TraceLog AS T
    WHERE T.ID = @Counter;

    ----------------------------------------------------------------------------------------------------------------
    -- Check if there are any data discrepancies
    -- If there are any, set IsDifferent to 1, so we can find the root cause
    ----------------------------------------------------------------------------------------------------------------
    IF EXISTS (SELECT * FROM Temporary._EB_Test_Mod EXCEPT SELECT * FROM Temporary._EB_Test_Orig)
    OR EXISTS (SELECT * FROM Temporary._EB_Test_Orig EXCEPT SELECT * FROM Temporary._EB_Test_Mod)
    BEGIN
        UPDATE T
        SET T.IsDifferent = 1
        FROM Temporary._EB_TraceLog AS T
        WHERE T.ID = @Counter;
    END

    ----------------------------------------------------------------------------------------------------------------
    -- Update record counts for each execution
    -- We can check if there aren't any different record counts even tho results are same
    -- EXCEPT clause removes duplicates when doing checks
    ----------------------------------------------------------------------------------------------------------------
    UPDATE T
    SET T.CurrentExecutionResultsCount = (SELECT COUNT(*) FROM Temporary._EB_Test_Orig)
        , T.TempExecutionResultsCount = (SELECT COUNT(*) FROM Temporary._EB_Test_Mod)
    FROM Temporary._EB_TraceLog AS T
    WHERE T.ID = @Counter;

    ----------------------------------------------------------------------------------------------------------------
    -- Print iteration number and proceed on next one
    ----------------------------------------------------------------------------------------------------------------
    PRINT @Counter;
    SET @Counter += 1;
END

SELECT *
FROM Temporary._EB_TraceLog;

This works quite well so far, but I would like to include IO and TIME statistics in each iteration. Is that possible?

I know I can do it using:

SET STATISTICS IO ON;
SET STATISTICS TIME ON;

But is there a way to grab summed up values and put them in my TraceLog table?

And on top of that, is there anything doesn't make sense in this piece of code?

Thanks

Evaldas Buinauskas
  • 13,739
  • 11
  • 55
  • 107
  • The only thing that comes to my mind is using extended events, but I'm not sure if it's suitable for this – James Z Jun 19 '15 at 07:04
  • If you want only Execution time then you can get it by declaring a `variable` and calculate it using `datetime` differences using `datediff` before start execution and after completed a statement. or for more detail info you can use this `DMV` `sys.dm_exec_query_stats`. – Arun Gairola Jun 19 '15 at 07:08
  • Hi @ArunGairola, I'm already doing this (about `DATEDIFF()`). But looking at `sys.dm_exec_query_stats` looks promising. How would I connect rows from this `DMV` to actual procedure executions? – Evaldas Buinauskas Jun 19 '15 at 07:20
  • you can use `SELECT total_elapsed_time FROM sys.dm_exec_query_stats ` using `sql handle of current `session` – Arun Gairola Jun 19 '15 at 07:23
  • I will try to do that, thank you! – Evaldas Buinauskas Jun 19 '15 at 07:24

1 Answers1

1

you can use this query

SELECT total_elapsed_time
FROM sys.dm_exec_query_stats 
WHERE sql_handle in (SELECT most_recent_sql_handle
FROM sys.dm_exec_connections
CROSS APPLY sys.dm_exec_sql_text(most_recent_sql_handle)
WHERE session_id = (@@spid))
Arun Gairola
  • 884
  • 4
  • 14