Estudando o TLog usando xEvents

Quer ler o PDF e baixar o script? Aqui mesmo.

Um dos pontos que eu gosto de destacar no uso do xEvents é a possibilidade dele nos deixar analisar detalhes em relação a engine do SQL Server, de maneira simples e direta. Aproveito para falar sobre o transaction log usando como base em uma demonstração que apresentei na palestra sobre xEvents.
Um dos eventos expostos pelo pacote sqlserver é o log_flush_complete, e quando capturamos essa saída vamos ter como saída campos como: database_id, write_size, row, log_block_id, etc. Este último me chamou a atenção, por ser um ID deve haver uma correlação com o transaction log e nosso famoso Log Sequence Number (LSN). Abaixo está um exemplo de cada um deles:

log_block_id:   

    <data name="log_block_id">

      <type name="uint64" package="package0" />

      <value>154618822976value>

    data>

LSN: 00000024:00000140:0004

Mas qual a relação entre estes? Fiz um pequeno teste e joguei o valor inteiro para ser convertido para hexadecimal. Olha o que saiu: 0x2400000140. Opa, que bela coincidência! Lembrando que na formação do LSN temos como primeiro elemento o VLF, segundo elemento o Log Block e o último o número do slot dentro do log block.

Muito bom, então conseguimos associar um flush ao bloco exato dentro do transaction log. Daí saiu outra curiosidade: analisando o log com o fn_dblog temos uma coluna chamada “Log Record Length” que traz o tamanho exato de uma entrada no log, então se pegarmos o detalhamento de um flush (rows e log records) e contabilizarmos o log block, os números devem bater.

Como resultado dessa comparação posto alguns resultados:

LSN: 00000024:00000140 -> 9 registros no log e somatório dos tamanhos: 728 bytes

Log_block_id 154618822976 -> 9 registros no flush e tamanho da operação: 4096 bytes

LSN: 00000024:000001a0 -> 55 registros no log e somatório dos tamanhos: 11328 bytes

Log_block_id 9663676832-> 55 registros no flush e tamanho da operação: 12288 bytes

Está claro que o número de registros é igual entre as fontes, mas o número de bytes do somatório do T-Log e operação de escrita não. E qual o motivo disso? O meu sistema de arquivos é o NTFS e por padrão o cluster size da partição é de 4K, então operações de escritas devem ser feitas em blocos de múltiplos de 4096 bytes, como pode ser percebido acima.

Já com a ferramenta em mãos apareceu uma nova dúvida, todo flush é sempre um log block completo? Ou pode haver dois flushes parciais do mesmo log block? Ou até dois log blocks no mesmo flush?

Para descobrir a resposta eu criei usei dos seguintes passos (script completo no fim do artigo):

1. Criei um banco de dados de exemplo

2. Marquei o LSN antes de começar o monitoramento

3. Disparei uma sessão xEvent para coletar o evento log_flush_complete filtrando pelo banco de dados de meu interesse

4. Gerei algumas atividades

5. Salvei o XML de resultado em uma tabela de coleta para posterior análise

6. A partir daí eu escrevi algumas consultas para agrupar o retorno do fn_dblog por log block, outra para consultar o XML de saída da monitoração e o join dos dados pelo log_block.

Resultado: um claro mapeamento direto entre log blocks e flushes, conforme pode ser visto na figura 01.

(Figura 01 - Comparando transaction log e log flushes)

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.

(Figura 02 – Detalhamento 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.

Um busca nova encontrei agora um post muito legal (http://rusanu.com/2012/01/17/what-is-an-lsn-log-sequence-number/) 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 (http://blogs.msdn.com/b/sqlsakthi/archive/2011/04/17/what-is-writelog-waittype-and-how-to-troubleshoot-and-fix-this-wait-in-sql-server.aspx). 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

[]s
Luciano Caixeta Moreira - {Luti}
luciano.moreira@srnimbus.com.br
www.twitter.com/luticm
www.srnimbus.com.br