ASM resilvering – or – how to recover your crashed cluster – Test no 4

Dear Readers,

my blog has moved to a different server.

The new address is:

http://blog.ronnyegner-consulting.de

Test #4: Corrupting the ASM disk with ASM disk group being online and active

After overwriting the ASM disk header while the disk group was offline we will now put some load on the full running cluster and corrupt the asm disk slightly.

Testcase

Put load on the database

Prior starting this test i created a larger table with one column and approx 1.2 GB size and an empty table with the same structure. So for our simple test we will just copy one table into another table. This forces oracle to read the database blocks and do some writes as well.

create table test2_empty as select * from test where rownum<1;

insert into test2_empty select * from test;

Corrupting the disk

According to fdisk the asm lun has a size of 21474836480 bytes:

Disk /dev/sde: 21.4 GB, 21474836480 bytes
64 heads, 32 sectors/track, 20480 cylinders
Units = cylinders of 2048 * 512 = 1048576 bytes

 Device Boot      Start         End      Blocks     Id  System
/dev/sde1               1       20480    20971504   83  Linux

And the disk is indeed the mirror partner of the disk we destroyed and re-added in the earlier part.

[root@rac1 ~]# oracleasm querydisk /dev/sde1
Device "/dev/sde1" is marked an ASM disk with the label "DISK003B"

We will corrupt the disk by writing 512 byte chunks of random data from /dev/urandom to 1000 different locations all over the lun. Given the lun size this makes 41943040 blocks of 512 bytes each.

Our command to corrupt the lun will be:

dd if=/dev/random bs=512 count=1 of=/dev/sde1 seek=nnnn

Where “seek=nnn” is a number from 0 to 41943040-1.

Note that this time we manipulate the second mirror disk of disk group DATA2 – DISK003B. In test no 3 we overwrote the asm disk header of DISK003A and re-added the disk to the data group. In this example we manipulate DISK003B. If there were undetected errors rebalancing the disks we will discover it now.

For this we first of all needed a small little random number generator within the limits of 0 to 41943040; here it is:

#!/bin/bash

function random()
{
 od -d /dev/urandom | sed -e 's/^[0-9]* //' -e 's/ //g' |\
 while read L ; do echo -n $L ; done |\
 dd bs=1 count=${1:-10} 2>/dev/null
}

A=$(random 10) #return random number with 10 numbers
B=$(expr $C % 41943040)  # keep number within range
echo $B

With this random number generator we created a small shell script for corrupting the asm lun which looks like this:

dd if=/dev/urandom of=/dev/sde1 bs=512 count=1 seek=986024
dd if=/dev/urandom of=/dev/sde1 bs=512 count=1 seek=1594423
dd if=/dev/urandom of=/dev/sde1 bs=512 count=1 seek=2236024
[..]

Expected test results

So what are we expecting?

According to oracle documents (note 416046.1) there are two different scenarios:

• If the primary extent is detected to be corrupt (asm only reads from primary extent unless a read preference set) ASM retries the read. If re-read data is also corrupt ASM fails over to the secondary extent. If data in secondary extent is valid data in primary extent will be overwritten with the good data from the secondary extent.
• If data in secondary extent is corrupt it will remain undetected. If new data is written the new data will be written both to the primary and secondary disk. This will most likely overwrite the corrupted data. But if the primary extent fails oracle will read the secondary extent and will discover the corruption as well –  but this time the corruption is not fixable. You will end up with restoring/recovering the corrupt database blocks and probably much more.

In addition to that i expect ASM and/or the database to automatically fix detected corruptions.

Testing

Message no. 1: Database detected and fixed corruption

During our Insert statement running the database alert.log showed:

Fri Oct 02 10:47:21 2009
Hex dump of (file 6, block 156029) in trace file /u01/app/oracle/diag/rdbms
  /ora11p/ora11p1/trace/ora11p1_ora_30023.trc
Corrupt block relative dba: 0x0182617d (file 6, block 156029)
Bad header found during multiblock buffer read
Data in bad block:
 type: 180 format: 3 rdba: 0xb19a95b2
 last change scn: 0x6f92.6c357e5d seq: 0x1 flg: 0x5a
 spare1: 0xfd spare2: 0x80 spare3: 0x4f3c
 consistency value in tail: 0x1591148c
 check value in block header: 0x2abf
 block checksum disabled
Reading datafile '+DATA2/ora11p/users02.dbf' for corruption at rdba:
  0x0182617d (file 6, block 156029)
Read datafile mirror 'DISK003B' (file 6, block 156029) found same corrupt data
Read datafile mirror 'DISK003A' (file 6, block 156029) found valid data
Repaired corruption at (file 6, block 156029)

Message no. 2: Database detected corruption

Corrupt block relative dba: 0x01c12d35 (file 7, block 77109)
Bad check value found during validation
Data in bad block:
 type: 2 format: 2 rdba: 0x01c12d35
 last change scn: 0x0000.00253bd5 seq: 0x73 flg: 0x04
 spare1: 0x0 spare2: 0x0 spare3: 0x0
 consistency value in tail: 0x3bd50273
 check value in block header: 0x94cb
 computed block checksum: 0xf0eb
Trying mirror side DISK003B.
Reread of blocknum=77109, file=+DATA2/ora11p/datafile/undotbs01_02.dbf. found
 same corrupt data
Reread of blocknum=77109, file=+DATA2/ora11p/datafile/undotbs01_02.dbf. found
 valid data

Note: This time the database does not say anything about the corruption being fixed.

Message no. 3: ASM detected and fixed corruption

Mon Oct 05 09:32:15 2009
WARNNING: cache read a corrupted block group=DATA2 fn=1
 blk=893 from disk 0
NOTE: a corrupted block from group DATA2 was dumped to /u01/app/oracle/diag/asm
 /+asm/+ASM1/trace/+ASM1_ora_4739.trc
WARNNING: cache read(retry) a corrupted block group=DATA2 fn=1
 blk=893 from disk 0
NOTE: cache repaired a corrupted block group=DATA2 fn=1 blk=893
 from disk 0

Conclusion

First of all: regardless of the caveats described below the insert statement most of the time completed successfully:

SQL> insert into test2 select * from sys.test;
134217728 rows created.

Second: During our tests ASM performed well and stable. We were consistently able to work on the disk groups even if the disk group missed their mirrors.

However i discovered some problems as well:

• ASM has no ability to check data on disk groups completely (i.e. compare data on all mirror partners and check for corruptions); so corruptions on secondary extents will remain undetected until primary extent fails and secondary extent is read
• ASM nor the database does always fix corruptions found in primary extents (see message 2 above… corruption was detected but NOT corrected and remained on disk) as indicated by note 416046
• Checking database with RMAN and “backup validate database” finds and reports errors but does not fix ANY error found. The error message no. 2 originated from a “select * from test….” but rman produces this type of error messages in alert.log as well. From the Metalink document which describes handling of block corruptions in ASM i would have expected ASM or the database to fix these errors automatically.
• There are scenarios where corrupted primary blocks prevent the database from starting at all. During our tests we have seen this two times with different error messages. One sample error message stack is reproduced in error message no. 3 coming from the asm instance and in the following lines below coming from the database instance:

Exception [type: SIGILL, Illegal operand] [ADDR:0x105DC01]
[PC:0x105DC01, kkestRCSBase()+221] [flags: 0x0, count: 1]
Errors in file /u01/app/oracle/diag/rdbms/ora11p/ora11p1/
trace/ora11p1_ora_5206.trc  (incident=48254):
ORA-07445: exception encountered: core dump [kkestRCSBase()+221]
[SIGILL] [ADDR:0x105DC01] [PC:0x105DC01] [Illegal operand] []
Incident details in: /u01/app/oracle/diag/rdbms/ora11p/ora11p1/
incident/incdir_48254/ora11p1_ora_5206_i48254.trc
Mon Oct 05 09:33:47 2009
Trace dumping is performing id=[cdmp_20091005093347]
Mon Oct 05 09:33:49 2009
Exception [type: SIGILL, Illegal operand] [ADDR:0x105DC01]
[PC:0x105DC01, kkestRCSBase()+221] [flags: 0x0, count: 1]
Errors in file /u01/app/oracle/diag/rdbms/ora11p/ora11p1/
trace/ora11p1_ora_5296.trc  (incident=48310):
ORA-07445: exception encountered: core dump [kkestRCSBase()+221]
[SIGILL] [ADDR:0x105DC01] [PC:0x105DC01] [Illegal operand] []
Incident details in: /u01/app/oracle/diag/rdbms/ora11p/ora11p1/
incident/incdir_48310/ora11p1_ora_5296_i48310.trc

Although we met this errors we were able to fix them: In one case dropping the disk containing the corrupted blocks was enough to start the instance again. The second incident reproduced above required the corrupted disk to be dropped, re-added and ASM instance to be restarted before we were able to successfully start the database instance.

• Dropping a corrupted disk and re-adding the disk requires the disk group the disk belonged to be taken offline. Otherwise labeling the former member disk failed with “device or resource busy”. I will investigate this further.

Summarizing my experiences until now i would go with ASM and normal or even high redundancy. This enables far more options for fixing errors without having to rebuild the disk group and restoring everything from tape/disk.