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

  • 相关阅读:
    去 抚仙湖 和 去 洱海 差不多
    开源项目 D++
    未来 的 科学家, 不仅 是 数学家, 也是 系统设计 大师
    出一道 智商题 : 证明 永动机 是否 能 设计出来 ?
    评论一下 “推倒数学大厦”的 一个 作业题
    用 无穷级数 的 思路 三等分角
    三等分角 化圆为方 可以 考虑 用 无穷级数 的 方式 来 实现
    CPU 应该 搞 0 级 Cache , 而不是 大寄存器
    关于 智商 (2)
    关于 智商
  • 原文地址:https://www.cnblogs.com/Joe-T/p/5799519.html
  • Copyright © 2020-2023  润新知