SQL Server fn_dblog – An interesting observation

Hi Friends,

I was experimenting with SQL Server fn_dblog function (undocumented and unsupported). This function allows you to read the active portion of the log file.

This is what I observed:

For an update transaction, the column “RowLog Contents 1” contains hex value of the entire record in case the table has variable length columns, but in case the table has only fixed length columns, it only contains the hex value of the column which is being modified.

Let me explain:

I create a database, two tables, and insert one record each:

select * from sqlmaestros
-- setup
create database fn_dblog_test
go
use fn_dblog_test
go
create table sqlservergeeks
(id int, firstname char(6), lastname varchar(6))
create table sqlmaestros
(id int, firstname char(6), lastname char(6))

insert into sqlservergeeks
(id,firstname)
values(1,'amit')
insert into sqlmaestros
(id,firstname)
values(1,'amit')
-- what does the data look like?
select * from sqlservergeeks

Observe that sqlservergeeks table has lastname column as varchar. The same column in sqlmaestros table is fixed length. And then we have NULL for both of them in our inserts.

Let us observe the DBCC page output for sqlservergeeks table which has variable length column. Note your page number may be different.

DBCC TRACEON(3604)
GO
DBCC IND(fn_dblog_test, 'sqlservergeeks', 1)
GO
DBCC PAGE('fn_dblog_test', 1, 228, 3)
GO

So, you can see the hex value of the record data. For example: 616d6974 represents the hex for ‘amit’. Here is a quick ready reference table:

For sqlmaestros table, which only has fixed length columns, we get a similar output, but there is an extra row for lastname which is fixed length:

DBCC IND(fn_dblog_test, 'sqlmaestros', 1)
GO
DBCC PAGE('fn_dblog_test', 1, 230, 3)
GO

Now, I will fire two update named transactions, for two tables, assigning some value to the lastname column.

begin tran sqlservergeeks
update sqlservergeeks
set lastname='bansal'
where id = 1
commit tran
go
begin tran sqlmaestros
update sqlmaestros
set lastname='bansal'
where id = 1
commit tran
go

And now check the log records for both of these named transaction and compare:

DECLARE @tid char(13)
select @tid=[transaction id] from fn_dblog(null,null)
where [transaction name] = 'sqlservergeeks'
select [RowLog Contents 1] from fn_dblog(null,null)
where [transaction id] = @tid

DECLARE @tid2 char(13)
select @tid2= [transaction id] from fn_dblog(null,null)
where [transaction name] = 'sqlmaestros'
</pre>
<pre class="lang:default decode:true">select [RowLog Contents 1] from fn_dblog(null,null)
where [transaction id] = @tid2

For sqlservergeeks table, the log content includes the entire record (first result set)

In this hex value:
0x30000E0001000000616D6974202003000001001B0062616E73616C

1000000 represents ‘1’
616D6974 represents ‘amit’
62616E73616C represents ‘bansal’

(Refer the hex table above)
But for sqlmaestros table, the log content includes only the value for the modified column

In this hex value:
0x62616E73616C030000

62616E73616C represents ‘bansal’

So the observation here is: “RowLog Contents 1” contains hex value of the entire record in case the table has variable length column(s), but in case the table has only fixed length column(s), it only contains the hex value of the column which is being modified.

Why so? Well, I do not have a very crystal clear explanation for this, but I guess this is for performance reasons, since for a table with only fixed length columns the offsets are fixed and reconstruction of the row is fast and transaction log need not have the entire row. However, in case of variable-length data, the offsets can change depending on the data and reconstruction may require extra work, so if the transaction log has the entire row, the work gets done quickly. Just my thought, but I may be wrong 🙂