Archive

Archive for January, 2013

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).

T-SQL Tuesday #38 – Standing Firm

08/01/2013 Leave a comment

TSQL2sday

Today’s T-SQL Tuesday is hosted by Jason Brimhall (blog|twitter). The topic this month is “Standing Firm”. This means that I should write something related to one of these words: resolve, resolution, or resolute.

It’s the time of year when many people make New Year’s resolutions and this is the first time I will make a three related to SQL Server:  to write more blog posts about SQL Server,  to do more local community speaking about SQL Server and to learn more about AlwaysOn, Performance Tuning and PowerShell.

Before a year and a half I started with writing a blog which is related to SQL Server and till now I wrote 28 posts. But only 5 of them I wrote last year.  I started to write a few blog posts last year but I never finished them.  Topics I’ve chosen for these posts were very complex and I never had time to finish them. Maybe it’s time to try a different tactic – writing about simple topics or writing more posts about complex topic (like blog post series).

I spoke once in local MS Community about SQL Server Policy Based Management and had very positive feedback. That was excellent experience and I want to more actively participate in our local user group. I will try to speak at least 2 times this year.

I always try to learn something new and this time I want to go further with AlwaysOn and Performance Tuning areas of SQL Server. I used PowerShell several times and I can say that it can be a powerful tool in the hands of DBA. I can even try to write a blog post series on these topics.

With this post I made a lot of firsts: the first blog post this year, the first time I am participating in T-SQL Tuesday and the first time I made SQL Server resolution. 🙂

Categories: T-SQL Tuesday