Transaction Log, LSN, DBCC LOGINFO e VLFs (Backup/Restore – Parte 3 de ?)
Continuando com o assunto de backup e restore e conforme dito no último artigo, vamos analisar o funcionamento do log de transação com o modo de recuperação full.
Em primeiro lugar, vamos criar o banco de dados InsideTLog (passo 00). Alterei o nome do banco de dados para facilitar a visualização dos backups na tabela backupset, mas se você quiser utilizar outro nome para este banco use o “find + replace” e escolha um novo nome. Para garantirmos o comportamento do recovery model full, fazemos um backup completo do banco (passo 01). Se necessário, altere o caminho do arquivo.
Depois de inserirmos 1200 registros (passos 03 e 04), conseguimos perceber que a situação dos VLFs no log de transação está bem diferente do que vimos no artigo anterior (recovery model simple).
/*
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 6 2 64 0
2 253952 262144 0 0 0 0
2 270336 516096 7 2 64 6000000048100001
2 262144 786432 8 2 64 7000000051300001
2 262144 1048576 9 2 64 8000000049500001
2 262144 1310720 10 2 64 9000000050000001
2 262144 1572864 11 2 64 10000000051000001
*/
Agora podemos ver o SQL Server realmente trabalhando com recovery model full. Ele foi criando outros VLFs sempre que necessário e, como é obrigado a manter as transações no log até que um backup de log ou um truncate seja feito, todos os VLFs utilizados até o momento são marcados como ativos.
Outro detalhe interessante: Vejam que o CreateLSN do FSeqNo 7 é iniciado com 6. O FSeqNo do VLF 8 é iniciado por 7. Assim por diante... Isso não é mera coincidência.
O número do LSN na verdade é composto de três partes e - acho que - já deu para perceber qual é uma delas, certo? Então vemos através do CreateLSN que os novos VLFs são criados quando o VLF anterior está ativo (seguindo a sequência natural destes), sempre que o SQL Server percebia que necessitava de mais espaço para o log de transação.
Curiosamente continuamos com o segundo VLF não utilizado, eu tenho um palpite sobre isso: O SQL Server pode manter diversos estados para o log manager. Quando o SQL Server anuncia que o log de transação está cheio, na verdade internamente ele ainda está com um pequeno espaço reservado para informações (logs) críticas. Acredito que este pequeno espaço no qual o SQL Server tenta manter pode ser este VLF, mas não posso afirmar com certeza.
Agora vamos ver como os VLFs se comportam com a inserção de N registros paralelamente a execução de backups de log e DBCC LOGINFO (passo 05). Analisando a saída do DBCC LOGINFO após cancelarmos as inserções (passo 06), temos:
DBCC LOGINFO('InsideTLog')
go
/*
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 238 0 64 0
2 253952 262144 250 2 64 0
2 270336 516096 239 0 64 6000000048100001
2 262144 786432 240 0 64 7000000051300001
2 262144 1048576 241 0 64 8000000049500001
2 262144 1310720 242 0 64 9000000050000001
2 262144 1572864 243 2 64 10000000051000001
2 262144 1835008 244 2 64 11000000050300001
2 262144 2097152 245 2 64 12000000050700001
2 262144 2359296 246 2 64 13000000049800001
2 262144 2621440 247 2 64 14000000049700001
2 327680 2883584 248 2 64 15000000050800001
2 327680 3211264 249 2 64 16000000063200001
2 393216 3538944 251 2 64 17000000063900001
2 393216 3932160 252 2 64 19000000039100003
2 458752 4325376 253 2 64 20000000040700004
2 253952 4784128 255 2 64 21000000053600008
2 270336 5038080 254 2 64 21000000053600008
2 253952 5308416 259 2 64 23000000013600003
2 270336 5562368 256 2 64 23000000013600003
2 253952 5832704 258 2 64 24000000052300003
2 335872 6086656 257 2 64 24000000052300003
2 253952 6422528 261 2 64 27000000013500004
2 401408 6676480 260 2 64 27000000013500004
2 253952 7077888 204 0 128 28000000078300001
2 466944 7331840 262 2 64 28000000078300001
2 253952 7798784 207 0 128 31000000012400001
2 253952 8052736 206 0 128 31000000012400001
2 278528 8306688 205 0 128 31000000012400001
2 253952 8585216 210 0 128 34000000013600003
2 253952 8839168 209 0 128 34000000013600003
2 344064 9093120 208 0 128 34000000013600003
2 253952 9437184 213 0 128 36000000049500001
2 253952 9691136 212 0 128 36000000049500001
2 475136 9945088 211 0 128 36000000049500001
2 253952 10420224 217 0 128 39000000049500001
2 253952 10674176 216 0 128 39000000049500001
2 253952 10928128 215 0 128 39000000049500001
2 286720 11182080 214 0 128 39000000049500001
2 262144 11468800 221 0 128 44000000013500003
2 262144 11730944 220 0 128 44000000013500003
2 262144 11993088 219 0 128 44000000013500003
2 393216 12255232 218 0 128 44000000013500003
2 327680 12648448 225 0 128 48000000015200012
2 327680 12976128 224 0 128 48000000015200012
2 327680 13303808 223 0 128 48000000015200012
2 327680 13631488 222 0 128 48000000015200012
2 327680 13959168 233 0 128 52000000028000004
2 327680 14286848 228 0 128 52000000028000004
2 327680 14614528 227 0 128 52000000028000004
2 458752 14942208 226 0 128 52000000028000004
2 393216 15400960 237 0 128 56000000027900003
2 393216 15794176 236 0 128 56000000027900003
2 393216 16187392 235 0 128 56000000027900003
2 393216 16580608 234 0 128 56000000027900003
2 393216 16973824 232 0 64 110000000027900004
2 393216 17367040 231 0 64 110000000027900004
2 393216 17760256 230 0 64 110000000027900004
2 524288 18153472 229 0 64 110000000027900004
*/
Como os VLFs são muito pequenos, podemos ver que os mais antigos são marcados como inativos, mas muitos ficam ativos porque as inserções preenchem o espaço dos VLFs rapidamente. Atualmente temos o VLF 243 como o primeiro ativo da seqüência.
Vamos alterar o exemplo para arrumar a casa e melhorar o entendimento, fazendo primeiro um truncate do log seguido de um encolhimento do arquivo (passo 06).
Um truncate do log de transação nada mais é que um backup de log jogando as informações fora (eu ia usar a palavra limbo, mas já que está em vias de extinção...).
Após a execução do comando, como esperado somente o último VLF (FSeqNo = 262) foi marcado como ativo. Isso acontece porque não existe nenhuma transação aberta em um VLF mais antigo, então todos os outros VLFs podem ser marcados como inativos.
O log de transação que está atualmente com 18240 KB (18 MB) e será encolhido para 2MB. Analisando o resultado do procedimento (passo 07) temos:
DBCC LOGINFO('InsideTLog')
go
/*
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 263 0 128 0
2 253952 262144 250 0 64 0
2 270336 516096 264 2 128 6000000048100001
2 262144 786432 240 0 64 7000000051300001
2 262144 1048576 241 0 64 8000000049500001
2 262144 1310720 242 0 64 9000000050000001
2 262144 1572864 243 0 64 10000000051000001
2 262144 1835008 244 0 64 11000000050300001
*/
Agora ficamos com os VLFs que estão no início do arquivo. Vejam o CreateLSN (Déjà vu??).
Após crescermos o log para ficarmos com VLFs maiores (Passo 08), podemos ver a nova distribuição dos VLFs (passo 09):
DBCC LOGINFO('InsideTLog')
go
/*
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 263 0 128 0
2 253952 262144 250 0 64 0
2 270336 516096 264 2 128 6000000048100001
2 262144 786432 240 0 64 7000000051300001
2 262144 1048576 241 0 64 8000000049500001
2 262144 1310720 242 0 64 9000000050000001
2 262144 1572864 243 0 64 10000000051000001
2 262144 1835008 244 0 64 11000000050300001
2 12582912 2097152 0 0 0 264000000004100001
2 12582912 14680064 0 0 0 264000000004100001
2 12582912 27262976 0 0 0 264000000004100001
2 12582912 39845888 0 0 0 264000000004100001
*/
Agora temos mais quatro VLFs, todos com 12.5 MB (50 % 4) e criados no mesmo momento, quando o VLF ativo é o 264 (mesmo CreateLSN para os novos VLFs). Quando o log de transação cresce em blocos maiores, não ficamos com muitos VLFs pequenos.
A tabela que define a quantidade de VLFs criados de acordo com o tamanho do bloco de crescimento pode ser vista na seguinte apresentação:
https://support.microsoft.com/servicedesks/webcasts/wc082900/wc082900.ppt
Vamos re-executar as inserções e backups (passo 10), agora o resultado deve ser mais interessante já que temos VLFs maiores...
/*
(**BackupLog - 01**)
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 263 0 128 0
2 253952 262144 250 0 64 0
2 270336 516096 264 0 128 6000000048100001
2 262144 786432 240 0 64 7000000051300001
2 262144 1048576 241 0 64 8000000049500001
2 262144 1310720 242 0 64 9000000050000001
2 262144 1572864 243 0 64 10000000051000001
2 262144 1835008 244 0 64 11000000050300001
2 12582912 2097152 0 0 0 264000000004100001
2 12582912 14680064 0 0 0 264000000004100001
2 12582912 27262976 266 2 64 264000000004100001
2 12582912 39845888 265 2 64 264000000004100001
(12 row(s) affected)
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
There is no current database backup. This log backup cannot be used to roll forward a preceding database backup.
Processed 5 pages for database 'InsideTLog', file 'InsideTLog_log' on file 1.
BACKUP LOG successfully processed 5 pages in 0.165 seconds (0.238 MB/sec).
(**BackupLog - 02**)
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 263 0 128 0
2 253952 262144 250 0 64 0
2 270336 516096 264 0 128 6000000048100001
2 262144 786432 240 0 64 7000000051300001
2 262144 1048576 241 0 64 8000000049500001
2 262144 1310720 242 0 64 9000000050000001
2 262144 1572864 243 0 64 10000000051000001
2 262144 1835008 244 0 64 11000000050300001
2 12582912 2097152 268 2 64 264000000004100001
2 12582912 14680064 267 2 64 264000000004100001
2 12582912 27262976 266 2 64 264000000004100001
2 12582912 39845888 265 0 64 264000000004100001
(12 row(s) affected)
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Processed 2368 pages for database 'InsideTLog', file 'InsideTLog_log' on file 1.
BACKUP LOG successfully processed 2368 pages in 1.300 seconds (14.916 MB/sec).
(**BackupLog - 03**)
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 275 2 64 0
2 253952 262144 274 2 128 0
2 270336 516096 276 2 64 6000000048100001
2 262144 786432 269 2 128 7000000051300001
2 262144 1048576 270 2 128 8000000049500001
2 262144 1310720 271 2 128 9000000050000001
2 262144 1572864 272 2 128 10000000051000001
2 262144 1835008 273 2 128 11000000050300001
2 12582912 2097152 268 2 64 264000000004100001
2 12582912 14680064 267 0 64 264000000004100001
2 12582912 27262976 266 0 64 264000000004100001
2 12582912 39845888 277 2 128 264000000004100001
(12 row(s) affected)
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Processed 2302 pages for database 'InsideTLog', file 'InsideTLog_log' on file 1.
BACKUP LOG successfully processed 2302 pages in 2.098 seconds (8.986 MB/sec).
(**BackupLog - 04**)
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 275 0 64 0
2 253952 262144 274 0 128 0
2 270336 516096 276 0 64 6000000048100001
2 262144 786432 269 0 128 7000000051300001
2 262144 1048576 270 0 128 8000000049500001
2 262144 1310720 271 0 128 9000000050000001
2 262144 1572864 272 0 128 10000000051000001
2 262144 1835008 273 0 128 11000000050300001
2 12582912 2097152 268 0 64 264000000004100001
2 12582912 14680064 279 2 128 264000000004100001
2 12582912 27262976 278 2 128 264000000004100001
2 12582912 39845888 277 2 128 264000000004100001
(12 row(s) affected)
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Processed 2327 pages for database 'InsideTLog', file 'InsideTLog_log' on file 1.
BACKUP LOG successfully processed 2327 pages in 1.251 seconds (15.235 MB/sec).
(**BackupLog - 05**)
FileId FileSize StartOffset FSeqNo Status Parity CreateLSN
----------- --------------------------------------- --------------------------------------- ----------- ----------- ------ ---------------------------------------
2 253952 8192 275 0 64 0
2 253952 262144 274 0 128 0
2 270336 516096 276 0 64 6000000048100001
2 262144 786432 269 0 128 7000000051300001
2 262144 1048576 270 0 128 8000000049500001
2 262144 1310720 271 0 128 9000000050000001
2 262144 1572864 272 0 128 10000000051000001
2 262144 1835008 273 0 128 11000000050300001
2 12582912 2097152 280 2 128 264000000004100001
2 12582912 14680064 279 2 128 264000000004100001
2 12582912 27262976 278 0 128 264000000004100001
2 12582912 39845888 277 0 128 264000000004100001
*/
Agora conseguimos ver melhor os VLFs sendo utilizados e marcados como inativos, fazendo o TLOG circular e manter um tamanho constante. Também vemos claramente que quando os VLFs maiores são utilizados, somente um ou dois ficam ativos, e quando os pequenos estão em uso diversos deles ficam ativos, pois são preenchidos rapidamente.
Cruzando os dados do DBCC LOGINFO com o histórico de backups do MSDB (passo 11), podemos ver o relacionamento entre VLFs e backupset.
select backup_set_id, database_name, first_lsn, last_lsn, checkpoint_lsn, database_backup_lsn,database_creation_date, type
from MSDB..backupset as BSW
where database_name = 'InsideTLog'
AND last_lsn > 265000000000000000
AND type = 'L'
order by backup_set_id asc
/*
backup_set_id database_name first_lsn last_lsn checkpoint_lsn database_backup_lsn database_creation_date type
------------- -------------------------------------------------------------------------------------------------------------------------------- --------------------------------------- --------------------------------------- --------------------------------------- --------------------------------------- ----------------------- ----
183 InsideTLog 266000001694800001 266000001702500001 266000001694800001 6000000002400003 2007-04-30 10:52:52.000 L
184 InsideTLog 266000001702500001 268000000577800001 266000001694800001 6000000002400003 2007-04-30 10:52:52.000 L
185 InsideTLog 268000000577800001 277000001409000001 268000000600200001 6000000002400003 2007-04-30 10:52:52.000 L
186 InsideTLog 277000001409000001 279000000219700001 277000001425600001 6000000002400003 2007-04-30 10:52:52.000 L
187 InsideTLog 279000000219700001 280000001471300001 279000000240500002 6000000002400003 2007-04-30 10:52:52.000 L
*/
Utilizamos o SELECT com os filtros acima porque quando executamos o primeiro backup de log, o menor VLF ativo era o 265 (Vide **BackupLog - 01**). Nota-se ainda que o last_lsn do backupset 187 é 280000001471300001, o que bate com a saída do VLF ativo no momento (#280).
(**BackupLog - 02**) - Coincide com o backup_set_id 184
* first_lsn = 266000001702500001 e last_lsn = 268000000577800001
* VLFs ativos: 266, 267 e 268
(**BackupLog - 03**) - Coincide com o backup_set_id 185
* first_lsn = 268000000577800001 e last_lsn = 277000001409000001
* VLFs ativos: 268, 269, 270, 271, 272, 273, 274, 275, 276 e 277 (VLFs pequenos)
(**BackupLog - 04**) - Coincide com o backup_set_id 186
* first_lsn = 277000001409000001 e last_lsn = 279000000219700001
* VLFs ativos: 277, 278 e 279
(**BackupLog - 05**) - Coincide com o backup_set_id 187
* first_lsn = 279000000219700001 e last_lsn = 280000001471300001
* VLFs ativos: 279 e 280
Por fim, verifique a situação do DBCC LOGINFO (passo 12), tire um backup de log e cheque o backupset (passo 13). Veremos então que o first_lsn e last_lsn estão dentro do VLF 280, que é o único ativo no momento.
Importante: o DBCC LOGINFO é um comando não documentado (mas atualmente de conhecimento público) e a qualquer momento o time do produto pode optar por tirar essa funcionalidade, então utilize esse recurso por sua conta e risco.
Outro dia continuarei com nossos artigos de backup e restore... Até lá!
[]s
Luciano Caixeta Moreira
=============================================================
This posting is provided "AS IS" with no warranties, and confers no rights
=============================================================
20070501 - Transaction Log - LSN - VLFs (backup-restore parte 3).zip