如何解讀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的理解有幫助。