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

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

上面的删除使用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';

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

从第一行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'

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

从上面的日志可以看到这是个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;

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

根据找到的事务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';

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

从上在的日志很容易就知道谁什么时候删除的。注意在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

上一篇:jQueryMobile控件之展开与合并


下一篇:华为S5300交换机配置基于接口的本地端口镜像