rusanu.com

with xmlnamespaces (default 'http://schemas.microsoft.com/sqlserver/2004/07/showplan')
select x.value(N'@NodeId',N'int') as NodeId
	, x.value(N'@PhysicalOp', N'sysname') as PhysicalOp
	, x.value(N'@LogicalOp', N'sysname') as LogicalOp
	, ox.value(N'@Database',N'sysname') as [Database]
	, ox.value(N'@Schema',N'sysname') as [Schema]
	, ox.value(N'@Table',N'sysname') as [Table]
	, ox.value(N'@Index',N'sysname') as [Index]
	, ox.value(N'@IndexKind',N'sysname') as [IndexKind]
	, x.value(N'@EstimateRows', N'float') as EstimateRows
	, x.value(N'@EstimateIO', N'float') as EstimateIO
	, x.value(N'@EstimateCPU', N'float') as EstimateCPU
	, x.value(N'@AvgRowSize', N'float') as AvgRowSize
	, x.value(N'@TableCardinality', N'float') as TableCardinality
	, x.value(N'@EstimatedTotalSubtreeCost', N'float') as EstimatedTotalSubtreeCost
	, x.value(N'@Parallel', N'tinyint') as DOP
	, x.value(N'@EstimateRebinds', N'float') as EstimateRebinds
	, x.value(N'@EstimateRewinds', N'float') as EstimateRewinds
	, st.*
	, pl.query_plan
from sys.dm_exec_query_stats as st
cross apply sys.dm_exec_query_plan (st.plan_handle) as pl
cross apply pl.query_plan.nodes('//RelOp[./*/Object/@Database]') as op(x)
cross apply op.x.nodes('./*/Object') as ob(ox)

I recently needed a query to look into the current query plan cache and locate all actual data access operators (index scans, index seeks, table scans). This is the query I used, I decided to place it here if someone else find it useful and, more importantly, so that I can find it again when I needed it…

LSNs, or Log Sequence Numbers, are explained on MSDN at Introduction to Log Sequence Numbers:

Every record in the SQL Server transaction log is uniquely identified by a log sequence number (LSN). LSNs are ordered such that if LSN2 is greater than LSN1, the change described by the log record referred to by LSN2 occurred after the change described by the log record LSN.

There are several places where LSNs are exposed. For example sys.database_recovery_status has the columns last_log_backup_lsn and fork_point_lsn, sys.database_mirroring has the mirroring_failover_lsn column and the msdb table backupset contains first_lsn, last_lsn, checkpoint_lsn, database_backup_lsn, fork_point_lsn and differential_base_lsn. Not surprisingly all these places where LSNs are exposed are related to backup and recovery (mirroring is a form of recovery). The LSN is exposed a numeric(25,0) value that can be compared: a bigger LSN number value means a later log sequence number and therefore it can indicate if more log needs to be backed up or recovered.

Yet we can dig deeper. Look at the LSN as exposed by the fn_dblog function:

select * from fn_dblog(null, null);

Current LSN
Operation
Context
Transaction ID
...


00000014:00000061:0001
LOP_BEGIN_XACT
LCX_NULL
0000:000001e4


00000014:00000061:0002
LOP_INSERT_ROWS
LCX_NULL
0000:000001e4


...





00000014:00000061:02ea
LOP_INSERT_ROWS
LCX_NULL
0000:000001e4


00000014:000000d9:0001
LOP_INSERT_ROWS
LCX_NULL
0000:000001e4


00000014:000000d9:0002
LOP_INSERT_ROWS
LCX_NULL
0000:000001e4


...





00000014:00000153:021e
LOP_INSERT_ROWS
LCX_NULL
0000:000001e4


00000014:00000153:021f
LOP_COMMIT_XACT
LCX_NULL
0000:000001e4


00000014:000001ab:0001
LOP_BEGIN_XACT
LCX_NULL
0000:000001ea


...





00000014:000001ab:01ac
LOP_INSERT_ROWS
LCX_NULL
0000:000001ea


00000015:00000010:0001
LOP_INSERT_ROWS
LCX_NULL
0000:000001ea

The LSN is shown as a three part structure. The first part seems to stay the same (the 14), the middle part apparently has some erratic increases and the last part seems to increase monotonically but it resets back to 0 when the middle part changes. It is much easier to understand what’s happening when you know what the three parts are:

• the first part is the VLF sequence number.
• the middle part is the offset to the log block
• the last part is the slot number inside the log block

Virtual Log files

SQL Server manages the log by splitting into regions called VLFs, Virtual Log Files, as explained in the Transaction Log Physical Architecture. We can inspect the VLFs of a database using DBCC LOGINFO:

FileId FileSize    StartOffset  FSeqNo  Status      Parity CreateLSN
------ ----------- -------------------------------- ------ -----------------
2      253952      8192         20      2           64     0
2      253952      262144       21      2           64     0
2      270336      516096       22      2           64     20000000021700747
2      262144      786432       23      2           64     21000000013600747
2      262144      1048576      24      2           64     22000000024900748
...
2      393216      16973824     75      2           64     74000000013600748
2      393216      17367040     0       0           0      74000000013600748
2      393216      17760256     0       0           0      74000000013600748
2      524288      18153472     0       0           0      74000000013600748

(59 row(s) affected)

So back to our fn_dblog result: the Current LSN value of 00000014:00000061:0001 means the following log record:

• the VLF sequence number 0×14 (20 decimal)
• in the log block starting at offset 0×61 in the VLF (measured in units of 512 bytes)
• the slot number 1

From the DBCC LOGINFO output we know that the VLF with sequence number 0×14 is starting at offset 8192 in the LDF file and has a size of 253952. It is the first VLF in the log file. the next LSNs increase the slot number until the LSN 00000014:00000061:02ea and then the LSN changes to 00000014:000000d9:0001. This means that the block that starts at offset 0×61 has filled up and the next block, from offset 0xd9, started to be used. If we do the math, 0xd9-0×61 is 0×78 (or 120 decimal), which is exactly 60Kb. You may remember that the maximum SQL Server log block size is 60Kb.

Our transaction continued to insert records until the LSN 00000014:00000153:021e then at the next LSN we have a commit operation (LOP_COMMIT_XACT). The next LSN, which is for the next transaction start, is at LSN 00000014:000001ab:0001. What does this tell us? The transaction terminated with the INSERT operation at LSN 00000014:00000153:021e and then it issued a COMMIT. The commit operation generated one more log record, the one at LSN 00000014:00000153:021f and then asked for the commit LSN to be hardened. This causes the log block containing this LSN (the log block starting at offset 0×153 in the VFL 0×14) to be closed and written to disk (along with any other not-yet-written log-block that is ahead of this block). The next block can start immediately after this block, so the next operation will have the LSN 00000014:000001ab:0001. If we do the math we can see that 0x1ab-0×153 is 0×58 (decimal 88) so this last log block had 44Kb.

I hope by now is clear what happened next in the fn_dblogoutput I shown: the transaction continues to insert records generating more LSNs. The entry at 00000014:000001ab:01ac is not only the last one in the current log block, but is also the last one in the current VLF. The next LSN is 00000015:00000010:0001, the LSN at slot 1 in the first log block (offset 0×10) of the VLF with sequence number 0×15.

Decimal LSNs

What about those LSN numbers like the 20000000021700747 CreateLSN value shown in DBCC LOGINFO output? They are still three part LSNs, but the values are represented in decimal. 20000000021700747 would be the LSN 00000014:000000d9:02eb.

Log flush waits

Look at the following fn_dblog output:

...
00000016:0000003c:0001  LOP_BEGIN_XACT      LCX_NULL    0000:0000057f
00000016:0000003c:0002  LOP_INSERT_ROWS     LCX_HEAP    0000:0000057f
00000016:0000003c:0003  LOP_COMMIT_XACT     LCX_NULL    0000:0000057f
00000016:0000003d:0001  LOP_BEGIN_XACT      LCX_NULL    0000:00000580
00000016:0000003d:0002  LOP_INSERT_ROWS     LCX_HEAP    0000:00000580
00000016:0000003d:0003  LOP_COMMIT_XACT     LCX_NULL    0000:00000580
00000016:0000003e:0001  LOP_BEGIN_XACT      LCX_NULL    0000:00000581
00000016:0000003e:0002  LOP_INSERT_ROWS     LCX_HEAP    0000:00000581
00000016:0000003e:0003  LOP_COMMIT_XACT     LCX_NULL    0000:00000581
00000016:0000003f:0001  LOP_BEGIN_XACT      LCX_NULL    0000:00000582
00000016:0000003f:0002  LOP_INSERT_ROWS     LCX_HEAP    0000:00000582
00000016:0000003f:0003  LOP_COMMIT_XACT     LCX_NULL    0000:00000582
...

Can you spot the problem? Notice how the LSN slot number stays at at 1,2,3 and the log block number grows very frequently: 3c, 3d, 3e, 3f… This is the log signature of a sequence of single row inserts that each committed individually. After each INSERT the application had to wait for the log block to be flushed to disk. The logs blocks were all of minimal size, 512 bytes.

Here is how I generated this log:

set nocount on;
declare @i int = 0;
while @i < 1000
begin
	insert into t (filler) values ('A');
	set @i += 1;
end
go

Had the application used a batch commit it would had solved several issues:

• only wait for one or few commits to flush the log.
• write less log, since every transaction generates an LOP_BEGIN_XACT and an LOP_COMMIT_XACT (they add up!).
• write the operations in few large IO requests as opposed to a lot of small IO requests.

So lets add batch commits to our test script:

set nocount on;
declare @i int = 0;
begin transaction
while @i < 1000
begin
	insert into t (filler) values ('A');
	set @i += 1;
	if @i % 100 = 0
	begin
		commit;
		begin transaction;
	end
end
commit
go

and then lets look at the log:

00000016:0000011d:0001  LOP_BEGIN_XACT     LCX_NULL   0000:000005d9
00000016:0000011d:0002  LOP_INSERT_ROWS    LCX_HEAP   0000:000005d9
00000016:0000011d:0003  LOP_INSERT_ROWS    LCX_HEAP   0000:000005d9
...
00000016:0000011d:006f  LOP_INSERT_ROWS    LCX_HEAP   0000:000005d9
00000016:0000011d:0070  LOP_COMMIT_XACT    LCX_NULL   0000:000005d9
00000016:00000136:0001  LOP_BEGIN_XACT     LCX_NULL   0000:000005db
00000016:00000136:0002  LOP_INSERT_ROWS    LCX_HEAP   0000:000005db
...
00000016:00000136:0064  LOP_INSERT_ROWS    LCX_HEAP   0000:000005db
00000016:00000136:0065  LOP_INSERT_ROWS    LCX_HEAP   0000:000005db
00000016:00000136:0066  LOP_COMMIT_XACT    LCX_NULL   0000:000005db
00000016:0000014d:0001  LOP_BEGIN_XACT     LCX_NULL   0000:000005dc
00000016:0000014d:0002  LOP_INSERT_ROWS    LCX_HEAP   0000:000005dc
00000016:0000014d:0003  LOP_INSERT_ROWS    LCX_HEAP   0000:000005dc
...
00000016:0000014d:0066  LOP_INSERT_ROWS    LCX_HEAP   0000:000005dc
00000016:0000014d:0067  LOP_COMMIT_XACT    LCX_NULL   0000:000005dc

We can see how the batch commit has created fewer, larger, log blocks. The application had to wait fewer times for the log to harden, and on each wait it issued a larger IO request. The log blocks are also more densely filled with LOP_INSERT_ROWS operations and do not have the overhead of having to log the LOP_BEGIN_XACT/LOP_COMMIT_XACT for every row inserted.

Conclusion

This little example shows not only how to understand the LSN structure, but it also shows how to read into the fn_dblog output. I also wanted to show the typical log signature of a commit operation: the LOP_COMMIT_XACT operation is recorded in the log and the log block is closed and flushed to disk. The next LSN will usually have slot 1 in the next block. The last example even shows how reading the log can spot potential application performance problems.