如何解讀SQL Server日誌(2/3)_ZenDei技術網路在線

接下來說說返回的RowLogo Content列，例子中返回了三個列。這些列包含了數據操作的“有效工作負載(Playload)”記錄。根據不同操作類型有效負載的內容也是不同的，但是它必須包含足夠的信息，能讓相應的數據操作在恢復時能被REDO和UNDO。對於每一個INSERT而言，它包含了插入行的所有 ...

接下來說說返回的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 ID]欄位得到INSERT的事務ID，再通過事務ID去找出與這個事務相關的所有日誌記錄。

--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 ID
declare @xactid nvarchar(14);
select top(1) @xactid=[Transaction ID] from sys.fn_dblog(null,null)
where CHARINDEX(@lockres,[Lock Information] )>0

--get all log record of the found Transaction ID
select [Current LSN], [Operation], [Transaction ID], 
    [Transaction SID], [Begin Time], [End Time]  
from sys.fn_dblog(null,null)
where [Transaction ID]=@xactid;

Current LSN             Operation             Transaction ID  Transaction SID      Begin Time               End Time
----------------------- ---------------- -------------------- ------------------ ----------------------- ---------
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 relevant Transaction IDs
declare @xactid table (xid nvarchar(14));
insert into @xactid
select [Transaction ID] 
from sys.fn_dblog(null,null)
where CHARINDEX(@lockres,[Lock Information] )>0

--get all log records of the found Transaction ID
select [Current LSN], [Operation], [Transaction ID], 
    [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 ID]=b.xid

Changed

從結果可以看到，有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 ID]
from fn_dblog(null, null)
where charindex(cast('important' as varbinary(20)), [Log Record]) > 0;

Current LSN             Operation        Context           Transaction ID
----------------------- ---------------- ----------------- --------------
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 ID] = '0000:00000366';

從找到的結果，可以看出LOP_INSERT_ROWS是的插入時的操作，LOP_DELETE_ROWS是一個插入操作。我們可以試著用LOP_DELETE_ROWS 的事務0000:00000366去找到相關的日誌記錄。例子中這種複雜粗暴找到日誌的方式在現實中可能會非常困難。例子用的一個簡單的ASCII的字元串，如果是其它類型的，你需要知道值在SQL Server中的內部表示形式(如numeric,decimal)，還要用寫出正確的Intel平臺的LSB值 (如int,datetime)。這個是非常非常困難的。