如何解讀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'

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值。碰撞的概率是非常低的,如果發生, 上面的查詢會返回多行。

總結

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


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM