Create Trigger to log SQL that affected table?

Question

I'm trying to find out what is updating the value of a column and i have very little knowledge of the application. At a quick glance I've noticed about 90% of the applications business logic is handled on the database. Needless to say the depth of SP's, functions, and triggers is crazy.

I'd like to create a trigger on the table in question that will log the SQL that affected the table. What SQL could be used to grab the executed SQL in the context of the table being updated?

Details: MS SQL Server 2008

Thanks!!

Answer 1

My Solution

I added a trigger on the table in question that logged information i narrowed down via timestamps from sys.dm_exec_sql_text AND sys.dm_exec_query_stats. This quickly nailed down what i was looking for. Turns out there were a few triggers i didn't know about that were updating data after a UPDATE.

SELECT 
    qStats.last_execution_time AS [ExecutedAt],
    qTxt.[text] AS [Query], qTxt.number
FROM
    sys.dm_exec_query_stats AS qStats
    CROSS APPLY
    sys.dm_exec_sql_text(qStats.sql_handle) AS qTxt
WHERE
    qTxt.[dbid] = @DbId
    AND qTxt.[text] like '%UPDATE%'
    AND qStats.last_execution_time between @StartExecutionSearchTime and @EndExecutionSearchTime
ORDER BY
    qStats.last_execution_time DESC 

Answer 2

I realise this issue has already been resolved but I was interested in how it could be resolved using SQL Server 2008 extended events. This is my first play with XEvents so I'm sure there's lots to improve!

Script to setup test Database

CREATE TABLE [dbo].[TableWithMysteryUpdate](
    [Period] [int] NOT NULL,
    [ColumnThatWillBeUpdated] [int]  NOT NULL
) ON [PRIMARY]
GO
INSERT [dbo].[TableWithMysteryUpdate] ([Period], [ColumnThatWillBeUpdated]) VALUES (1, 20)
INSERT [dbo].[TableWithMysteryUpdate] ([Period], [ColumnThatWillBeUpdated]) VALUES (2, 23)

GO

CREATE TABLE [dbo].[TestTable](
    [foo] [int] IDENTITY(1,1) NOT NULL,
    [bar] [nchar](10) NOT NULL,
 CONSTRAINT [PK_TestTable] PRIMARY KEY CLUSTERED 
(
    [foo] ASC
)
)
GO

CREATE TRIGGER [dbo].[triggerCausingMysteryUpdate] 
   ON  [dbo].[TestTable] 
   AFTER INSERT
AS 
BEGIN
    SET NOCOUNT ON;
UPDATE [dbo].[TableWithMysteryUpdate]
   SET [Period] = [Period]+1

END
GO

CREATE PROCEDURE [dbo].[Proc4]
AS
BEGIN
INSERT INTO [dbo].[TestTable]
           (
           [bar])
     VALUES
           ('Test')
END

GO

CREATE PROCEDURE [dbo].[Proc3]
AS
BEGIN
EXEC dbo.Proc4
END
GO

CREATE PROCEDURE [dbo].[Proc2]
AS
BEGIN
EXEC dbo.Proc3
END
GO

CREATE PROCEDURE [dbo].[Proc1]
AS
BEGIN
EXEC dbo.Proc2
END

So the scenario is that TableWithMysteryUpdate is being updated but I'm not sure by what. I'll add an update trigger that does nothing in order to be able to filter on this object.

CREATE TRIGGER [dbo].[triggerAfterUpdate] 
   ON  [dbo].[TableWithMysteryUpdate] 
   AFTER UPDATE
AS 
BEGIN
    SET NOCOUNT ON;

END

Then run the script to create the XEvents Session, fire the procedure that will eventually down the call stack cause the Update to occur, and then stop the session.

USE TestDB    

DECLARE @DynSql nvarchar(max)

SET @DynSql = '

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name=''test_trace'')
    DROP EVENT SESSION [test_trace] ON SERVER;
CREATE EVENT SESSION [test_trace]
ON SERVER
ADD EVENT sqlserver.sql_statement_completed(
     ACTION (package0.callstack, sqlserver.session_id, sqlserver.sql_text, sqlserver.tsql_stack)
     WHERE (object_id = ' + cast(object_id('[dbo].[triggerAfterUpdate]') as varchar(10)) + ') 
     )
,
ADD EVENT sqlserver.sp_statement_completed(
     ACTION (package0.callstack, sqlserver.session_id, sqlserver.sql_text, sqlserver.tsql_stack)
     WHERE (object_id = ' + cast(object_id('[dbo].[triggerAfterUpdate]') as varchar(10)) + ') 
     )
ADD TARGET package0.asynchronous_file_target
(set filename = ''c:\temp\test_trace.xel'' , metadatafile = ''c:\temp\test_trace.xem'')
ALTER EVENT SESSION [test_trace] ON SERVER STATE = START
'

EXEC sp_executesql @DynSql
GO

EXEC  dbo.Proc1

GO

ALTER EVENT SESSION [test_trace] ON SERVER STATE = STOP

The trace data can be read with

SELECT CONVERT (XML, event_data) AS data
        FROM sys.fn_xe_file_target_read_file ('C:\Temp\test_trace*.xel', 'C:\Temp\test_trace*.xem', NULL, NULL)

The call stack part is

 <action name="tsql_stack" package="sqlserver">
    <value>&lt;frame level='1' handle='0x03000800E8EA0D0612E4EB00A59D00000000000000000000' line='6' offsetStart='228' offsetEnd='264'/&gt;
&lt;frame level='2' handle='0x03000800921155002C81E700A59D00000000000000000000' line='8' offsetStart='258' offsetEnd='398'/&gt;
&lt;frame level='3' handle='0x03000800CB3549012F81E700A59D00000100000000000000' line='5' offsetStart='90' offsetEnd='284'/&gt;
&lt;frame level='4' handle='0x03000800045A3D022F81E700A59D00000100000000000000' line='5' offsetStart='90' offsetEnd='120'/&gt;
&lt;frame level='5' handle='0x030008003D7E31033081E700A59D00000100000000000000' line='5' offsetStart='90' offsetEnd='120'/&gt;
&lt;frame level='6' handle='0x0300080076A225043081E700A59D00000100000000000000' line='5' offsetStart='90' offsetEnd='120'/&gt;
&lt;frame level='7' handle='0x010008002E775203603D9A0D000000000000000000000000' line='2' offsetStart='4' offsetEnd='-1'/&gt;</value>
    <text />
  </action>

Joining onto the DMVs

WITH CapturedResults AS
    ( SELECT data.value ( '(/event/@timestamp)[1]', 'DATETIME')                                        AS [TIME],
        data.value ( '(/event/data[@name=''cpu'']/value)[1]', 'INT')                                   AS [CPU (ms)],
        CONVERT (FLOAT, data.value ('(/event/data[@name=''duration'']/value)[1]', 'BIGINT')) / 1000000 AS [Duration (s)],
        data.value ( '(/event/action[@name=''sql_text'']/value)[1]', 'VARCHAR(MAX)')                   AS [SQL STATEMENT],
        CAST(data.value('(/event/action[@name="tsql_stack"]/value)[1]','varchar(MAX)') AS XML)         AS [stack_xml]
    FROM (SELECT CONVERT (XML, event_data) AS                                                             data
        FROM sys.fn_xe_file_target_read_file ('C:\Temp\test_trace*.xel', 'C:\Temp\test_trace*.xem', NULL, NULL)
        )
        entries
    )
    ,
    StackData AS
    ( SELECT frame_xml.value('(./@level)', 'int')      AS [frame_level],
        frame_xml.value('(./@handle)', 'varchar(MAX)') AS [sql_handle],
        frame_xml.value('(./@offsetStart)', 'int')     AS [offset_start],
        frame_xml.value('(./@offsetEnd)', 'int')       AS [offset_end]
    FROM CapturedResults CROSS APPLY stack_xml.nodes('//frame') N (frame_xml)
    )
SELECT sd.frame_level,
    object_name(st.objectid, st.dbid) AS ObjectName,
    SUBSTRING(st.text, (sd.offset_start/2)+1, ((
            CASE sd.offset_end
                WHEN -1
                THEN DATALENGTH(st.text)
                ELSE sd.offset_end
            END - sd.offset_start)/2) + 1) AS statement_text,
    qp.query_plan,
    qs2.creation_time,
    qs2.last_execution_time,
    qs2.execution_count
FROM StackData AS sd CROSS APPLY sys.dm_exec_sql_text(CONVERT(VARBINARY(MAX),sd.sql_handle,1)) AS st
    LEFT OUTER JOIN sys.dm_exec_query_stats qs2
    ON  qs2.sql_handle = CONVERT(VARBINARY(MAX),sd.sql_handle,1) OUTER APPLY sys.dm_exec_query_plan(CONVERT(VARBINARY(MAX),qs2.plan_handle,1)) AS qp

gives results (showing the whole tsql call stack)

Answer 3

Besides using triggers that will be fired when a data change occurs, you can use SQL Server traces and analyse them in SQL Profiler, or a third party auditing tool that tracks executed code for DML changes.

Using ApexSQL Comply you can narrow down the auditing only the the specific database object (table in this case) and event type.

The reports show various useful info, including the SQL statement executed that initiated the change.

Disclaimer: I work for ApexSQL as a Support engineer

Answer 4

Please vote for this Microsoft Connect item, and have a look at this call stack workaround.

Answer 5

SQL Server 2008 introduced a new feature called Change Data Capture (CDC), rather than use triggers. Read more about it here.