如何解读SQL Server日志(1/3)

SQL Server 的事务日志包含所有数据修改的操作记录。分析日志一般作为解决某些问题的最后手段，如查看某些意外的修改。理解和分析日志内容是件非常困难的事情，fn_dblog通常会输出非常多的数据，查看也比较困难。我尝试用一些实例帮助大家更好地分析和理解日志。

SQL Server 使用Write-ahead logging (WAL)方式保证任何数据变更的日志要比数据变更先发生。同时，对数据库中任何数据变更操作都会被记录在日志中。注意所有的数据对象(tables, views, stored procedures, users, permissions etc)是元数据，但是也数据。所以对数据库中任何对象的变更操作都会被记录在日志中。注意，像最小化日志操作、大容量日志操作和Truncate(谣传的“无日志操作”)都是事务性的，都会记录在日志中。

事务日志中的每一条日志记录由LSN(Log Sequence Number)唯一标识。LSN是有序的，如果LSN2大于LSN1,则LSN2的日志所代表的数据修改操作发生在LSN1之后。

下面用一个例子来开始分析。将使用未公开的函数sys.fn_dblog，它能够读取当前数据库活动部分的事务日志。此函数返回的 [Transaction ID] 字段表示SQL Server 为每个事务分配的事务ID，同一个事务所有的日志记录具有一样的事务ID。

use master 
go
create database LogTest
go
use LogTest
go
create table demotable (
	id int not null identity(1,1) primary key, 
	data char(20), 
	created_at datetime default getutcdate());
go

insert into demotable (data) values ('standalone xact');
go 5


begin transaction
go

insert into demotable (data) values ('one xact');
go 5

commit;
go

delete from demotable
where id in (2,5,6,9);
go

sys.fn_dblog返回的[operation]表示进行的是什么操作，我们先看看一个非常重要的操作： LOP_BEGIN_XACT。它标记一个事务的开始，也是日志中唯一包含事务开始时间的记录，同时还包含发出语句用户的SID。

select [Current LSN], [Operation], [Transaction ID], [Parent Transaction ID],
	[Begin Time], [Transaction Name], [Transaction SID]
from fn_dblog(null, null)
where [Operation] = 'LOP_BEGIN_XACT'

SQL Server总是对数据操作使用事务，不管是用户定义的显示事务或者是自动的隐式事务。 LSN:00000023:00000033:0001开始事务0000:00000352，事务名叫做CREATE TABLE。LSN开始了INSERT事务0000:00000356，这就是脚本中的5个单独的INSERT语句，每个INSERT是一个隐式事务。它还还包括事务0000:00000359，0000:0000035a，0000:0000035b，0000:0000035c。观察事务ID，会发现者是按1增长的16进制数。再看LSN 00000023:00000061:0001的事务0000:0000035d，它叫做user_transaction。这是脚本中用户定义的INSERT的显式事务。它从BEGIN TRANSACTION开始，包括了5个INSERT，而不像之前产生5个INSERT隐式事务。最后LSN 00000023:00000070:0001开始了DELETE事务0000:00000360。

还发现有两个SplitPage的Parent Transaction ID等于CREATE TABLE的事务ID。页拆分是B-TREE根据排序键维护数据顺序的一种方式。注意，这里的两页拆分是因为CREATE TABLE插入元数据导致内部元数据表的页拆分，而不是用户表。

在第一个INSERT事务后接着一个事务Allocate Root。正常情况，创建表时，不会分配页给它。第一个INSERT会触发分配第一个页配给表。分配操作由单独的事务完成，并且会立即提交。即使触发页分配的那个INSERT事务被回滚或者延迟提交，也不会影响其它的数据插入操作。从这里也可以看出，一个会话中，可以开始和提交独立于会话主事务之外的事务的，只是这个功能没有提供给T-SQL，只是内部使用。

Transaction SID 列表示启动事务的登录名的SID，可以用SUSER_SNAME()函数获取到实际的登录名。

观察一个事务的详细日志内容

select [Current LSN], [Operation], 
	[AllocUnitName], [Page ID], [Slot ID], 
	[Lock Information],
	[Num Elements], [RowLog Contents 0], [RowLog Contents 1], 
	[RowLog Contents 2]
from fn_dblog(null, null)
where [Transaction ID]='0000:00000356'

我们来看看第一个INSERT事务：356的详细日志内容。很明显，356事务有4条日志。每个事务必须以LOP_BEGIN_XACT开始，以一条日志结，通常是LOP_COMMIT_XACT。还有一条关于锁的日志(LOP_LOCK_XACT)和一条关于实际数据修改的日志(LOP_INSERT_ROWS)。

数据修改操作(如LOP_INSERT_ROWS)总是会记录它操作的物理内容(PageID,SlotID)和对象：分配单元(Allocation Unit ID)和分区ID(Partition ID)。查看AllocUnitName列是确定哪一个对象被修改的最简单的方式。Page ID 和Slot ID告诉我们哪个页的哪一个槽位被事务修改了。16进制90=144十进制，0=0。我们通过DBCC PAGE来看看144页的Slot 0。

dbcc traceon(3604,-1);
dbcc page(7,1,144,3);
------------------------------------------------------------------------
Slot 0 Offset 0x60 Length 39

Record Type = PRIMARY_RECORD        Record Attributes =  NULL_BITMAP    Record Size = 39

Memory Dump @0x00000000117AA060

0000000000000000:   10002400 01000000 7374616e 64616c6f 6e652078  ..$.....standalone x
0000000000000014:   61637420 20202020 797d6f00 64a60000 030000    act     y}o.d......

Slot 0 Column 1 Offset 0x4 Length 4 Length (physical) 4

id = 1                              

Slot 0 Column 2 Offset 0x8 Length 20 Length (physical) 20

data = standalone xact              

Slot 0 Column 3 Offset 0x1c Length 8 Length (physical) 8

created_at = 2016-08-16 06:45:55.390

Slot 0 Offset 0x0 Length 0 Length (physical) 0

KeyHashValue = (8194443284a0)       
Slot 1 Offset 0xae Length 39

从输出的页，我们确定144页的Slot 0 的确存储着第一个INSERT的内容，也佐证了sys.fn_dblog内容是正确的。日志中的这部分内容可以帮助我们解决一个问题：现在知道某个行的位置(页ID和槽ID)，想要找出是哪一个事务修改了这一行？可以通过搜索日志记录中的Slot ID和Page ID找到相关事务。但是，这个方法对于B-TREE来说是非常困难的。因为B-TREE发生页拆分时会改变行的物理地址，在匹配时就会很困难了。

Lock Information列的完整内容：

HoBt 72057594039042048:ACQUIRE_LOCK_IX OBJECT: 7:245575913:0 ;
ACQUIRE_LOCK_IX PAGE: 7:1:144 ;
ACQUIRE_LOCK_X KEY: 7:72057594039042048 (8194443284a0)

其中有表的Object ID，页ID和索引键的键锁信息。对于B-TREE，键锁就是键值的HASH值，所以通过它能定位到数据行(就算发生页拆分，但是键值是不会变的)。

select %%lockres%%, *
from demotable
where %%lockres%% = '(8194443284a0)';

                      id          data                 created_at
--------------- --------- -------------------- -----------------------
(8194443284a0)        1          standalone xact      2016-08-16 06:45:55.390

通过键锁信息，我们正确定位到第一个INSERT的行。注意，HASH值存在HASH碰撞的可能，即不同的键值生成了同样的HASH值。碰撞的概率是非常低的，如果发生， 上面的查询会返回多行。

总结

1. 原文地址：How to read and interpret the SQL Server log ，非逐字翻译，在自己理解的基础上的意译，有增和删内容。
2. 解析日志内容，通常只会在少数特殊的场景用到，但会对SQL Server的理解有帮助。