Interessante é que quando eu comecei o monitoramento o MaxLSN era o 00000024:00000140:0004 (4 atividades do bloco), e quando o primeiro flush aconteceu o SQL Server levou todas as 9 atividades do bloco, que mostra o comportamento do flush ser sempre o log block. Analisando as outras colunas sempre existe uma igualdade entre número de entradas no log e no flush, bem como a unicidade de log blocks nos flush do transaction log.
Analisando o log podemos notar que a cada operação que gera um flush (ex.: commit e checkpoint), novos blocos são gerados. Isto é, as operações relacionadas com o flush (LOP_COMMIT_XACT, LOP_BEGIN_CKPT, LOP_END_CKPT,...) vão gerar um novo log block.
Curioso é que a operação LOP_MODIFY_ROW também gerou um log block novo, mas somente com contexto LCX_SCHEMA_VERSION, pois testei com LCX_CLUSTERED e o log block se manteve. LOP_FILE_HDR_MODIFY com LCX_FILE_HEADER também gerou um novo log block, o que parece ser operações mais sensíveis e que alteram estruturas que precisam ser persistidas logo no disco. Nota: pode ter sido coincidência dos meus testes, mas optei por relatar aqui.
Lembrando que a ordenação de escrita dos log blocks é de extrema importância para o funcionamento do T-log! Leia o SQL Server 2000 I/O basics para lembrar que uma propriedade fundamental do log é o write ordering.
Aproveitando a análise do log block, vamos estudar a sequência em sua numeração (figura 01), por exemplo: 188, 190, 198, 1a0. Podemos notar um crescimento constante de 8 unidades, e este independente do número de registros, senão a numeração deveria ser acrescentada de 2, 3, 5, 9 ou 55 unidades, que é a quantidade de registros em cada bloco.
Mas o que temos de constante é o tamanho do write_bytes em 4K, se dividirmos esse valor por 8 unidades nós temos 512 bytes por unidade... Um setor! Parece-me uma hipótese plausível, então se o cálculo estiver correto o flush que escreveu 12K é representado por 24 setores (ou 18 em hexadecimal), somando 18 a 1A0 (número do bloco de 55 linhas) temos como próximo número: 1B8! Lindo, não?
E aí, gostou? Essa foi uma pequena brincadeira com o xEvents e o transaction log, e claro, um pouco de “intuição internals”. Curiosamente nunca apresentamos a formação do log block no treinamento do internals e procurei “log block” em alguns livros, whitepapers, mas não encontrei todo esse detalhamento.
) que ainda diz que o tamanho máximo do log block é de 60K, porém existe outro post do time de suporte falando que o bloco pode chegar a 64K (
). Qual está certo?! Particularmente eu tenho uma anotação do último PASS Summit onde em uma sessão foi dito que o bloco é de 60K, inclusive com meu comentário “Pq 60K e não 64K?”... Será?
Abaixo está o script que utilizei para você conduzir seus experimentos e quem sabe você não me ajuda a validar um pouco do que eu escrevi.
/****************************************************************************
*****************************************************************************
Autor: Luciano Caixeta Moreira
E-mail:
luciano.moreira@srnimbus.com.br
Blog: http://luticm.blogspot.com
Twitter:
@luticm
Data criação: 17/05/2012
Descrição: Script para o
artigo - Estudando o TLog usando xEvents
Histórico de atualizações:
*****************************************************************************
****************************************************************************/
-- Criando a estrutrua para a demonstração
-- Script foi testado utilizando o SQL Server 2012 RTM
USE master
GO
IF DB_ID('LogInternals') IS NOT NULL
DROP DATABASE LogInternals
go
CREATE DATABASE LogInternals
go
USE LogInternals
go
IF OBJECT_ID('dbo.TabelaBase', 'U') IS NOT NULL
DROP TABLE TabelaBase
GO
CREATE TABLE dbo.TabelaBase
(ID INT IDENTITY NOT NULL PRIMARY KEY
, Nome VARCHAR(100) NOT NULL DEFAULT ('Sr. Nimbus')
, DataRegistro DATETIME2 NOT NULL DEFAULT (SYSDATETIME())
)
go
INSERT INTO TabelaBase DEFAULT VALUES
go
BACKUP DATABASE LogInternals
TO DISK = 'C:\TEMP\LogInternalsBAK.bkp'
go
CHECKPOINT
go
/*
Função auxiliar para fazer
conversão de string hexa para varbinary.
Referência:
http://blogs.msdn.com/b/rextang/archive/2008/01/13/7091118.aspx
*/
CREATE FUNCTION dbo.HexStrToVarBinary(@hexstr varchar(8000))
RETURNS varbinary(8000)
AS
BEGIN
DECLARE @hex char(1), @i int, @place bigint, @a bigint
SET @i = LEN(@hexstr)
set @place = convert(bigint,1)
SET @a = convert(bigint, 0)
WHILE (@i > 0 AND (substring(@hexstr, @i, 1) like '[0-9A-Fa-f]'))
BEGIN
SET @hex = SUBSTRING(@hexstr, @i, 1)
SET @a = @a +
convert(bigint, CASE WHEN @hex LIKE '[0-9]'
THEN CAST(@hex as int)
ELSE CAST(ASCII(UPPER(@hex))-55 as int) end * @place)
set @place = @place * convert(bigint,16)
SET @i = @i - 1
END
RETURN convert(varbinary(8000),@a)
END
GO
-- Cria tabela de coleta na tempdb para não interferir
-- nas escritas do transaction log no banco LogInternas
IF OBJECT_ID('tempdb.dbo.Coleta_EventSession', 'U') IS NOT NULL
DROP TABLE tempdb.dbo.Coleta_EventSession
GO
SELECT
xe.name AS EventSession
,CAST(xet.target_data AS xml) AS SaidaXML
, SYSDATETIME() AS DataHoraRegistro
INTO tempdb.dbo.Coleta_EventSession
FROM sys.dm_xe_session_targets
AS xet
JOIN sys.dm_xe_sessions AS xe
ON xe.address = xet.event_session_address
WHERE 1=2
go
-- DBID = 20
SELECT DB_ID('LogInternals') AS BDID
go
CREATE EVENT SESSION xMonitorLogFlush
ON SERVER
ADD EVENT sqlserver.log_flush_complete (WHERE database_id = 20)
ADD TARGET package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY =
1 SECONDS)
go
ALTER EVENT SESSION xMonitorLogFlush
ON SERVER
STATE = START
GO
SELECT * FROM ::fn_dblog(NULL, NULL)
-- Max LSN: 00000024:00000140:0004 LOP_MODIFY_HEADER LCX_PFS
-- No momento não devemos encontrar nenhum evento registrado, pois não
houve açao para exigir um log flush
SELECT
xe.name AS EventSession
,CAST(xet.target_data AS xml) AS SaidaXML
, SYSDATETIME() AS DataHoraRegistro
FROM sys.dm_xe_session_targets
AS xet
JOIN sys.dm_xe_sessions AS xe
ON xe.address = xet.event_session_address
WHERE XE.name = 'xMonitorLogFlush'
go
-- Monitorando algumas atividades...
INSERT INTO TabelaBase DEFAULT VALUES
go 10
BEGIN TRANSACTION
INSERT INTO TabelaBase DEFAULT VALUES
INSERT INTO TabelaBase DEFAULT VALUES
INSERT INTO TabelaBase DEFAULT VALUES
COMMIT TRANSACTION
BEGIN TRANSACTION
INSERT INTO TabelaBase DEFAULT VALUES
INSERT INTO TabelaBase DEFAULT VALUES
INSERT INTO TabelaBase DEFAULT VALUES
CHECKPOINT
INSERT INTO TabelaBase DEFAULT VALUES
INSERT INTO TabelaBase DEFAULT VALUES
INSERT INTO TabelaBase DEFAULT VALUES
COMMIT TRANSACTION
go
SELECT * FROM ::fn_dblog(NULL, NULL)
-- Max LSN: 00000024:000001c8:0005 LOP_COMMIT_XACT LCX_NULL
-- Vamos guardar o estado dos xEvents
INSERT INTO tempdb.dbo.Coleta_EventSession (EventSession, SaidaXML, DataHoraRegistro)
SELECT
xe.name AS EventSession
,CAST(xet.target_data AS xml) AS SaidaXML
, SYSDATETIME() AS DataHoraRegistro
FROM sys.dm_xe_session_targets
AS xet
JOIN sys.dm_xe_sessions AS xe
ON xe.address = xet.event_session_address
WHERE XE.name = 'xMonitorLogFlush'
go
ALTER EVENT SESSION xMonitorLogFlush
ON SERVER
STATE = STOP
GO
SELECT
LEFT([Current LSN], 17) AS LogBlock
, *
FROM fn_dblog(NULL, null)
GO
-- Lista os eventos de forma ordenada...
WITH LB AS (
SELECT
LEFT([Current LSN], 17) AS LogBlock
, SUM([Log Record Length]) AS TamanhoLogBlock
, COUNT(*) AS EntradasLog
FROM fn_dblog(NULL, null)
GROUP BY LEFT([Current LSN], 17)
)
SELECT *
, dbo.HexStrToVarBinary(LEFT(LogBlock, 8))
, dbo.HexStrToVarBinary(RIGHT(LogBlock, 8))
FROM LB
ORDER BY dbo.HexStrToVarBinary(LEFT(LogBlock, 8)) ASC
, dbo.HexStrToVarBinary(RIGHT(LogBlock, 8)) ASC
GO
-- Analisando o que foi coletado
SELECT * FROM tempdb.dbo.Coleta_EventSession
go
-- Quebrando o XML
SELECT
EventSession
, DataHoraRegistro
, T.C.value('(./data[@name =
"database_id"]/value)[1]', 'INT') AS database_Id
, CAST(T.C.value('(./data[@name =
"log_block_id"]/value)[1]', 'BIGINT') AS VARBINARY(8)) AS log_block_id
, T.C.value('(./data[@name =
"write_size"]/value)[1]', 'BIGINT') AS write_size
FROM tempdb.dbo.Coleta_EventSession
CROSS APPLY SaidaXml.nodes('//event') AS T(C)
--WHERE DataHoraRegistro > '2012-05-17 15:20:00'
GO
-- Consultas para cruzamento dos dados
; WITH LB AS (
SELECT
LEFT([Current LSN], 17) AS LogBlock
, SUM([Log Record Length]) AS TamanhoLogBlock
, COUNT(*) AS EntradasLog
FROM fn_dblog(NULL, null)
GROUP BY LEFT([Current LSN], 17)
)
, ES AS (
SELECT
EventSession
, DataHoraRegistro
, T.C.value('(./data[@name =
"database_id"]/value)[1]', 'INT') AS database_Id
, CAST(T.C.value('(./data[@name =
"log_block_id"]/value)[1]', 'BIGINT') AS VARBINARY(8)) AS log_block_id
, T.C.value('(./data[@name =
"write_size"]/value)[1]', 'BIGINT') AS write_size
, T.C.value('(./data[@name =
"rows"]/value)[1]', 'INT') AS rows
, RIGHT(STUFF(
sys.fn_varbintohexstr(CAST(T.C.value('(./data[@name = "log_block_id"]/value)[1]', 'BIGINT') AS VARBINARY(8)))
, 11, 0, ':'), 17) AS LogBlock
FROM tempdb.dbo.Coleta_EventSession
CROSS APPLY SaidaXml.nodes('//event') AS T(C)
WHERE DataHoraRegistro > '2012-05-17 15:20:00'
)
SELECT
LB.LogBlock
, ES.LogBlock
, LB.EntradasLog
, ES.rows
, LB.TamanhoLogBlock
, ES.write_size
FROM LB
FULL OUTER JOIN ES
ON LB.LogBlock = ES.LogBlock
ORDER BY dbo.HexStrToVarBinary(LEFT(LB.LogBlock, 8)) ASC, dbo.HexStrToVarBinary(RIGHT(LB.LogBlock, 8)) ASC
go
DROP EVENT SESSION xMonitorLogFlush
ON SERVER
GO
