Topic: This post is about lost writes in Oracle and in particular on techniques to reproduce and investigate the effects of lost writes in a test environment and with Data Guard
Motivations: Imagine this scenario: a production system has two standbys to protect against disaster and to load balance read-only load (with Active Data Guard (ADG)). A lost write happens in the primary and remains unnoticed for a few days. Finally the block that suffered a lost write is updated again. Both standbys stop applying redo throwing ORA-600 [3020] (also known as stuck recovery). The primary DB keeps working fine, although it is logically corrupted by the lost write.
You are the DBA in charge of fixing this, what would you do?
The importance of testing: I hope that the example above illustrates that lost write can generate quite complex recovery scenarios and overall a few headaches to support DBAs. In this post I illustrate a few techniques and examples that can be used to test the effects of lost writes in Oracle and therefore prepare in case of a real-world issue strikes. Of particular interest will be to test the effect of lost writes in an environment with (Active) Data Guard.
We need to cover some ground first on techniques and how to setup the test. But first a definition.
Lost writes: "A data block lost write occurs when an I/O subsystem acknowledges the completion of the block write, while in fact the write did not occur in the persistent storage" (from support note 1302539.1). Lost writes can be caused by faulty storage, but also anything in between our data in RAM (in the buffer cache, for example) and disk storage can potentially cause similar effects, this list includes also potential Oracle bugs.
Digression on techniques.
1. A useful technique that we will need in the following is the ability to read and write a single block from Oracle data files (in a test environment). For databases on filesystems (and also DBs on NFS) dd is the tool for this job (I am using the Linux platform as reference). Examples:
read one 8KB block from filesystem (block 134 in this example):
dd if=testlostwrite.dbf bs=8192 count=1 skip=134 of=blk134.dmp conv=notrunc
write one 8KB block to filesystem (block 134 in this example)::
dd of=testlostwrite.dbf bs=8192 count=1 seek=134 if=blk134.dmp conv=notrunc
Note when writing we must use
conv=notrunc or else we will end up with an unusable output file. Note also the syntax for specifying the block offset, skip is used for input files (reads) and seek for output files (writes).
How to read and write single blocks on ASM data files. One possibility is to take a backup copy of the datafile with RMAN, edit it with
dd (as detailed above), then (with rman again) restore the backup copy. With a little knowledge of
ASM internals, more direct ways to access files in ASM are available: one can find the position of the block (and its mirror copies if relevant) and then use
dd to read/write data directly. Currently my preferred way is sightly different and it exploits the dbms_diskgroup package. This is an undocumented package (see again the link above on ASM internals for some additional details) although it is extensively used by Oracle's
asmcmd utility. I have packaged the dbms_diskgroup.read and dbms_diskgroup.write calls into a small utility written in perl (that I called asmblk_edit, follow
this link to download asmblk_edit). Similar ideas can be found also in support note 603962.1.
The following example illustrates using the utility asmblk_edit to read and write block number 134 from and to a data files stored in ASM:
read one 8KB block from an Oracle data file in ASM (block 134 in this example):
./asmblk_edit -r -s 134 -a +TESTDB_DATADG1/TESTDB/datafile/testlostwrite.353.810578639 -f blk134.dmp
write one 8KB block to and Oracle data file in ASM (block 134 in this example):
./asmblk_edit -w -s 134 -a +TESTDB_DATADG1/TESTDB/datafile/testlostwrite.353.810578639 -f blk134.dmp
2. Another technique that we need is quite straightforward and allows us to find the offset of the Oracle block that we want to read/write to for our tests.
The example here below shows how to find block number where data is stored, using rowid:
SQL> select rowid, dbms_rowid.ROWID_BLOCK_NUMBER(rowid), a.* from testlosttable a;
Incidentally finding the block number for an index leaf block can be done with the following (using the undocumented function sys_op_lbid):
SQL> select rowid rowid_table_from_index_leaf, sys_op_lbid(18297477,'L',t.rowid) index_leaf_rowid from testlosttable t --note: 18297477 in this example is the data_object_id of the index I am examining, edit with the actual number as needed
3. Last but not least, we need a way to modify data blocks 'under the nose of Oracle', in particular we want to make sure we flush/invalidate the relevant cached data and metadata. The method we will use in the following is:
- Offline the tablespace where data resides (this flushes dirty blocks and invalidates cache entries)
- Perform the read/write modifications to the block, with dd or asmblk_edit, as needed
- Online the tablespace again before next usage
A basic recipe to reproduce the effects of a lost write.
We can now put together the ideas and techniques described above into a working example aimed at reproducing the effects of a lost write in Oracle:
SQL> create bigfile tablespace testlostwrite datafile '..{path to datafile}../testlostwrite.dbf' size 10m;
SQL> create table testlosttable (id number, payload varchar2(100)) tablespace testlostwrite ;
SQL> create index i_testlosttable on testlosttable (id) tablespace testlostwrite ;
SQL> insert into testlosttable values (10,'aaaaaaaaaaaaaaaaaaaaaaaaa');
SQL> insert into testlosttable values (20,'bbbbbbbbbbbbbbbbbbbbbbbbb');
SQL> commit;
SQL> select rowid, dbms_rowid.ROWID_BLOCK_NUMBER(rowid), a.* from testlosttable a;
--note: this will allow to find the block_id where data resides, let's say it's block 134
SQL> alter tablespace testlostwrite offline;
-- read block either with dd or with asmblk_edit and create backup copy. Example:
-- ./asmblk_edit -r -s 134 -a +TESTDB_DATADG1/TESTDB/datafile/testlostwrite.353.810578639 -f blk134.dmp
SQL> alter tablespace testlostwrite online;
SQL> insert into testlosttable values (30,'cccccccccccccccccccccccccc');
SQL> commit;
SQL> alter tablespace testlostwrite offline;
-- write block either with dd or with asmblk_edit and from previously created backup copy. Example:
-- ./asmblk_edit -w -s 134 -a +TESTDB_DATADG1/TESTDB/datafile/testlostwrite.353.810578639 -f blk134.dmp
SQL> alter tablespace testlostwrite online;
SQL> -- our database has now a lost write in the table testlosttable block 134
The effect of the lost write on the table is that the row with id=30 has disappeared from the table. However the entry with id=30 is still visible in the index. This observation can be confirmed with the 2 queries reported here. Note that in case of normal operations (i.e. no lost writes) the 2 queries should both return three rows, this is not the case here because of our manual editing of the table block.
SQL> select /*+ INDEX_FFS(a)*/ id from testlosttable a where id is not null;
SQL> select /*+ FULL(a)*/ id from testlosttable a;
SQL> -- these 2 queries return different results in our test with a lost write.. and only one of them is correct!
We can now proceed with a very interesting test: insert another row of data into the table, for example:
SQL> insert into testlosttable values (40,'ddddddddddddddddddddddd');
SQL> commit;
What we should notice notice at this point is that Oracle keeps working fine and no errors are shown to the user. With the techniques discussed above we can easily show that this new row has been inserted into block 134 (the block with a lost write). Let's postpone further investigations for a later paragraph and for now just note that Oracle cannot easily find out that we have suffered a lost write.
An example of the effects of lost writes with Standby (Data Guard).
A standby database provides a copy of the database that Oracle can use to detect lost writes (i.e. the standby provides a reference of 'good data; in first approximation). Let's see how we can test how this works in practice:
- We start by going through the same steps described above and we create a lost write in the primary.
- Note that at this point the standby has no knowledge that something has gone wrong in the primary.
- Now we can go ahead and run DML against the block that has suffered the lost write
- i.e. we insert the row with id=40 as detailed above.
- At the moment when the standby database will try to apply the 'redo' (change vector) to the block with a lost write, it will compare SCN numbers and find that 'something is wrong'. MRP will stop and throw ORA-600 [3020] (stuck recovery).
Example of the error stack for a stuck recovery. Note that ORA-600 [3020] can be caused by a lost write (as in this example) but also by other issues, in particular with the redo consistency (outside the scope of this discussion):
ORA-00600: internal error code, arguments: [3020], [10], [134], [134], [], [], [], [], [], [], [], []
ORA-10567: Redo is inconsistent with data block (file# 10, block# 134, file offset is 1097728 bytes)
ORA-10564: tablespace TESTLOSTWRITE
ORA-01110: data file 10: '+STDBY_DATADG1/TESTDB/datafile/testlostwrite.347.810578685'
ORA-10561: block type 'TRANSACTION MANAGED DATA BLOCK', data object# 18299147
Note: additional information is dumped in the trace files of MRP and of the recovery slaves
Oracle 11g and lost write protection.
In our previous example to reproduce lost write effects, Oracle will only throw an error (ORA-600 [3020], aka stuck recovery) when a DML operation is performed on the primary DB against a block that had suffered a lost write. This means that in practice lost writes may remain silently unnoticed in the primary for an unlimited period of time. A new feature of 11g can be used to make Oracle look for lost writes also in blocks used for queries (in the primary). This is what we can do to use it:
- we set DB_LOST_WRITE_PROTECT = TYPICAL (or FULL if we prefer) on the primary database. This will cause the generation of additional redo entries when Oracle performs physical reads.
- we set DB_LOST_WRITE_PROTECT = TYPICAL on the standby, this will make MRP and its recovery slaves to check for lost writes using the extra information in the redo log stream.
- If we hit a lost write MRP and its slaves will stop and throw ORA-752: recovery detected a lost write of a data block
An example of the error stack for lost writes with db_lost_write_protect set to typical is pasted here below. In comparison with ORA-600 [3020] seen above, in this case we have more relevant information, also Oracle has checked that this is a case of lost write and has even tried to resolve the 'logical corruption' trying to read the second mirror copy from the ASM diskgroup (which could not help in this case).
Hex dump of (file 10, block 134) in trace file {path..}/standby_pr09_26471.trc
Reading datafile '+STDBY_DATADG1/TESTDB/datafile/testlostwrite.347.810578685' for corruption at rdba: 0x00000086 (file 10, block 134)
Read datafile mirror 'STDBY_DATADG1_0000' (file 10, block 134) found same corrupt data (logically corrupt)
Read datafile mirror 'STDBY_DATADG1_0011' (file 10, block 134) found same corrupt data (logically corrupt)
STANDBY REDO APPLICATION HAS DETECTED THAT THE PRIMARY DATABASE
LOST A DISK WRITE OF BLOCK 134, FILE 10
NO REDO AT OR AFTER SCN 6367748422450 CAN BE USED FOR RECOVERY.
ORA-00752: recovery detected a lost write of a data block
ORA-10567: Redo is inconsistent with data block (file# 10, block# 134, file offset is 1097728 bytes)
ORA-10564: tablespace TESTLOSTWRITE
ORA-01110: data file 10: '+STDBY_DATADG1/TESTDB/datafile/testlostwrite.347.810578685'
ORA-10561: block type 'TRANSACTION MANAGED DATA BLOCK', data object# 18299538
Note: additional information is dumped in the trace files of MRP and of the recovery slaves
Digression on DB_LOST_WRITE_PROTECT.
A comment: from the discussion above we see that the extra checks that oracle recovery process does when setting DB_LOST_WRITE_PROTECT are definitely an improvement from 10g behavior, although this mechanism
does not provide a complete protection against lost writes but only gives us a higher probability that a lost write will be found.
How about the
impact in production of this parameter? Extra redo entries are generated on the primary: they are called block read redo (BRR). We can directly investigate BRR entries with 2 simple techniques: dumping redo (BRR corresponds to redo at
layer 23 and opcode 2) and querying v$mystat or v$sysstat (we will look for stats with 'lost write' in their name).
Example SQL:
SQL> alter system dump logfile '...{path to storage}.../thread_2_seq_1816.510.810661967' layer 23 opcode 2;
SQL> select name, sum(value) from v$mystat se, v$statname n where n.statistic#=se.statistic# and (n.name like '%lost write%' or name like '%physical read%') group by name;
The size of BRR entries in the redo stream varies, as redo dumps show that and a few optimizations can come into play (such as batching more entries in one redo record). Based on a few observations of a production system I estimate than on average we can expect 30 bytes of extra redo generated by BRR for each physical block read performed by the database, although mileage may vary and definitely the impact of the parameter should be tested before applying it to a busy production! Another observation based on testing is that direct read operations (for example reads for parallel query) do not generate BRR.
On a standby instance Oracle sets
_db_lost_write_checking (enable scn-based lost write detection mechanism) to the value 2 (based on observation of my test system 11.2.0.3). MRP slaves do the extra work of checking for lost writes
by comparing SCNs in BRRs with SCN in the block headers. Notably the extra work implies additional physical reads on the standby. This can be seen in v$sysstat (statistics name = 'recovery blocks read for lost write detection' and also the related stat 'recovery blocks skipped lost write checks').
Example of BRR entry from a logfile dump:
CHANGE #5 TYP:0 CLS:4 AFN:10 DBA:0x00000086 OBJ:18299943 SCN:0x05ca.9b6e95f9 SEQ:1 OP:23.2 ENC:0 RBL:1
Block Read - afn: 10 rdba: 0x00000086 BFT:(1024,134) non-BFT:(0,134)
scn: 0x05ca.9b6e95f9 seq: 0x01
flags: 0x00000004 ( ckval )
After setting db_lost_write_protect to typical (or full) and rebooting the instance Oracle will set _log_committime_block_cleanout to true (based on observations on my test system 11.2.03). The effect is that (on the primary instances) Oracle will write into the redo logs additional entries related to block cleanout operations (layer 4 opcode 6). I would comment that logging block cleanout redo record (and subsequently applying them to the standby database) is a desirable feature especially in the case of Active Data Guard.
Note: checks for lost write based on SCN from BRR entries are performed also when doing media recovery (for example recover database command). Therefore even if Data Guard is not available one can use a simple restore of the database from backup to perform validation of BRR records to search for lost writes.
Analysis and troubleshooting.
A good starting point for troubleshooting lost writes in a production system is
support note 1265884.1 "Resolving ORA-752 or ORA-600 [3020] During Standby Recovery".
However now we have a test environment with a lost write and we can have some
fun investigating it and developing techniques for analysis and troubleshooting. All this with the great advantage, compared to a real-life case, that now we know for sure what the root cause of the problem is!
- Investigate the block contents on primary and standby by
dumping the block contents to a trace file. The idea is to compare the contents of the primary and standby. Of particular interest will be the SCN of the last change to the block and also SCNs in the ITL list. This is an easy operation to perform. Example:
SQL> alter system dump datafile 10 block 134;
SQL> alter session set events 'immediate trace name set_tsn_p1 level <ts#+1>'; -- where ts# is the tablespace number
SQL> alter session set events 'immediate trace name buffer level <decimal rdba>'; --rba is 134 in our example
- We can also investigate the contents of the block with a lost write using SQL. This has the advantage of allowing the use of
flashback query. This is particularly useful for reading the details of the block on the primary database. The current content of the block on the primary may not be what we want. We are interested in a
consistent image at point in time with SCN equal to the SCN where we have our error message on the standby (current SCN of the standby). Example:
SQL> set num 16
SQL> select ora_rowscn, rowid, dbms_rowid.rowid_row_number(a.rowid) row_number, a.* from testlosttable as of scn 6367748219413 a where rowid like 'ABFzkJAAAAAAACG%'; -- edit values for scn and rowid, use SQL below to find the values to use
Find rowid of the block with lost write (block 134 of file 10 and object_id=18299145). Actually what we need is just the first 15 characters of the rowid (the last three characters are the row_number inside the block). Example:
SQL> select substr(DBMS_ROWID.ROWID_CREATE(rowid_type =>1, object_number =>18299145, relative_fno =>0, block_number =>134, row_number =>0),1,15) rowid_prefix from dual;
Find current SCN (at the standby):
SQL> select current_scn from v$database;
-
Dump from all relevant logfiles searching for entries related to the block with lost writes (in our example it's block 134 of file 10). The dump will include transaction details and most notably redo marking the time when DBWR has written the give block (this info is sotre in block written redo,
BWR). If the parameter db_lost_write_protect is set to typical or full the redo dump will also show details of the block read redo (see BRR discussed above). For further info on logfile dumps see also
Julian Dyke's website. Example:
SQL> alter system dump logfile '...{path to storage}.../thread_2_seq_1816.510.810661967' DBA MIN 10 134 DBA MAX 10 134; -- edit file number and block number as needed
- Perform log mining to find the SQL of all the transactions for the affected block. Identify the relevant redo logs to mine first. Example:
SQL> BEGIN
SYS.DBMS_LOGMNR.ADD_LOGFILE(LogFileName=>'...{path to storage}.../thread_2_seq_1816.510.810661967',Options=>SYS.DBMS_LOGMNR.NEW);
SYS.DBMS_LOGMNR.START_LOGMNR(Options=> SYS.DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG);
END;
/
SQL> SELECT scn,sql_redo FROM SYS.V_$LOGMNR_CONTENTS WHERE data_obj#=18299145 and row_id like 'ABFzkJAAAAAAACG%'; -- calculate rowid with dbms_rowid package as detailed above
- Other analysis that can be done in case we have indexes on the tables:
In case one or more indexes are present we can read data from the index and compare the results with what we have on the table. Example to read from the index:
SQL> select rowid rowid_table_from_index_leaf, id, sys_op_lbid(18299146,'L',t.rowid) index_leaf_rowid from testlosttable t where rowid like 'ABFzkJAAAAAAACG%';
--note: update 18299146 with the the data_object_id of the index of interest
-- in this example this is the data_object_id of I_TESTLOSTTABLE
Another standard check with corruption between index and table is to run analyze table validate, although in my experience this can be quite time consuming and not necessarily add more information to the analysis. Example:
SQL> analyze table testlosttable validate structure cascade online;
Actions that we can take to restore the services
Suppose that our analysis has confirmed that a lost write happened and also that we have the details of what 'is lost'. We need now to fix the corrupted block on the primary and restore the service on the standby. In particular if we have an Active Data Guard with a SLA, the latter may be quite an urgent action. Hopefully we also have some ideas of what the root cause was and a way to fix it in the future.
One possible action is to failover to standby. This action plan however may provide to be unacceptable in many circumstances, given the potential for data loss it implies. A failover would likely not be acceptable if the primary database has continued working and accepting users transactions since the time (SCN) of the incident that has generated ORA-600 (or ORA-752).
Another possibility is to use our knowledge of the lost transactions gathered in the analysis phase to run SQL actions to 'fix the primary'. This has to be evaluated case by case. In some circumstances we can also get away with just dropping and recreating the object with a lost write. In our simple example of a lost insert on table testlosttable, the action to perform on the primary is:
SQL> alter index i_testlosttable rebuild online;
SQL> insert into testlosttable values (30,'cccccccccccccccccccccccccc');
SQL> commit;
What about fixing the standby? We can unstuck the recovery on the standby by allowing it to corrupt the block with a lost write (and fix it later, as detailed below). Example:
SQL> alter system set db_lost_write_protect=none; --temporarily disable lost write check if needed
SQL> alter database recover automatic standby database allow 1 corruption;
SQL> --wait till the redo that cause the error message has been applied
SQL> alter database recover cancel;
SQL> -- restart normal Data Guard operations. An example for ADG:
SQL> alter system set db_lost_write_protect=typical;
SQL> alter database open read only;
SQL> alter database recover managed standby database nodelay using current logfile disconnect;
At this point all is OK except for one corrupted block on the standby. How to restore the corrupted block on standby? This depends on the case, we may just rebuild the object on primary this will fix the problem on standby. Another option is to copy over the datafile from primary to standby
In our example the corrupted block is block 134 of file 10 and we have an active data guard in real time apply. We can use automatic block media recovery (ABMR) to fix it. In my tests AMBR is attempted but does not really work against the corrupted block 134, I can work around this by zeroing out the block. This is an example (intended to be used on test databases):
.
/asmblk_edit -w -s 134 -a +STDBY_DATADG1/TESTDB/datafile/testlostwrite.347.810578685 -f zeroblock
where zeroblock file is created with: dd if=/dev/zero bs=8192 count=1 of=zeroblock
if my standby was on filesystem I could have used:
dd if=/dev/zero of=testlostwrite.dbf bs=8192 count=1 seek=134 if=blk134.dmp conv=notrunc
If we now query the table (the table testlostwrite in our example) when Oracle reaches the zeroed block it will fetch a copy from production (see the manual for the details of configuring ABMR). This will happen in a transparent way for the user issuing the query, the operation is logged in the alert log of the instance (the 2 lines here below appeared repeated twice in my test using 11.2.0.3):
Automatic block media recovery requested for (file# 10, block# 134)
Automatic block media recovery successful for (file# 10, block# 134)
Oracle's OTN demo video on lost write
Short videos with demos on testing lost writes and automatic block media recovery in a Data Guard environment can be
found on OTN.
See also support document "Best Practices for Corruption Detection, Prevention, and Automatic Repair - in a Data Guard Configuration" [ID 1302539.1]
Conclusions and future work
This article illustrates a simple example on how to
reproduce and investigate the effects lost write in a test environment, which is intended as a training exercise for DBAs.
I would like to end with
four points that I still find unsettling when thinking at how lost writes can affect an Oracle setup configured for high availability:
- Finding the root causes of a lost write can prove to be very time consuming: was it caused by the storage, or by an Oracle bug, or somewhere in between? If the issue cannot be re-produced you can easily find yourself in between a finger-pointing discussion between vendors.
- Having a standby is of great help for discovering lost writes. However once a lost write is found the redo apply stops: the recovery is stuck and throws error ORA-600 [3020] or ORA-752 if we try to restart it. A support DBA most likely will have to analyze the situation and decide what to do to fix the issue (for example perform a failover or rather going through a process similar to what described in this article). Moreover if one or more Active Data Guards are used for critical read-only activity, there is time pressure to restart the redo apply.
- How can we check that our primary and standby databases are 'in sync', that is that there are no lost writes waiting to 'explode' as time bombs? I am not aware of a utility that could do such check. This is a very interesting topic, probably material for another post. A brief discussion of this problem and possible solutions can be found at this link and also here.
- Database restores can be affected by lost writes too. For example the restore of a database backup can fail (get stuck on applying redo) because of a lost write that has happened in production after the latest data file backup. This has potential impacts on the disaster and recovery strategy.
Note: the examples reported in this article have been tested against Oracle 11.2.0.3 64 bit for Linux (RHEL5).
