SQL Server: How to find what lines are executed

Question

I am working on a mutation test framework for SQL Server, for this I need to be able to calculate what lines of a stored procedure, function or trigger are executed when I execute a certain stored procedure.

The difficult part is that I want to know the exact lines or statements being executed from the stored procedure I call.

With a query like this I can see what stored procedures/triggers/functions are being executed, since I know when I call the stored procedure I can use the time to see if it was executed.

SELECT  d.object_id, d.database_id, 
         OBJECT_NAME(object_id, database_id) AS proc_name, 
         MAX( d.last_execution_time) as last_execution_time,
         OBJECT_DEFINITION(object_id) as definition
         FROM sys.dm_exec_procedure_stats AS d 
         WHERE d.database_id = DB_ID()
         GROUP BY  d.object_id, d.database_id, 
         OBJECT_NAME(object_id, database_id) 

How would I find the lines/statements that have been executed, I also have to know inside what stored procedure/trigger/function the lines/statements exists and in which shema this is. I have to take into account that a IF/ELSE statement may be used.

With this data I can do 2 important things:

• generate a code coverage report
• optimize what lines to mutate, since I dont have to mutate uncovered lines.

A possible, but not a very nice, solution would be to automaticly change stored procedures to add a line that inserts the previous line into a table, but this will require splitting up the procedure into statements, which I don't know how to do.

Please note that I cannot change the code users want to test with my framework. I can search for patterns and replace but manually changing procedures is NOT a option.

EDIT: Lets redifine this question: How to split a stored procedure definition into its different statements in a way that does not depend on code style? and How to add a new statement in between found statements?

EDIT: in the SO post SQL Server: How to parse code into its different statements I have found a way to trace statement execution, but I can't filter it yet.

Answer 1

So the extended events are the solution, this is how I have done it:

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='testMSSQLTrace')  
   DROP EVENT SESSION testMSSQLTrace ON SERVER;  

DECLARE @cmd VARCHAR(MAX) = '';
SELECT @cmd = 'CREATE EVENT SESSION testMSSQLTrace 
ON SERVER
    ADD EVENT sqlserver.sp_statement_completed
        (WHERE (sqlserver.database_name = N''' + DB_NAME() + '''))
    ADD TARGET package0.ring_buffer
        WITH (
            MAX_MEMORY = 2048 KB,
            EVENT_RETENTION_MODE = NO_EVENT_LOSS,
            MAX_DISPATCH_LATENCY = 3 SECONDS,
            MAX_EVENT_SIZE = 0 KB,
            MEMORY_PARTITION_MODE = NONE,
            TRACK_CAUSALITY = OFF,
            STARTUP_STATE = OFF
        );'

EXEC (@cmd)

This creates an event that can be fired after every statement completion, this is done dynamicly to filter on the database

Then I have 3 procedures that make controlling this event easy

/*******************************************************************************************
    Starts the statement trace
*******************************************************************************************/
CREATE OR ALTER PROC testMSSQL.Private_StartTrace
AS
BEGIN 
    ALTER EVENT SESSION testMSSQLTrace
          ON SERVER
        STATE = START; 
END
GO

/*******************************************************************************************
    Ends the statement trace, this also clears the trace
*******************************************************************************************/
CREATE OR ALTER PROC testMSSQL.Private_StopTrace
AS
BEGIN
    ALTER EVENT SESSION testMSSQLTrace
          ON SERVER
        STATE = STOP; 
END
GO


/*******************************************************************************************
    Saves the statements trace
*******************************************************************************************/
CREATE OR ALTER PROC testMSSQL.Private_SaveTrace
AS
BEGIN
    DECLARE @xml XML;

    SELECT @xml = CAST(xet.target_data AS xml)
        FROM sys.dm_xe_session_targets AS xet INNER JOIN sys.dm_xe_sessions AS xe ON (xe.address = xet.event_session_address)  
        WHERE xe.name = 'testMSSQLTrace'  

    INSERT INTO testMSSQL.StatementInvocations (testProcedure, procedureName, lineNumber, statement)
        SELECT testMSSQL.GetCurrentTest(), 
            OBJECT_NAME(T.c.value('(data[@name="object_id"]/value)[1]', 'int')),
            T.c.value('(data[@name="line_number"]/value)[1]', 'int'), 
            T.c.value('(data[@name="statement"]/value)[1]', 'VARCHAR(900)')
        FROM @xml.nodes('RingBufferTarget/event') T(c)
        WHERE T.c.value('(data[@name="nest_level"]/value)[1]', 'int') > 3

END
GO

These procedures respectivly start and stop the trace and the last one stores the result in a table where it filters on the nest level so my own code is not traced.

Finally I use it a bit like this:

start trace
start tran/savepoint
run SetUp (users code)
run test (users code)
save trace
save trace to variable
rollback tran (also catch errors and stuff like that)
save variable back to table so the trace is not rolled back

Special thanks to @Jeroen Mosterd for originally coming up with a proposal for this solution in this SQL Server: How to parse code into its different statements SO post

Answer 2

You can either:

• Add a @DEBUG parameter to each stored procedure you call, or
• Log everything you want, or
• Only log when you want.

With the @Debug parameter, you can default it to OFF, then call it with ON when you want to trace your statements, with the following code:

IF (@Debug = 1) PRINT 'your tracing information goes here';

If you want to log everything, create a log table and insert a row into it wherever you need to know which statement was executed, such as:

DECLARE @log AS TABLE (msg VARCHAR(MAX));

and

INSERT INTO @log VALUES('your tracing information goes here');

Or you can combine them:

IF (@Debug = 1) INSERT INTO @log VALUES('your tracing information goes here');

Of course these will affect performance even when you don't output/log.