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

makala

如何查看被截断的日志
　　如果数据库做了日志备份操作，则日志会被截断，然后原来活动的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>　　
go
　　

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

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


　　
select [Current LSN], [Operation], [Transaction>
　　[AllocUnitName], [Page>　　from fn_dblog(null, null)

　　
where [transaction>　　

　　上面的删除使用tablockx表提示，使得删除是直接对表使用X锁，而不是行锁。这样在[Lock Information]就没有包含键锁的HASH值(Lockres)。如图，我们现在能获取到Page>　　但是日志的有效工作负载还是包含了所有的内容，因此可以通过搜索[Log Record]或者 [RowLog Contents 0~5] 来找到具体的行。

　　最小化日志操作也会让查找日志变得更困难。最小化日志操作的日志内容只扫描了某个页包含了最小华日志操作，SQL Server必需保证它在事务提交前被刷新到磁盘。在相关日志中只看到LOP_FORMAT_PAGE操作及其操作(最小化日志操作)的Page>
实践时的注意事项
　　本文的例子的日志量非常少，搜索起来也很快。在真实环境中可能要透过数百万行日志才能找到所需要的日志记录，当然会很慢。最好将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>　　另外，分析日志中DDL，要与特定的版本和更新相匹配。不同的版本、SP甚至CU，元数据表和元数据表结构可能会不同。

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

--executed 2 DDLs: CREATE and>
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>　　
from sys.fn_dblog(null,null)
　　
where [Lock Information] like N'%SCH%293576084%'
　　
go
　　

　　
Current LSN              Operation             Lock Information                   Transaction>　　
-----------              ------------    ----------------------------------------------     --------------    -------------
　　
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>[Description], [Begin Time], [Transaction Name], [Transaction SID]
　　
from fn_dblog(null, null)
　　where [Transaction>　　

　　从第一行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>[Description], [Begin Time], [Transaction Name], [Transaction SID]
　　
from fn_dblog(null, null)

　　where [Transaction>　　

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

查找被删除对象的OBJECT>
　　对象被删除后，就没有办法根据OBEJCT>　　

drop table xx;　　
go
　　
select [Current LSN], Operation, [AllocUnitName], [Lock Information], [Transaction>　　[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;
　　

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

select [Current LSN], Operation, [AllocUnitName], [Lock Information], [Transaction>[Description], [Begin Time], [Transaction Name], [Transaction SID]
　　
from fn_dblog(null, null)

　　where [Transaction>　　

　　从上在的日志很容易就知道谁什么时候删除的。注意在LOP_BEGIN_XACT后的LOP_LOCK_XACT，在它的锁信息里有被删除对象的OBJECT>
　　
注意，OBJECT> 所以在使用OBJECT>　　还要注意CHARINDEX(cast(N'xx' as varbinary(4000)), [Log Record]) > 0，它可能会返回名字中包含‘xx’的其它对象。
　　分析日志不是一种常规的和常用的技术。同时，它的难度高，也很容易被海量的日志误导，所以分析时最好从多个角度，使用多种方法去定位相关的日志。

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