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

bco

　　接下来说说返回的RowLogo Content列，例子中返回了三个列。这些列包含了数据操作的“有效工作负载(Playload)”记录。根据不同操作类型有效负载的内容也是不同的，但是它必须包含足够的信息，能让相应的数据操作在恢复时能被REDO和UNDO。对于每一个INSERT而言，它包含了插入行的所有数据。我们来验证一下，先看看RowLogo Contents 0的内容：
　　

0x10002400010000007374616E64616C6F6E6520786163742020202020797D6F0064A60000030000　　

　　然后再看DBCC PAGE中Slot 0的内容：
　　

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

　　DBCC PAGE输出行的内容被分成了左、中、右三个部分：

• 左：表示对应内容在行内的字符位置(或者起始偏移量)
  
• 中：表示存储在页上实际数据，由5段8位的16进制数组成
  
• 右：实际数据的ASCII表示形式，只有字符数据能够被辨认出来。　　
  BY Joe .TJ
  
  

　　对比RowLogo Contents 0和DBCC PAGE输出Slot 0的中段数据，发现两者数据是一样的。同时证明了LOP_INSERT_ROWS操作的RowLogo Contents 0日志内容包含了完整的被插入数据的内容。然而，通过分析RowLogo Contents的内容去找出某一特定的行，这个是非常困难的事情。如果你熟悉行结构，RowLogo Contents 0 列的内容可以分解为：

• 1000 (列头，2Bytes状态位)
  
• 2400 (2Bytes 列数量值的Offset量，也表示列数量值前有多少字节被使用)
  
• 01000000 (ID列,INT)
  
• 7374616E64616C6F6E6520786163742020202020 (data列，char(20))
  
• 797D6F0064A60000 (created_at列，datetime)
  
• 0300 (列数量,2Bytes)
  
• 　　00 (NULL位图=Ceiling(NULL列数量/8))
  
  

  　　关于行结构的更多内容，参考《SQL Server 2012 Internals》第六章'Table Storage'中的'The structure of data row'部分。行结构图：
  　　
  
  
  

  
  

　　我用几个例子来说明如何使用这些知识帮助我们解决问题。先修改表中的数据：
　　

insert into demotable (data) values ('junk'), ('important'), ('do not change!');　　
update demotable set data='changed' where data = 'do not change!';
　　
update demotable set created_at = getutcdate() where data = 'changed';
　　
delete from demotable where data='important'
　　

　　经过上面的修改，新插入的三行中只有('junk')没有改变。('do not changed')被改成了('change'),创建时间也被改成现在的UTC时间。important行被删除了。我们能否从日志找到这些修改操作对应的日志呢？先从较简单的问题开始

• 找到'junk'相关的日志
  

　　因为'junk'还存在于表中，我们通过找到它的lockres,然后根据lockres去搜索日志中的[Lock Information]，再从匹配的行中[Transaction>　　

--get lockres value of 'junk'　　
declare @lockres nchar(14);
　　
select top(1) @lockres=%%lockres%%
　　
from dbo.demotable
　　
where data='junk';
　　


　　
--Using lockres to find Transaction>　　
declare @xactid nvarchar(14);

　　
select top(1) @xactid=[Transaction>　　
where CHARINDEX(@lockres,[Lock Information] )>0
　　


　　
--get all log record of the found Transaction>
　　
select [Current LSN], [Operation], [Transaction>　　[Transaction SID], [Begin Time], [End Time]  
　　
from sys.fn_dblog(null,null)

　　
where [Transaction>　　


　　
Current LSN             Operation             Transaction>　　
----------------------- ---------------- -------------------- ------------------ ----------------------- ---------
　　
00000023:0000007b:0001  LOP_BEGIN_XACT       0000:00000363     0x01                 2016/08/19 14:50:27:917  NULL
　　
00000023:0000007b:0002  LOP_INSERT_ROWS      0000:00000363     NULL                 NULL                     NULL
　　
00000023:0000007b:0003  LOP_INSERT_ROWS      0000:00000363     NULL                 NULL                     NULL
　　
00000023:0000007b:0004  LOP_INSERT_ROWS      0000:00000363     NULL                 NULL                     NULL
　　
00000023:0000007b:0005  LOP_COMMIT_XACT      0000:00000363     NULL                 NULL            2016/08/19 14:50:27:920
　　

　　使用上面的方法时，我假设了几个前提：

• lockres是唯一的，没有HASH碰撞
  
• 锁定行的第一个事务就是我想找的事务
  

　　在现实中情况不会这么简单：HASH碰撞的问题，可能有很多事务曾锁定过这一行等等。

• 找出把'do not change!'修改成'changed!'的事务
  

　　跟之前的思路差不多，先从表中存的'changed'找到lockres，然后根据lockres找到所有事务ID，然后再找出所有的日志记录。
　　

--get lockres value of the updated 'changed'　　
declare @lockres nchar(14);
　　
select @lockres=%%lockres%%
　　
from dbo.demotable
　　
where data='changed';
　　


　　
--Using lockres to find ALL>　　
declare @xactid table (xid nvarchar(14));
　　
insert into @xactid

　　
select [Transaction>　　
from sys.fn_dblog(null,null)
　　
where CHARINDEX(@lockres,[Lock Information] )>0
　　


　　
--get all log records of the found Transaction>
　　
select [Current LSN], [Operation], [Transaction>　　[Transaction SID], [Begin Time], [End Time],
　　[Num Elements], [RowLog Contents 0], [RowLog Contents 1],
　　[RowLog Contents 2],
　　[RowLog Contents 3], [RowLog Contents 4], [RowLog Contents 5]
　　
from sys.fn_dblog(null,null)as a
　　
join @xactid b
　　
on a.[Transaction>　　

　　从结果可以看到，有2个LOP_MODIFY_ROW操作的日志，怎么知道哪一条日志是我想要找的？在查询时，我增了[Num Elements]列，因为[Num Elements]=6，表示这个操作有6个有效工作负载，所以我增加了和[RowLog Contents 0]到[RowLog Contents 5]这6个字段。这个6个字段中，包含所有的效工作负载。我们之前说过，日志必须包含足够多的信息，才能支持恢复时的REDO和UNDO。也谅是说这个6个有效工作负载包含了修改前后的数据。从LSN=00000023:0000007d:0002的LOP_MODIFY_ROW的[RowLog Contents 0]和[RowLog Contents 1]的有效负载内容，可以看出是ASCII。于是：
　　

select cast(0x646F206E6F74206368616E676521 as char(20)),　　
cast (0x6368616E67656420202020202020 as char(20))
　　
-------------------- --------------------
　　
do not change!       changed   
　　

　　现在我们可以确定事务0000:00000364谅是我们要找的UPDATE的日志。然后通过[Begin Time]和[Transaction SID]可以谁什么时候修改了这条数据。

• 找出删除'important'的日志
  

　　'important'被删除了，所以没有办法使用lockres来寻找。如果我们知道它的ID值，我们可以插入一条相同ID的记录，它会生成一样lockres，可惜我们也不知道ID值。我们现知道的只有data列的值为'important'，如果'important'在data列中的筛选度足够高的话，可以尝试通过[Log Record]去找到一些匹配的日志记录。
　　

select [Current LSN],Operation,Context,[Transaction>
from fn_dblog(null, null)
　　
where charindex(cast('important' as varbinary(20)), [Log Record]) > 0;
　　


　　
Current LSN             Operation        Context           Transaction>　　
----------------------- ---------------- ----------------- --------------
　　
00000023:0000007b:0003  LOP_INSERT_ROWS  LCX_CLUSTERED     0000:00000363
　　
00000023:0000007f:0002  LOP_DELETE_ROWS  LCX_MARK_AS_GHOST 0000:00000366
　　

　　
select [Current LSN], [Operation], [AllocUnitName], [Transaction Name]
　　from fn_dblog(null, null)

　　where [Transaction>　　

　　从找到的结果，可以看出LOP_INSERT_ROWS是的插入时的操作，LOP_DELETE_ROWS是一个插入操作。我们可以试着用LOP_DELETE_ROWS 的事务0000:00000366去找到相关的日志记录。例子中这种复杂粗暴找到日志的方式在现实中可能会非常困难。例子用的一个简单的ASCII的字符串，如果是其它类型的，你需要知道值在SQL Server中的内部表示形式(如numeric,decimal)，还要用写出正确的Intel平台的LSB值 (如int,datetime)。这个是非常非常困难的。