An XEvent a Day (22 of 31) – The Future – fn_dblog() No More? Tracking Transaction Log Activity in Denali

I bet that made you look didn’t it?  Worry not, fn_dblog() still exists in SQL Server Denali, and I plan on using it to validate the information being returned by a new Event in SQL Server Denali CTP1, sqlerver.transaction_log, which brings with it the ability to correlate specific transaction log entries to the operations that actually caused them to occur.

There is no greater source of information about the transaction log in SQL Server than Paul Randal’s blog category Transaction Log.  It is also listed as the referenced pre-reading material for the Microsoft SQL Server MCM program Logging, Recovery, Log Maintenance topic.  In a number of his blog posts, Paul shows how to look at the transaction log by using an undocumented system function fn_dblog().  Note that I said it is undocumented, meaning its use is not supported by Microsoft, its functionality is subject to change at any point in time without notification, and its use is at your own risk.  Is it safe to use?  That’s a topic that is up for debate, but at the end of the day if you were to have a problem associated with its use you are on your own because its undocumented.

Why does any of this matter?  It matters because there is a lot of information that we can learn about the internal operations of SQL Server from the log operations that occur as the result of changes in our database.  Some examples of this would be:

A SQL Server DBA myth a day: (19/30) TRUNCATE TABLE is non-logged
Benchmarking: 1-TB table population (part 2: optimizing log block IO size and how log IO works)
Lock logging and fast recovery
How do checkpoints work and what gets logged
Finding out who dropped a table using the transaction log

Admittedly this isn’t necessarily information that you would start a conversation with at a party, unless of course you are surrounded by other ubergeeks SQL Server internal junkies, and its not really the kind of information that I use day to day in my work as a Database Administrator.  Prior to the introduction of Extended Events, some information about how SQL Server operated was only available inside of the transaction log records, and I am sure that there are still some items that you can only see inside of the log records.  Microsoft obviously recognized a demand to look the log operations generated by SQL Server in a supported fashion and added this functionality to Extended Events.

The sqlserver.transaction_log Event returns 10 data elements in its payload, which can be found in the sys.dm_xe_object_columns DMV.

SELECT 
    oc.name, 
    oc.type_name, 
    oc.description
FROM sys.dm_xe_packages AS p
INNER JOIN sys.dm_xe_objects AS o
    ON p.guid = o.package_guid
INNER JOIN sys.dm_xe_object_columns AS oc
    ON oc.object_name = o.name
        AND oc.object_package_guid = o.package_guid
WHERE o.name = 'transaction_log'
  AND oc.column_type = 'data'

The operation and context elements have corresponding Maps in sys.dm_xe_map_values that provide the different Log Operations and Contexts that are available through Extended Events.  There are currently 70 Log Operations and 29 Contexts for those operations available in SQL Server Denali CTP1. 

SELECT 
    name,
    map_key,
    map_value
FROM sys.dm_xe_map_values
WHERE name in ('log_op', 'log_context')
ORDER BY name, map_key

To show how this Event can be used, we’ll first create a database named TransactionLogDemo, and then switch our connection to that database.  We’ll then create an table that will be used to generate some Transaction Log events.  We’ll create our Event Session to capture the sqlserver.sql_statement_starting, sqlserver.sql_statement_completed, and sqlserver.transaction_log Events and we’ll add a Predicate to each Event to only fire for the TransactionLogDemo database.  To add the Predicate dynamically, we’ll use Dynamic SQL to create our Event Session since inline parameters cannot be used in the CREATE EVENT SESSION DDL. 

CREATE DATABASE TransactionLogDemo
GO
USE TransactionLogDemo
GO
CREATE TABLE CreateLogRecords
(RowID int identity primary key,
 RowData nvarchar(120))
GO
DECLARE @sqlcmd nvarchar(2000) = '
CREATE EVENT SESSION TransactionLogDemo
ON SERVER
ADD EVENT sqlserver.page_reference_tracker,
ADD EVENT sqlserver.sql_statement_starting
( ACTION(sqlserver.sql_text)
  WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')
),
ADD EVENT sqlserver.sql_statement_completed
( ACTION(sqlserver.sql_text)
  WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+')
),
ADD EVENT sqlserver.transaction_log
( WHERE (sqlserver.database_id = '+ cast(DB_ID() as varchar(3))+'))
ADD TARGET package0.asynchronous_file_target(
     SET filename=''C:\SQLBlog\TransactionLogDemoDenali.xel'',
         metadatafile=''C:\SQLBlog\TransactionLogDemoDenali.xem'')
WITH (MAX_MEMORY = 4MB, EVENT_RETENTION_MODE = NO_EVENT_LOSS, TRACK_CAUSALITY = ON )'
EXEC (@sqlcmd)
GO
CHECKPOINT
GO
-- Start the Event Session
ALTER EVENT SESSION TransactionLogDemo
ON SERVER
STATE=START
GO

Once the Event Session is created, we’ll call CHECKPOINT on the database so that the log can truncate (you did create the database in SIMPLE recovery right?) and clear allowing our later call to fn_dblog() to only return the log records specific to the operations that occur after the CHECKPOINT.  We’ll start our Event Session, and then insert 20 rows into the CreateLogRecords table, and then immediately delete all of the rows from the table, and stop our Event Session to end the collection of Events.

INSERT INTO CreateLogRecords (RowData)
SELECT REPLICATE('abc123', 20)
FROM master.dbo.spt_values a
WHERE a.type = 'P'
  AND a.number < 20
GO
DELETE CreateLogRecords
GO
-- Disable the Event Session
ALTER EVENT SESSION TransactionLogDemo
ON SERVER
STATE=STOP
GO

Once this is done, we can now query the package0.asynchronous_file_target to get our Event data from Extended Events, and then at the same time query fn_dblog() to get the log records from the Transaction Log as well so that we can validate what we’ve collected in our Event Session.

-- Fetch the Event Data from the Event Session Target
SELECT 
    XEvent.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            XEvent.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    COALESCE(XEvent.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
             XEvent.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
    XEvent.value('(event/data[@name="index_id"]/value)[1]', 'int') AS [index_id],
    XEvent.value('(event/data[@name="object_id"]/value)[1]', 'int') AS [object_id],
    XEvent.value('(event/data[@name="transaction_id"]/value)[1]', 'int') AS [transaction_id],
    XEvent.value('(event/data[@name="log_record_size"]/value)[1]', 'int') AS [log_record_size],
    XEvent.value('(event/data[@name="operation"]/text)[1]', 'varchar(50)') AS [operation],
    XEvent.value('(event/data[@name="context"]/text)[1]', 'varchar(50)') AS [context],
    XEvent.value('(event/data[@name="transaction_start_time"]/value)[1]', 'datetime2') AS [transaction_start_time],
    XEvent.value('(event/data[@name="replication_command"]/value)[1]', 'int') AS [replication_command],
    XEvent.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(1000)') AS [sql_text],
    CAST(SUBSTRING(XEvent.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier) as activity_id,
    CAST(SUBSTRING(XEvent.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int) as event_sequence
FROM (
    SELECT CAST(event_data AS XML) AS XEvent
    FROM sys.fn_xe_file_target_read_file('C:\SQLBlog\TransactionLogDemoDenali*.xel', 'C:\SQLBlog\TransactionLogDemoDenali*.xem', null, null)) as src
ORDER BY 
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            XEvent.value('(event/@timestamp)[1]', 'datetime2')),
    CAST(SUBSTRING(XEvent.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 1, 36) AS uniqueidentifier),
    CAST(SUBSTRING(XEvent.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)'), 38, 10) AS int)
GO

-- Fetch Log records from log for comparison
SELECT 
    [Xact ID] as transaction_id, 
    [Log Record Fixed Length] as log_record_size, 
    [Operation] as operation, 
    SUBSTRING([context], 5, LEN(context)) as context, 
    [Begin Time]
FROM fn_dblog(null, null) 
GO

When we look at the output of the above two queries, first you’ll note that there are four log records that don’t have associated records in our Extended Event Session.  These are the log records generated by the CHECKPOINT operation and the ALTER EVENT SESSION command and occurred before the Event Session was actually collecting data.  The first two LOP_BEGIN_XACT records in the Event Session correspond to the transaction_id of the log records returned in rows 5 and 6 of the fn_dblog() output, but if you notice the Event Session is missing the transaction_start_time for the log operations, something I believe to be a bug in Denali CTP1 and which I’ve submitted a Connect item for (Denali – Transaction_Log Extended Event Returning Incorrect Data). 

On quick glance it appears that all of our log records are in the same order, but if we look at more closely, there is a LOP_MODIFY_ROW operation that is missing from our Event Session, but exists inside of the fn_dblog() output.

If you scroll down further, you’ll also see that there are two missing log records for the delete as well, LOP_MODIFY_HEAP and LOP_SET_BITS with a context of PFS.  However, the Extended Event Session captures the lock logging for the ALTER EVENT SESSION command that stopped the Event collection, whereas the output from fn_dblog() does not show that.

To cleanup from this Event Session, the following code can be run.

USE master
GO
DROP DATABASE TransactionLogDemo
GO
DROP EVENT SESSION TransactionLogDemo
ON SERVER
GO
EXECUTE sp_configure 'show advanced options', 1
GO
RECONFIGURE
GO
EXECUTE sp_configure 'xp_cmdshell', 1
GO
RECONFIGURE
GO
EXEC xp_cmdshell 'DEL C:\SQLBlog\TransactionLogDemoDenali*'
GO
EXECUTE sp_configure 'xp_cmdshell', 0
GO
RECONFIGURE
GO
EXECUTE sp_configure 'show advanced options', 0
GO
RECONFIGURE
GO