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

SQL Server 的事務日誌包含所有數據修改的操作記錄。分析日誌一般作為解決某些問題的最後手段，如查看某些意外的修改。理解和分析日誌內容是件非常困難的事情，fn_dblog通常會輸出非常多的數據，查看也比較困難。我嘗試用一些實例幫助大家更好地分析和理解日誌。 SQL Server 使用Write ...

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'

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'

FirstInsert

我們來看看第一個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值。碰撞的概率是非常低的，如果發生，上面的查詢會返回多行。

總結

原文地址：How to read and interpret the SQL Server log ，非逐字翻譯，在自己理解的基礎上的意譯，有增和刪內容。
解析日誌內容，通常只會在少數特殊的場景用到，但會對SQL Server的理解有幫助。