Tracking RESTORE operation

O SQL Server 2016 já vem dando as caras desde que foi anunciado o primeiro CTP (Community Technical Preview).

O Program Manager Ajay Jagannathan publicou no blog do oficial do time de engenheiros do SQL Server, uma novidade muito interessante para visualização detalhada de cada passo do que a engine do SQL Server faz durante a execução de operações de Backup e Restore. A partir da release CTP 2.0 do SQL Server 2016, existe um novo Extended Event (XE) que permite que você saiba exatamente em que fase está a sua operação de backup ou restore.

Em um outro blog post ([SQL Server Backup Internals] – Backup Full), escrevi detalhando um pouco do que acontece durante seu backup e, apesar de ter bastante detalhes no que foi mostrado naquele blog post, este novo evento do XE exibe as informações de uma forma muito mais detalhada e durante o acontecimento.

No post supracitado, foram utilizados alguns traceflags para exibição de algumas informações sobre o processo do backup após sua execução, dentre eles, os seguintes:

• 3604 : Este Trace Flag é necessário para exibição do resultado de alguns outros TF.
• 3014 : Utilizado para fornecer maiores informações detalhadas sobre as operações de Backup / Restore.
• 3226: Omite do Error Log do SQL Server, as entradas contendo informações de sucesso de backups realizados. Vale lembrar que operações de backup com falha ainda continuam sendo escritas no Error Log.
• 3004: Exibe informações detalhadas sobre o que está acontecendo entre o SQL Server e a mídia de backup. Este TraceFlag também mostra informações sobre o processos que escrevem em disco, como por exemplo o “Instant File Inicialization”.

Algo importante a ser observado, é que o propósito dos traceflags é diferente do novo XE que foi anunciado, visto que os traceflags exibem informações com bastante riqueza de detalhes, mas somente após o término do backup / restore, enquando o novo XE exibe informações sobre o progresso de tais operações, sendo assim seria possível até mesmo uma combinação de ambos para uma cobertura completa de tudo o que está acontecendo durante a operação de backup ou restore, e um “relatório” minucioso após a conclusão destas operações.

Vamos ao teste:

Para validar e conhecer o output gerado pelo novo XE, monitorei o restore de uma base de dados com as seguintes Características:

• Database_Size: 36.698 MB
• DataFileSize: 30.553 MB
• LogFileSize: 6.146 MB
• BackupSize: 24.153 MB
• CompressedBackupSize: 4.364 MB

Configuração do Extended Event:

Para criação da sessão do XE, pode-se executar o código (retirado do blog post informativo do novo XE ) abaixo no SSMS.

CREATE EVENT SESSION [Backup trace] ON SERVER
ADD EVENT sqlserver.backup_restore_progress_trace
ADD TARGET package0.event_file(SET filename=N’Backup trace’)
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,
TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

Código T-SQL do restore:

RESTORE DATABASE BDXeTeste
FROM DISK = ‘D:MSSQLSQL2016BACKUPBDXeTeste.bak’
WITH STATS = 1
,MOVE ‘BDXeTeste’ TO ‘D:MSSQLSQL2016DATABDXeTeste.mdf’
,MOVE ‘BDXeTeste_Log’ TO ‘D:MSSQLSQL2016LogBDXeTeste.ldf’

Resultado:

O Resultado em tempo real é impressionante, as informações exibidas são detalhadas exatamente com o que está acontecendo naquele exato momento dentro da engine do SQL Server com relação à operação de Backup ou Restore (restore, neste caso).

Abaixo, uma explicação item a item do output  do novo XE:

Figura 1 – Parte inicial do processo de restore, até 6%.

Na imagem acima é possível observar os processos iniciais que são excutados:

• RESTORE DATABASE started
  • Início do restore.
• Opening backup set
  • Abertura (acesso) ao backup set (arquivo(s) de backup).
• Processing the leading metadata
  • Processamento dos metadados do backup set para iniciar o planejamento do restore
• Planing begins
  • Início do planejamento de como será realizado o restore.
• Effective options : Checksum=0, Compression = 1, Encryption=0, BufferCount=6, MaxTransferSize=1024 KB
  • Opções a serem utilizadas para o restore. neste caso, não fará a verificação com checksum, o restore está com compressão habilitada, sem criptografia e o tamanho do memory cleark a ser utilizado, definido pelos parâmetros BufferCount e MaxTransferSize. (Valores default)
  • UPDATE: Este post nasceu de uma conversa / dica do meu amigo e também MVP em SQL Server Luciano [Luti] Moreira (Blog| Twitter), e então ele me sugeriu ressaltar a importâncias dos parâmetros BufferCount e MaxTransferSize, que podem ser de grande valia para aumentar consideravelmente a performance das operações de Backup e Restore.
• Planning is complete
  • Conclusão da fase de planejamento do restore,
• Beginning OFFLINE restore
  • Início dos procedimentos de restore previamente planejados.
• Attached database as DB_ID=6
  • Realizado o Attach (criação) do banco de dados, com ID = 6.
• Preparing containers
  • Preparando os containers (Filegroups e Files) que receberão os dados restaurados.
• Containers are ready
  • Conclusão da preparação dos containers
• Restoring the backup set
• Estimated total size to transfer = 25326763008 bytes
  • Estimativa total da quantidade de dados a serem transferidos do arquivo de backup para os datafiles. (24153 MB)
• Transfering data
  • Transferindo os dados
• BackupStream(0): Processing MSDA of size 386464 extents
  • Processamento do restore dos dados com tamanho de 386464 (extents) * 64 (kb / extent) = 24153.43 MB
• 1 percent
• 2 percent

Figura 2 – Início dos processos finais para conclusão do restore.

Na imagem acima é possível observar os processos que são excutados:

• 99 percent
• 100 percent
• Backup Stream(0): Completed MSDA
  • Conclusão do Streaming entre o arquivo de backup e os datafiles.
• Waiting for log zeroing to complete
  • Alocando o arquivo de Log (ldf) e zerando o mesmo. (Lembrando que arquivos de log não beneficiam-se do Instant File Initialization)
• Log zeroing is complete
  • Conclusão da alocação do arquivo de Log.
• BackupStream(0): Processing MSTL (FID=2, VLFID=293881, size=131071 bytes)
  • Início da transferência do conteúdo do backup (parte ativa do log) para o arquivo do log de transações (.ldf)
• Data transfer is complete
  • Conclusão da transferência.
• Backup set is restored
  • Informação de conclusão do “restore” (cópia do conteúdo do backup do arquivo para os datafiles e logfile).
• Offline rollfoward begins
  • Início do processo de rollfoward (re-executar as transações que foram executadas durante
• Processing 63 VLF headers
  • Processamento dos cabeçalhos dos VLFs que passarão pelo rollfoward.
• Processing VLF headers is complete
  • Conclusão do processamento dos cabeçalhos dos VLFs
• First LSN: 293881:26608:225, Last LSN: 293881:26757:1 
• Stop LSN: 293881:26757:1
  • Informações sobres os LSNs referentes aos rollfowards
• Offline rollfoward is complete
  • Conclusão do processo de rollfoward das transações “in-flight” durante a realização do backup.
• Database fixup is complete
  • Conclusão das etapas de “fixup” do banco de dados.
• Transitioning database to ONLINE
• Restarting database for ONLINE
  • Transição do banco para status ONLINE para finalização do restore.
• PostRestoreContainerFixups begins
• PostRestoreContainerFixups is complete
  • Conclusão das etapas relacionadas aos conteineres (arquivos de dados (.mdf))
• PostRestoreReplicationFixup begins

Figura 3 – Parte final do processo de restore, quando o mesmo é finalizado .

Na imagem acima é possível observar os processos finais que são excutados:

• PostRestoreReplicationFixup: CDC cleanup begins
• PostRestoreReplicationFixup: CDC cleanup is complete
  • Execução do cleanup do CDC (Change Data Capture) no banco restaurado. Essa ação deve-se ao fato de o restore não ter sido realizado com a opção: KEEP_CDC.
• PostRestoreReplicationFixup is complet
• Database is Restarted
  • Restart do banco de dados.
• Resuming any halted Fulltext crawls
• Writing history records
• Writing history records is complete (elapsed = 606 ms)
  • Gravação do registo da atividade de restore nas tabelas de sistema do banco de MSDB. (restorehistory)
• MSDB maintenance is complete
• RESTORE DATABASE finished
  • Finalização do Backup e disponibilização do banco de dados para utilização.

Conclusão:

Para uma simples conferência do percentual do progresso de atividades de BACKUP e RESTORE, um select na DMV sys.dm_exec_requests ou mesmo a cláusula STATS no comando de backup / restore podem resolver, porém se for necessário um acompanhamento mais detalhado, principalmente para grandes bancos de dados (VLDB), pois nestes casos, mesmo após a exibição de 100% do progresso, pode-se demorar um tempo considerável, é possível a utilização deste novo XE juntamente com os traceflags mencionados neste blog post, e conseguir com isso um excelente detalhamento do processo como um todo.

Referências:

• New extended event to track backup and restore progress
  • http://blogs.msdn.com/b/sql_server_team/archive/2015/09/22/new-extended-event-to-track-backup-and-restore-progress.aspx#.VgtLzHpVhBd
• Instant File Intialization
  • http://msdn.microsoft.com/en-us/library/ms175935.aspx