Archive

Archive for the ‘Transaction Log’ Category

Tracking Transaction Log Records With SQL Server 2012 Extended Events

29/01/2013 Leave a comment

Last week I tested sqlserver.transaction_log event in SQL Server 2012 SP1 CU2. I wanted to compere results from fn_dblog() and transaction_log event. Jonathan Kehayias (blog|twitter) wrote here about this event while SQL Server 2012 was in CTP1.
At that time, there were 70 Log Operations and 29 Contexts for those operations available in SQL Server Denali CTP1. (Information taken from Jonathan’s post)

 In SQL Server 2012 SP1 CU2 there are 73 Log Operations and 32 Contexts for those operations.
Description for transaction_log event is: “Occurs when a record is added to the SQL Server transaction log. This is a very high volume event that will affect the performance of the server. Therefore, you should use appropriate filtering to reduce the number of events, and only use this event for targeted troubleshooting during a short time period.”

From description transaction_log event should capture all log records that will be written to transaction log file. So I expected same number of log operations returned from transaction_log event and fn_dblog() function. Let’s confirm that.

For testing I will create database TruncateDb and set database to simple recovery mode so the log clears out on CHECKPOINT. Then I will create a table and insert 1 record in it. I will create event session named TransactionLog to capture the sqlserver.transaction_log event for the database TruncateDb and to store events to the file C:\XELogs\TransactionLog.xel.

CREATE DATABASE TruncateDb;
GO
USE TruncateDb;
GO
ALTER DATABASE TruncateDb SET RECOVERY SIMPLE;
GO

-- Create table
CREATE TABLE dbo.t1 (c1 INT IDENTITY(1,1), c2 CHAR (8000));
GO
-- Insert 1 record
INSERT INTO dbo.t1(c2)
SELECT 'a';
GO

-- Create Xevent session
DECLARE @sqlcmd nvarchar(2000) = '
CREATE EVENT SESSION [TransactionLog] ON SERVER
ADD EVENT sqlserver.transaction_log(
    ACTION(package0.event_sequence)
    WHERE ([database_id]=('+ cast(DB_ID() as varchar(3))+')))
ADD TARGET package0.event_file(SET filename=N''C:\XELogs\TransactionLog.xel'')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,
STARTUP_STATE=OFF)'
EXEC (@sqlcmd)
GO

When the event session is created, I will execute CHECKPOINT on the database so that transaction log clears out and fn_dblog() function will return only 3 records.

-- clear the log
CHECKPOINT;
GO
-- returns only 3 records
SELECT * FROM fn_dblog (NULL, NULL);
GO

checkpoint

Then I’ll start event session, truncate table t1 and stop event session TransactionLog.

--Start session
ALTER EVENT SESSION TransactionLog
ON SERVER
STATE=START;
GO
USE TruncateDb;
GO
-- Truncate table
TRUNCATE TABLE t1;
GO
--Stop session
ALTER EVENT SESSION TransactionLog
ON SERVER
STATE=STOP
GO

Now I can query data from event file and compare it with records from fn_dblog().

-- records from fn_dblog()
SELECT [Current LSN], Operation, Context, [Xact ID], [Transaction ID], [Log Record Fixed Length],
[Log Record Length], [Log Reserve], AllocUnitId
FROM fn_dblog (NULL, NULL);

-- records from transaction_log event
SELECT 
    XEvent.value('(event/@name)[1]', 'varchar(50)') AS event_name,
	XEvent.value('(event/data[@name="operation"]/text)[1]', 'nvarchar(100)') as log_op_name,
    XEvent.value('(event/data[@name="transaction_id"]/value)[1]', 'int') as transaction_id,
	XEvent.value('(event/data[@name="log_record_size"]/value)[1]', 'nvarchar(100)') as log_record_size,
	XEvent.value('(event/data[@name="context"]/text)[1]', 'nvarchar(20)') as context,
	XEvent.value('(event/data[@name="replication_command"]/value)[1]', 'int') as replication_command,
	XEvent.value('(event/data[@name="alloc_unit_id"]/value)[1]', 'nvarchar(100)') as alloc_unit_id,
	XEvent.value('(event/data[@name="transaction_start_time"]/value)[1]', 'datetime2') as transaction_start_time
FROM (
	SELECT CAST(event_data AS XML) AS XEvent
	FROM sys.fn_xe_file_target_read_file('C:\XELogs\TransactionLog*.xel',null,null,null) )as src 
ORDER BY XEvent.value('(event/action[@name="event_sequence"]/value)[1]', 'int')

fn_dblog()

transaction_log

First 3 records from fn_dblog() are generated by CHECKPOINT and they aren’t included in event session file because I started event session after checkpoint. The first record from event file is LOP_BEGIN_XACT with transaction_id = 74018. It correspond to the [Xact ID] of LOP_BEGIN_XACT log record returned in row 4 of the fn_dblog().

We can see that event session file returns only 12 records while we have 16 records from fn_dblog() after checkpoint. We can see that LOP_COUNT_DELTA operations missing from event session file.

If we select only LOP_COUNT_DELTA operations from fn_dblog() we can see that LOP_COUNT_DELTA operations are used for updating system catalog and that Transaction ID is different (0000:00000000).

SELECT [Current LSN], Operation, Context, [Transaction ID], 
AllocUnitId, AllocUnitName
FROM fn_dblog (NULL, NULL)
WHERE Operation ='LOP_COUNT_DELTA'

LP_COUNT_DELTA

Although descriptions says that transaction_log event capture all log records that will be written to transaction log file it isn’t true. I also tested transaction_log event with INSERT statements and noticed that transaction_log event didn’t capture:

non-transactional updates

It seems that transaction_log event doesn’t capture log records with Transaction ID=0000:00000000. These log records are not part of transactional updates (called being non-transactional – thanks Paul Randal for naming it here).