如何讀懂SQL Server的事務日誌

簡介

本文將介紹SQL Server的事務日誌中記錄了哪一些信息，如何來讀懂這些事務日誌中信息。首先介紹一個微軟沒有公開的函數fn_dblog，在文章的接下來的部分主要用到這個函數來讀取事務日誌。

1. fn_dblog (@StartingLSN,@EndingLSN)
2. --@StartingLSN:表示起始的LSN號，若是爲NULL值則表示從首日誌記錄開始查詢。
3. --@EndingLSN:表示結束的LSN號，若是爲NULL值則表示查詢到尾日誌記錄。
4. --須要注意的是咱們平時所看到的LSN都是十六進制的，而這邊的參數須要轉化爲十進制，如00000021:00000077:0003在做爲參數傳給fn_dblog時須要轉換爲33:119:3

正文

1. --建立測試數據庫
2. USE [master];
3. GO
4. CREATE DATABASE TestDB;
5. GO
6. -- 建立表
7. USE TestDB;
8. GO
9. CREATE TABLE [Location] (
10.     [Sr.No] INT IDENTITY,
11.     [Date] DATETIME DEFAULT GETDATE (),
12.     [City] CHAR (25) DEFAULT 'xiamen');

經過上面的代碼建立了一個名爲TestDB的數據庫，並建立了一個三個字段的表。接下看看事務日誌的內容

1. USE TestDB;
2. GO
3. select [Current LSN],
4.        [Operation],
5.        [Transaction Name],
6.        [Transaction ID],
7.        [Transaction SID],
8.        [SPID],
9.        [Begin Time]
10. FROM fn_dblog(null,null)

從上圖能夠看出總共產生了195行日誌記錄，我截取了部分的結果，在Operation列中記錄了對應的LSN所作的操做，其中LOP_BEGIN_XACT表示一個事務的開始，Transaction Name顯示了建立的數據庫的名稱，而Trasaction ID則記錄了所對應的事務ID。下面列出Operation幾種比較常見而重要的值

• LOP_BEGIN_XACT 事務的開始
• LOP_LOCK_XACT 獲取鎖
• LOP_MODIFY_ROW 修改行(具體修改的對象能夠查看AllocUnitName)
• LOP_COMMIT_XACT 提交事務
• LOP_DELETE_ROWS 刪除數據
• LOP_INSERT_ROWS 插入數據

接下來向表中插入100行數據，並查看對應的事務日誌，代碼以下：

1. INSERT INTO Location DEFAULT VALUES
2. GO 100
3. GO
4.  
5. SELECT
6.  [Current LSN],
7.  [Transaction ID],
8.  [Operation],
9.   [Transaction Name],
10.  [CONTEXT],
11.  [AllocUnitName],
12.  [Page ID],
13.  [Slot ID],
14.  [Begin Time],
15.  [End Time],
16.  [Number of Locks],
17.  [Lock Information]
18. FROM sys.fn_dblog(NULL,NULL)
19. WHERE Operation = 'LOP_INSERT_ROWS' AND AllocUnitName = 'dbo.Location'

獲得如上圖所示的結果，返回的行數與咱們insert的次數一致，接下來取其中的一個Trasaction ID來看看一次insert在事務日誌中記錄了哪些動做。

1. SELECT
2.  [Current LSN], [Transaction ID], [Operation], [Transaction Name], [CONTEXT], [AllocUnitName], [Page ID], [Slot ID], [Begin Time], [End Time], [Number of Locks], [Lock Information]
3. FROM sys.fn_dblog(NULL,NULL)
4. WHERE [Transaction ID] = '0000:000002fc'

從圖中能夠看出這個Transaction執行步驟的詳細信息

• 在2014/05/25 18:35:39:197事務開始
• 在堆表dbo.Location的PAGEID爲0001:0000004f插入數據
• 在2014/05/24 18:35:39:200提交事務

下面這一段是我從Lock Information欄位複製出的內容，來詳細的看一下

1. HoBt 72057594039042048:ACQUIRE_LOCK_IX OBJECT: 6:245575913:0 ;ACQUIRE_LOCK_IX PAGE: 6:1:79 ;ACQUIRE_LOCK_X RID: 6:1:79:0

經過下面的代碼咱們來驗證一下，這樣一條INSERT語句所得到的鎖信息

1. DBCC TRACEON(-1,3604)
2. DBCC TRACEON (-1,1200)--查看當前Session的鎖信息
3. BEGIN TRAN
4. INSERT INTO Location DEFAULT VALUES
5. ROLLBACK TRAN
6. DBCC TRACEOFF ( -1,1200)
7. DBCC TRACEOFF ( -1,3604)
8. /*
9. Process 57 acquiring IX lock on OBJECT: 6:245575913:0 (class bit2000000 ref1) result: OK
10. Process 57 acquiring IX lock on PAGE: 6:1:79 (class bit2000000 ref0) result: OK
11. Process 57 acquiring X lock on RID: 6:1:79:90 (class bit2000000 ref0) result: OK
12. */

能夠看到Lock Information欄位所記錄的信息與1200跟蹤標記鎖輸出的信息是一致的。

另外從事務日誌中還能夠看到SQL Server的一些內部操做，並看到這些操做一些具體信息，如開始的時間，進行的次數，操做的步驟等等。接下來看看頁拆分的動做

1. --查找頁拆分動做的Transaction
2. SELECT
3.  [Current LSN], [Transaction ID], [Operation], [Transaction Name], [CONTEXT], [AllocUnitName], [Page ID], [Slot ID], [Begin Time], [End Time], [Number of Locks], [Lock Information]
4. FROM sys.fn_dblog(NULL,NULL)
5. WHERE [Transaction Name] = 'SplitPage'
6. --查看具體Transaction中的動做
7. SELECT
8.  [Current LSN], [Transaction ID], [Operation], [Transaction Name], [CONTEXT], [AllocUnitName], [Page ID], [Slot ID], [Begin Time], [End Time], [Number of Locks], [Lock Information]
9. FROM sys.fn_dblog(NULL,NULL)
10. WHERE [Transaction ID] = '0000:000002f8'

結語

經過了解事務日誌中所記錄的內容，能夠更方便咱們去了解SQL Server所作的一些操做的執行過程。