如何解读SQL Server日志(3/3)

如何查看被截断的日志

如果数据库做了日志备份操作，则日志会被截断，然后原来活动的VLF会被重用。使用sys.fn_dblog将会看不到任何被截断的日志。那如何查看日志备份中的日志呢？使用fn_dump_dblog读取日志备份的内容。它的输出和sys.fn_dblog是一样的，所以进行查询过滤时也可以跟其一样。

use master
go
backup log logtest to disk='d:\logtest.trn';
go
select [Current LSN], [Operation], [AllocUnitName], [Transaction Name]
    from fn_dump_dblog (
    NULL, NULL, 'DISK', 1, 'D:\logtest.trn',
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT)
    where  [Transaction ID]='0000:00000367'
go

当[Lock Infomation]的内容无用时

前面我们使用[Lock Infomation]的内容帮助我们定位和分析日志操作，但是如果数据操作没有单独锁定某个行时(e.g.锁升级和使用表提示锁定表)，则它的内容对我们的帮助就很少了。

delete top(1) from demotable with (tablockx);

select [Current LSN], [Operation], [Transaction ID],
	[AllocUnitName], [Page ID], [Slot ID], [Lock Information]
	from fn_dblog(null, null)
where [transaction id]='0000:0000036a'

DELETED

上面的删除使用tablockx表提示，使得删除是直接对表使用X锁，而不是行锁。这样在[Lock Information]就没有包含键锁的HASH值(Lockres)。如图，我们现在能获取到Page ID、Slot ID和Object ID，但是不能定位到行。

但是日志的有效工作负载还是包含了所有的内容，因此可以通过搜索[Log Record]或者 [RowLog Contents 0~5] 来找到具体的行。

最小化日志操作也会让查找日志变得更困难。最小化日志操作的日志内容只扫描了某个页包含了最小华日志操作，SQL Server必需保证它在事务提交前被刷新到磁盘。在相关日志中只看到LOP_FORMAT_PAGE操作及其操作(最小化日志操作)的Page ID。最小化日志只有INSERT、blob .WRITE和WRITETEXT/UPDATETEXT操作，其它的操作都会完整记录日志，这样分析日志要分析的内容就少了很多。有一种情况会增加操作的日志量：更新事务复制中的发布表的数据。

实践时的注意事项

本文的例子的日志量非常少，搜索起来也很快。在真实环境中可能要透过数百万行日志才能找到所需要的日志记录，当然会很慢。最好将sys.fn_dblog返回的日志行先存到表中，然后建立需要的索引，这样查询时会快很多。使用sys.fn_dblog时如果能传入开始和结束的LSN，也会让其它返回速度快一些。注意，如果传入不正确的LSN给sys.fn_dblog，则会导致服务器内核转储( server core dump )，在生产环境这会导致SQL Server僵死一会儿。

DDL 修改

分析DDL修改的思路跟分析数据修改的一样。数据库对象是存储于一个或多个系统表中的数据，所有DDL修改最终会通过修改系统表的数据而完成。这样会让所有的DDL修改在分析日志时看起来差不多，例如LOP_INSER_ROWS操作插入数据到sys.syschhobjs，它可能是CREATE TABLE,也可能是CREATE VIEW或者CREATE PROC，甚至CREATE TABLE foo和CREATE TABLE bar的日志看起来是一样的。

DDL操作和DML操作两者修改数据时的主要区别在于使用不同锁。DDL使用元数据锁(Metedata Lock)，一般情况，DDL会以包含Object ID的SCH_M锁开始。

另外，分析日志中DDL，要与特定的版本和更新相匹配。不同的版本、SP甚至CU，元数据表和元数据表结构可能会不同。

利用OBJECT ID

找出某个对象的DDL具体操作的最好方法是通过找出在对象上请求SCH_M锁的事务。先通过OBJECT_ID()得对象的ID，然后在[Lock Information]列中匹配搜索模式N'%SCH%%'得到事务。通过事务再找到所有相关的操作日志。

--executed 2 DDLs: CREATE and ALTER
create table xx(id int ,val nchar(10));
insert into xx values(1,'A'),(2,'B')
alter table xx 
 alter column val nchar(20);
go
select OBJECT_ID('xx')
-- returned 293576084
go
select [Current LSN], Operation, [Lock Information], [Transaction ID], [Description] 
from sys.fn_dblog(null,null)
where [Lock Information] like N'%SCH%293576084%'
go

Current LSN	             Operation	           Lock Information	                  Transaction ID	  Description
-----------              ------------    ----------------------------------------------     --------------    -------------
00000023:000000a9:0002	LOP_LOCK_XACT	HoBt 0:ACQUIRE_LOCK_SCH_M OBJECT: 7:293576084:0    0000:0000036b	             
00000023:000000b7:0002	LOP_LOCK_XACT	HoBt 0:ACQUIRE_LOCK_SCH_M OBJECT: 7:293576084:0 	  0000:00000370

返回两个事务，我们逐一查看。

select [Current LSN], Operation, [AllocUnitName], [Lock Information], [Transaction ID], 
	[Description], [Begin Time], [Transaction Name], [Transaction SID]
from fn_dblog(null, null) 
	where [Transaction ID] = N'0000:0000036b';

DDL1

从第一行LOP_BEGIN_XACT事务开始，在Description和Transaction Name看到CREATE TABLE，还有Begin Time，然后还有Transaction SID。由这些信息我们可以知道：谁什么时候创建了这个表。

余下的行结合System Base Tables可以解读出其含义：

  • LOP_INSERT_ROWS 插入 sys.sysschobjs
    这个操作是向sys.objects插入数据行。有4个LOP_INSERT_ROWS操作是因为sys.sysschobjs表有1个聚集索引和3个非聚集索引。

  • LOP_INSERT_ROWS 插入 sys.syscolpars
    这个操作向sys.columns插入2行数据。每一个插入操作有2条记录，分别为sys.syscolpars上的聚集索引和非聚集索引。

  • LOP_INSERT_ROWS 插入 sys.sysidxstats
    插入数据到sys.indexes。

  • LOP_INSERT_ROWS 插入 sys.sysiscols
    插入数据到sys.index_columns。

通过上面的分析，虽然没有得到具体的DDL语句，但是我们知道一些非常有用的信息：在2016/08/22 17:13:47:667 创建的表，表中有2列。如果我们进一步解析rowlog contents和log content还能知道列名。例子中的CREATE语句非常简单，如果是复杂的CREATE语句，会生成很多的日志记录。比如对表进行分区，则会增加很多LOP_INSERT_ROWS记录，因为每个分区必须往sys.sysrowstes添加行，分区上的每一个列和索引都必须被记录在sys.sysrscols中。而这些操作都需要在低级别的HoBT元数被插入前完成。

再来看看另一个事务：

select [Current LSN], Operation, [AllocUnitName],[Lock Information], [Transaction ID], 
	[Description], [Begin Time], [Transaction Name], [Transaction SID]
from fn_dblog(null, null) 
	where [Transaction ID] = N'0000:00000370'

DDL2

从上面的日志可以看到这是个ALTER TABLE操作，并且操作是一个堆表，也能知道操作时间和SID。通过LOP_MODIFY_COLUMNS操作，知道这是修改列属性的操作。

查找被删除对象的OBJECT ID

对象被删除后，就没有办法根据OBEJCT ID去找相关日志了。但是我们知道删除对象本质上从sys.sysschobjs删除数据，所以搜索sys.sysschobjs的LOP_DELETE_ROWS操作。我们还知道操作的分配单元是sys.sysschobjs.clst。同时，被删除对象的名字肯定存在于Log Contents中的。

drop table xx;
go
select [Current LSN], Operation, [AllocUnitName], [Lock Information], [Transaction ID], 
	[Description], [Begin Time], [Transaction Name], [Transaction SID]
from fn_dblog(null, null) 
	where [Operation] = N'LOP_DELETE_ROWS'
	and [AllocUnitName] = N'sys.sysschobjs.clst'
	and CHARINDEX(cast(N'xx' as varbinary(4000)), [Log Record]) > 0;

DDL3

根据找到的事务ID，去找到相关的日志记录：

select [Current LSN], Operation, [AllocUnitName], [Lock Information], [Transaction ID], 
	[Description], [Begin Time], [Transaction Name], [Transaction SID]
from fn_dblog(null, null) 
	where [Transaction ID] = N'0000:00000371';

DDL4

从上在的日志很容易就知道谁什么时候删除的。注意在LOP_BEGIN_XACT后的LOP_LOCK_XACT，在它的锁信息里有被删除对象的OBJECT ID。有了OBJECT ID，我们就可以利它进一步的分析日志。
注意，OBJECT ID是能够被重用的。 所以在使用OBJECT ID分析日志时，要分辨出它是否被重用了。在日志中，LSN严格按照时间排序的，所以可以利用之来区分OBEJCT ID的重用。

还要注意CHARINDEX(cast(N'xx' as varbinary(4000)), [Log Record]) > 0，它可能会返回名字中包含‘xx’的其它对象。

分析日志不是一种常规的和常用的技术。同时，它的难度高，也很容易被海量的日志误导，所以分析时最好从多个角度，使用多种方法去定位相关的日志。

文中的例子，我用的SQL Server 2012 - 11.0.5343.0,同时dbo.xx表，我用是一个堆表。这两个地方导致与原文有较大差异。 BY Joe . TJ

posted @ 2016-08-23 15:22  Joe.TJ  阅读(3390)  评论(0)  编辑  收藏  举报