Focus On Oracle,MySQL,SQL Server and PostgreSQL..

一次超过200TB的Oracle exadata故障恢复

—

由

dbsupport
于 , ,

近期某客户的Oracle exadata出现故障，最后4个计算节点全部crash，然后最后无法正常启动，在open数据库时写丢失错误，如下：

Fri Apr 22 13:11:21 2022
Recovery of Online Redo Log: Thread 4 Group 15 Seq 199807 Reading mem 0
  Mem# 0: +DATA/xxxxx/ONLINELOG/group_15.286.1022953965
  Mem# 1: +RECO/xxxxx/ONLINELOG/group_15.274.1022953965
Fri Apr 22 13:11:22 2022
Hex dump of (file 82, block 4100304379) in trace file /u01/ordb/oracle/diag/rdbms/xxxxx/xxxxx1/trace/xxxxx1_p00p_193823.trc

Reading datafile '+DATA/xxxxx/960AB3D86A40640DE0530100290A3BEA/DATAFILE/xxxxx01.93924.1065190333' for corruption at rdba: 0xf465adfb (file 82, block 4100304379)
Read datafile mirror 'DATA_CD_01_XD08xxxxx06' (file 82, block 4100304379) found same corrupt data (logically corrupt)
Read datafile mirror 'DATA_CD_03_XD08xxxxx04' (file 82, block 4100304379) found same corrupt data (logically corrupt)
Fri Apr 22 13:11:26 2022
Hex dump of (file 82, block 4089892618) in trace file /u01/ordb/oracle/diag/rdbms/xxxxx/xxxxx1/trace/xxxxx1_p00s_194316.trc

Reading datafile '+DATA/xxxxx/960AB3D86A40640DE0530100290A3BEA/DATAFILE/xxxxx01.93924.1065190333' for corruption at rdba: 0xf3c6cf0a (file 82, block 4089892618)
Read datafile mirror 'DATA_CD_06_XD08xxxxx01' (file 82, block 4089892618) found same corrupt data (logically corrupt)
Read datafile mirror 'DATA_CD_08_XD08xxxxx02' (file 82, block 4089892618) found same corrupt data (logically corrupt)
Fri Apr 22 13:19:34 2022
Reconfiguration started (old inc 87, new inc 89)
List of instances (total 3) :
......
Fri Apr 22 14:00:17 2022
Errors in file /u01/ordb/oracle/diag/rdbms/xxxxx/xxxxx1/trace/xxxxx1_p00p_193823.trc:
ORA-01172: recovery of thread 3 stuck at block 4100304379 of file 82
ORA-01151: use media recovery to recover block, restore backup if needed
Fri Apr 22 14:00:17 2022
……
Fri Apr 22 18:28:22 2022
ORA-279 signalled during: ALTER DATABASE RECOVER    CONTINUE DEFAULT  ...
ALTER DATABASE RECOVER    CONTINUE DEFAULT
Fri Apr 22 18:28:22 2022
Media Recovery Log +RECO/xxxxx/ARCHIVELOG/2022_04_22/thread_1_seq_302478.1451.1102677095
Fri Apr 22 18:33:59 2022
Redo application during media recovery has detected that the database lost a disk write.
No redo at or after SCN 630363030521 can be used for recovery.
BLOCK THAT LOST WRITE 4100064450, FILE 82, TABLESPACE# 7
The block read during the normal successful database operation had SCN 630361032511 (0x0092.c472073f) seq 1 (0x01)
ERROR: ORA-00752 detected lost write on primary
Errors with log +RECO/xxxxx/ARCHIVELOG/2022_04_22/thread_1_seq_302478.1451.1102677095
Fri Apr 22 18:34:06 2022
Media Recovery failed with error 752

从上述的报错来看，数据库最后open时报错无法进行instance recovery；主要是因为在进行实例恢复时遇到了逻辑坏块。

也就是说该数据库在之前出现了写丢失，导致出现了逻辑坏块，最后导致实例重启后无法进行实例恢复。

通过分析4个rac节点的故障前后顺序发现，最早出现crash的是节点3，该节点因为出现out of memory，进而导致数据库crash：

Apr 22 10:37:46 xd08xxxxx03 kernel: Call Trace:
Apr 22 10:37:46 xd08xxxxx03 kernel: dump_stack+0x63/0x7f
Apr 22 10:37:48 xd08xxxxx03 kernel: dump_header+0x9f/0x233
Apr 22 10:37:50 xd08xxxxx03 kernel: ? security_capable_noaudit+0x4b/0x63
Apr 22 10:37:50 xd08xxxxx03 kernel: oom_kill_process+0x23a/0x448
Apr 22 10:37:51 xd08xxxxx03 kernel: out_of_memory+0x114/0x499
Apr 22 10:37:53 xd08xxxxx03 kernel: __alloc_pages_slowpath+0x946/0xb95
Apr 22 10:37:54 xd08xxxxx03 kernel: __alloc_pages_nodemask+0x2b1/0x2fc
Apr 22 10:37:54 xd08xxxxx03 kernel: alloc_pages_current+0x6a/0xb0
Apr 22 10:37:54 xd08xxxxx03 kernel: kmalloc_order+0x18/0x39
Apr 22 10:37:55 xd08xxxxx03 kernel: kmalloc_order_trace+0x2a/0xb4
Apr 22 10:37:56 xd08xxxxx03 kernel: __kmalloc+0x21d/0x225
Apr 22 10:37:56 xd08xxxxx03 kernel: __rds_rdma_map+0x150/0x490 [rds]
Apr 22 10:37:57 xd08xxxxx03 kernel: rds_get_mr+0x59/0x80 [rds]
Apr 22 10:37:58 xd08xxxxx03 kernel: rds_setsockopt+0x262/0x700 [rds]
Apr 22 10:37:58 xd08xxxxx03 kernel: ? audit_filter_syscall+0x33/0xce
Apr 22 10:37:58 xd08xxxxx03 kernel: ? __audit_syscall_entry+0xac/0xef
Apr 22 10:37:59 xd08xxxxx03 kernel: ? __fdget+0x13/0x15
……
Apr 22 10:38:12 xd08xxxxx03 kernel: Out of memory: Kill process 64782 (ora_lms3_xxxx3) score 47 or sacrifice child

我们可以看到，该数据库实例的核心进程LMS因为OOM被kill，所以导致实例异常终止，最终也影响了其他节点的通信，陆续出现了其他节点LMON终止实例的情况。那么该节点为什么会出现内存耗尽的情况呢？分析了故障前20分钟的监听日志发现确实存在大量连接：

[root@xxxx tmp]# tail -800000 listener_5.log | fgrep "22-APR-2022 10:" |fgrep "establish" |awk '{print $1 " " $2}' |awk -F: '{print $1 ":" $2 }' |sort |uniq -c
    190 22-APR-2022 10:00
    230 22-APR-2022 10:01
    ......
    201 22-APR-2022 10:15
    234 22-APR-2022 10:16
    121 22-APR-2022 10:17
     67 22-APR-2022 10:18
    193 22-APR-2022 10:19
    219 22-APR-2022 10:20
    233 22-APR-2022 10:21
    127 22-APR-2022 10:22
     53 22-APR-2022 10:23
    184 22-APR-2022 10:24
    207 22-APR-2022 10:25
    196 22-APR-2022 10:26
      2 22-APR-2022 10:27
    412 22-APR-2022 10:29
    334 22-APR-2022 10:30
    298 22-APR-2022 10:31
    252 22-APR-2022 10:32
    284 22-APR-2022 10:33
    309 22-APR-2022 10:34
    233 22-APR-2022 10:35
    378 22-APR-2022 10:36
    219 22-APR-2022 10:37
    479 22-APR-2022 10:38
      4 22-APR-2022 10:39
      1 22-APR-2022 10:41

大家不难看出，从10:29分开始暴涨，但是在10:27和10:28分是异常的，一分钟居然只有2个连接，甚至没有。查看该时间段的ASH数据也会发现存在大量的SQL*Net more data from client、SQL*Net more data from dblink等待。检查上述等待的相关应用SQL，没有什么特殊的，都是一些常规insert into操作，按理说不应该出现这种异常等待。对于一个event而言：

该等待事件本质上是指服务器进程等待客户端发送更多的数据或者消息。

客户端发送数据传输的过程，大概分为如下4个步骤：

  • 服务器进程变成开始接收数据的状态
  • 客户端开始发送数据
  • 通过网络传输
  • 服务器进程接收数据完成

由于Oracle Net通过SDU (Session Data Unit) 来控制着发送和收接数据的大小，如果传输数据时，数据大于用于传输的SDU大小的话（SDU默认8K），就需要进行多次传输；此时的表现就是会话等待SQL*Net more data from client;直到数据传输完毕，该等待才会结束。

 因此该等待事件产生通常为如下几个原因:

  • 应用SQL传输数据过大
  • 数据库SDU配置过小
  • 网络问题

因此我们很容易排出前面2个因素，那么极大概率就是网络问题了。再看第2个event，这就完全跟网络有关系了，基于dblink的访问操作，如果应用SQL本身ok的话，也不应该出现这么大量的等待，这样明确的指向了网络问题。

后经过客户了解到，该单位业务部门在10:26分左右进行了网络调整，这一切都能解释通了。。。

那么此次问题的根源就是业务期间进行了网络调整；导致数据库其中一个节点出现了堵塞，进而出现连接暴涨的情况，最后内存耗尽，导致实例crash，最终引发了一系列的连锁反应。

罪魁祸首已经找到了。那么最前面的写丢失是如何产生的呢？从这里来看，并非常见的物理坏块，比如因为IO出现块写断裂，不完整的情况；而是逻辑坏块。逻辑坏块本身表示块结构是完整，只是数据不一致，比如无法应用redo，或者表和索引数据不一致等。

由于最后启动时报错的block scn相对旧一些，因此我们认为仍然是这次实例突然crash引发的写丢失。

评论

发表回复

您的电子邮箱地址不会被公开。 必填项已用 * 标注