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

lx86

　　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>　　

use master　　
go
　　
create database LogTest
　　
go
　　
use LogTest
　　
go
　　
create table demotable (

　　id int not null>　　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>　　
go
　　

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

select [Current LSN], [Operation], [Transaction>[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>注意，这里的两页拆分是因为CREATE TABLE插入元数据导致内部元数据表的页拆分，而不是用户表。
　　在第一个INSERT事务后接着一个事务Allocate Root。正常情况，创建表时，不会分配页给它。第一个INSERT会触发分配第一个页配给表。分配操作由单独的事务完成，并且会立即提交。即使触发页分配的那个INSERT事务被回滚或者延迟提交，也不会影响其它的数据插入操作。从这里也可以看出，一个会话中，可以开始和提交独立于会话主事务之外的事务的，只是这个功能没有提供给T-SQL，只是内部使用。
　　Transaction SID 列表示启动事务的登录名的SID，可以用SUSER_SNAME()函数获取到实际的登录名。

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

select [Current LSN], [Operation],
　　[AllocUnitName], [Page>　　[Lock Information],
　　[Num Elements], [RowLog Contents 0], [RowLog Contents 1],
　　[RowLog Contents 2]
　　
from fn_dblog(null, null)

　　
where [Transaction>　　

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

　　数据修改操作(如LOP_INSERT_ROWS)总是会记录它操作的物理内容(PageID,SlotID)和对象：分配单元(Allocation Unit>　　

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>　　

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

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值。碰撞的概率是非常低的，如果发生， 上面的查询会返回多行。

总结

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