Point in time recovery and fn_dump_dblog()

For starters and to create some content I will simply translate articles I’ve already written for the past 3 years in french. Actually I am no lazy writer, but this is quite difficult to find original subjects for articles, so much has already been written. In time, I’ll come up with 100% new articles.

For this first one, we’ll be discussing point in time recovery using an undocumented TVF I’ve bumped into when trying to get my hands on OPENROWSET internals.

I want to do PIT recovery, what are my options ?

When you think of point in time recovery, first thing that comes to mind is STOPAT / STOPATMARK / STOPBEFOREMARK keywords used in conjunction with the RESTORE DATABASE command. Either you can stop the restore operation using a date (STOPAT) or using a transaction name (STOPATMARK/STOPBEFOREMARK). But in the end, I find these approaches quite unpractical: you never know the exact time your colleague has deleted a couple of rows by mistake. If he says the delete occured at about 13h45, this is quite imprecise in a real life environment with hundreds of transactions per second. Maybe the delete really occured at 13h47, and if you decide to restore at 13h45, you will potentially discard committed transactions, not pretty good…

Or you could use named transactions to restore at or before a specific transaction. Again in real life, who uses explicit named transactions ? I know this is a good practice to name transactions in T-SQL developments, but objectively, it is still barely implemented. The final solution would be to use another syntax of STOPATMARK /STOPBEFOREMARK:

RESTORE LOG ... WITH STOPBEFOREMARK = 'lsn:'

Now the real problem with this syntax is how do you find the LSN values for each transaction in a transaction log backup ?

Enter fn_dump_dblog():

If you copy the MDF/LDF files of a resource database and attach them, you will eventually discover this TVF burried in the system objects list:

create function sys.fn_dump_dblog
(
@start    nvarchar (25) = NULL,
@end      nvarchar (25) = NULL,
@devtype  nvarchar (260) = NULL, -- NULL(DISK) | DISK | TAPE | VIRTUAL_DEVICE
@seqnum   Int         = 1,
@fname1   nvarchar (260) = NULL,
@fname2   nvarchar (260) = NULL,
@fname3   nvarchar (260) = NULL,
...
@fname64   nvarchar (260) = NULL
)
returns table
as
return select
[Current LSN],  [Operation],  [Context],  [Transaction ID],   [Tag Bits],
[Log Record Fixed Length],  [Log Record Length],   [Previous LSN],
(...)
from OpenRowset (DBLog, @start, @end, @devtype, @seqnum,
@fname1,  @fname2,  @fname3,  @fname4,  @fname5,
(...)
@fname62,  @fname63,  @fname64)

It takes an awful lot of @fname arguments, and as long it is neither documented nor supported, I don’t even know if all those arguments are even used in the underlying code, but one of them is very interesting: @devtype. It typically takes the path of a transaction log backup, and the function returns an output similar to fn_dblog(), including the LSN of each LOP_BEGIN_XACT operator. Let’s have a try.

Oops, I’ve deleted some data by mistake

Forgetting a where clause in a DML statement can happen to anybody, but using fn_dump_dblog() in conjunction with the standby mode of a restore allows us to restore to the transaction just before the mistake. Let’s create some data to illustrate this:

use master
GO
if exists (select 1 from sys.databases where name='demorecovery')
 drop database demorecovery
GO
create database demorecovery
GO

use demorecovery
GO
create table T1(
 a numeric identity,
 b char(4000) default replicate('b',4000),
 c bigint default round(rand()*100,0))
GO
insert into T1 default values
GO 1000
create unique clustered index IDX_T1C on T1(a)
GO
create index IDX_T1NC__c on T1(c)
GO

And switch to full recovery model:

alter database demorecovery set recovery full
GO
backup database demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_FULL.bak' with init, stats
GO

Let’s create some transactions and backup them:

delete from T1 where a < 10
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG1.bak' with init, stats
GO
delete from T1 where a < 20
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG2.bak' with init, stats
GO
delete from T1 where a < 30
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG3.bak' with init, stats
GO

Another two xacts and then the manual mistake:

delete from T1 where a < 40
GO
delete from T1 where a < 50
GO
delete from T1 where a < 60  -- <-- Oh my 😦
GO
backup log demorecovery to disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with init, stats
GO

Gone Fishing

First thing is to cut down the applications, to avoid further transaction processing past your potential recovery point. You can switch the database to single user mode with rollback immediate to do that. And then, we need to recover the database to the point in time before the last 10 rows are removed by mistake. We are going to use a combination of restore log with standby and fn_dump_dblog to do this. First we need to identify the different transactions embedded in the log backup taken just after the delete. This is when fn_dump_dblog comes in:

select *, [Current LSN]
 ,Operation
 ,[Transaction ID]
 ,AllocUnitId
 ,[Begin Time]
 ,[Transaction Name]
 ,[End Time]
 ,[Description]
from fn_dump_dblog(DEFAULT, DEFAULT,DEFAULT, DEFAULT,
'C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak',
DEFAULT,DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT)
where Operation  = 'LOP_BEGIN_XACT'

Current LSN             Operation         Transaction ID  Begin Time               Transaction Name    Description
----------------------- ----------------- --------------  ------------------------ ------------------- -----------------------------------------------------------------------
00000041:00000338:000e  LOP_BEGIN_XACT    0000:000008b8   2011/07/13 15:59:43:580  DELETE              DELETE;0x0105000000000005150000006aa3aebb1b5c3491642b62e2e8030000
00000042:00000021:0001  LOP_BEGIN_XACT    0000:000008b9   2011/07/13 15:59:43:587  DELETE              DELETE;0x0105000000000005150000006aa3aebb1b5c3491642b62e2e8030000
00000042:00000076:0001  LOP_BEGIN_XACT    0000:000008ba   2011/07/13 15:59:43:630  DELETE              DELETE;0x0105000000000005150000006aa3aebb1b5c3491642b62e2e8030000

So we have three candidates: 00000041:00000338:000e, 00000042:00000021:0001 and 00000042:00000076:0001. We have to manually try each one using the standby mode to reach exactly the point of recovery. First we need to restore the first set of backups :

restore database demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_FULL.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG1.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG2.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG3.bak' with stats, norecovery
GO

Let’s restore to the first transaction and see if our missing data is here:

restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
standby='C:\UTRECHT\MSSQL.1\MSSQL\Backup\stdby_files.bak', stopbeforemark='lsn:0x00000042:00000021:0001'
GO

select state_desc, is_in_standby from sys.databases where name='demorecovery'
GO

state_desc    is_in_standby
------------- --------------
ONLINE        1

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----
40     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 31
41     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 28
42     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 77
43     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 18
44     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 12
45     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 42
46     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
47     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 46
48     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 39
49     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 74
50     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 45
51     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
52     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 32
53     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 10
54     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
55     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 99
56     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 71
57     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 38
58     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
59     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 41

Still here. So the point is a little bit forward. Let’s recover the second transaction:

use master
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
standby='C:\UTRECHT\MSSQL.1\MSSQL\Backup\stdby_files.bak', stopbeforemark='lsn:0x00000042:00000076:0001'
GO

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----
50     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 45
51     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
52     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 32
53     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 10
54     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
55     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 99
56     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 71
57     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 38
58     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
59     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 41

Closing in. We can recover the last transaction to confirm:

use master
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
standby='C:\UTRECHT\MSSQL.1\MSSQL\Backup\stdby_files.bak'
GO

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----

Looks like that’s our point. We need to restore the full backup sets over again and apply all transactions up to LSN ‘0x00000042:00000076:0001’:

use master
GO
restore database demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_FULL.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG1.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG2.bak' with stats, norecovery
GO
restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG3.bak' with stats, norecovery
GO

restore log demorecovery from disk='C:\UTRECHT\MSSQL.1\MSSQL\Backup\demorecovery_LOG4.bak' with stats,
stopbeforemark='lsn:0x00000042:00000076:0001', recovery
GO

use demorecovery
GO
select * from T1 where a < 60
GO

a      b                            c
------ ---------------------------- ----
50     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 45
51     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
52     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 32
53     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 10
54     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
55     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 99
56     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 71
57     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 38
58     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 2
59     bbbbbbbbbbbbbbbbbbbbbbbbbbbb 41

Note that there is no way to apply further transactions past the recovery point, even if they happear to be 100% valid. It means that the fastest you are aware of the problem the littlest transactions you’ll lose.

Résumé:

Finally a way to recover to the exact point in time you need, thanks to an undocumented function.

See you next time. ~David

Advertisements

About dbaffaleuf

I've been in the IT for a decade administering mission critical RDBMS systems such as Sybase ASE and Microsoft SQL Server, for some of the largests investment banks, asset managers and telecoms in France. I came to the position of principal consultant on SQL Server technologies at CapData Consulting in 2006, where I still manage a team of senior DBAs, do expertise jobs and software support for our remote monitoring solutions. I also have the privilege of sharing my experience by teaching classes on SQL Server topics, and blogging in french at http://blog.capdata.fr and in english at SQL Server Central. (http://www.sqlservercentral.com/Authors/Articles/David__Baffaleuf/405129/).
This entry was posted in Backup & Recovery and tagged . Bookmark the permalink.

One Response to Point in time recovery and fn_dump_dblog()

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s