分类目录归档：数据库

接手一个只差临门一脚的数据库恢复

发表于 2026 年 6 月 18 日 由 惜分飞

刚刚进行了一个数据库恢复case,故障处理起来非常简单(设置一个参数启动库即可),大概回溯下故障经过,反馈是由于客户在没有停机的情况下复制虚拟机,然后启动虚拟机之后,数据库无法正常启动报ORA-00314 ORA-00312错误

Wed Jun 17 10:24:02 2026
ALTER DATABASE   MOUNT
Successful mount of redo thread 1, with mount id 3689345602
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: ALTER DATABASE   MOUNT
Wed Jun 17 10:24:06 2026
ALTER DATABASE OPEN
Beginning crash recovery of 1 threads
 parallel recovery started with 32 processes
Started redo scan
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_60458.trc:
ORA-00314: log 2 of thread 1, expected sequence# 12271 doesn't match 9443
ORA-00312: online log 2 thread 1: '/oradata/orcl/redo02.log'
Aborting crash recovery due to error 314
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_60458.trc:
ORA-00314: log 2 of thread 1, expected sequence# 12271 doesn't match 9443
ORA-00312: online log 2 thread 1: '/oradata/orcl/redo02.log'
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_60458.trc:
ORA-00314: log 2 of thread 1, expected sequence# 12271 doesn't match 9443
ORA-00312: online log 2 thread 1: '/oradata/orcl/redo02.log'
ORA-314 signalled during: ALTER DATABASE OPEN...
Wed Jun 17 10:24:07 2026
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_61170.trc:
ORA-00314: log 1 of thread 1, expected sequence# 12269 doesn't match 9441
ORA-00312: online log 1 thread 1: '/oradata/orcl/redo01.log'
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_61170.trc:
ORA-00314: log 2 of thread 1, expected sequence# 12271 doesn't match 9443
ORA-00312: online log 2 thread 1: '/oradata/orcl/redo02.log'
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_61170.trc:
ORA-00314: log 3 of thread 1, expected sequence# 12265 doesn't match 9444
ORA-00312: online log 3 thread 1: '/oradata/orcl/redo03.log'
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_61170.trc:
ORA-00314: log 4 of thread 1, expected sequence# 12266 doesn't match 9438
ORA-00312: online log 4 thread 1: '/oradata/orcl/redo04.log'
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_61170.trc:
ORA-00314: log 5 of thread 1, expected sequence# 12267 doesn't match 9439
ORA-00312: online log 5 thread 1: '/oradata/orcl/redo05.log'
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_m000_61170.trc:
ORA-00314: log 6 of thread 1, expected sequence# 12268 doesn't match 9440
ORA-00312: online log 6 thread 1: '/oradata/orcl/redo06.log'

这个错误的redo sequence差距有点大,个人感觉可能不是简单的复制引起的,由于没有第一现场不好溯源,不乱做评论,姑且认为是由于虚拟机复制引起的问题
客户使用隐含参数强制打开数据库，报ORA-1555错误

Wed Jun 17 10:42:50 2026
ALTER DATABASE OPEN RESETLOGS
RESETLOGS is being done without consistancy checks. This may result
in a corrupted database. The database should be recreated.
RESETLOGS after incomplete recovery UNTIL CHANGE 1838398816
Resetting resetlogs activation ID 3463997979 (0xce786a1b)
ORA-344 signalled during: ALTER DATABASE OPEN RESETLOGS...
Wed Jun 17 10:44:30 2026
ALTER DATABASE OPEN RESETLOGS
RESETLOGS is being done without consistancy checks. This may result
in a corrupted database. The database should be recreated.
RESETLOGS after incomplete recovery UNTIL CHANGE 1838398816
Resetting resetlogs activation ID 3463997979 (0xce786a1b)
Wed Jun 17 10:45:13 2026
Setting recovery target incarnation to 3
Wed Jun 17 10:45:13 2026
Assigning activation ID 3689297678 (0xdbe6370e)
Thread 1 opened at log sequence 1
  Current log# 1 seq# 1 mem# 0: /oradata/orcl/redo01.log
Successful open of redo thread 1
Wed Jun 17 10:45:14 2026
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Wed Jun 17 10:45:14 2026
SMON: enabling cache recovery
ORA-01555 caused by SQL statement below (SQL ID: 4krwuz0ctqxdt, SCN: 0x0000.6d93bd66):
select ctime, mtime, stime from obj$ where obj# = :1
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_18038.trc:
ORA-00704: bootstrap process failure
ORA-00704: bootstrap process failure
ORA-00604: error occurred at recursive SQL level 1
ORA-01555: snapshot too old: rollback segment number 35 with name "_SYSSMU35_3782695576$" too small
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_18038.trc:
ORA-00704: bootstrap process failure
ORA-00704: bootstrap process failure
ORA-00604: error occurred at recursive SQL level 1
ORA-01555: snapshot too old: rollback segment number 35 with name "_SYSSMU35_3782695576$" too small
Error 704 happened during db open, shutting down database
USER (ospid: 18038): terminating the instance due to error 704
Instance terminated by USER, pid = 18038
ORA-1092 signalled during: ALTER DATABASE OPEN RESETLOGS...
opiodr aborting process unknown ospid (18038) as a result of ORA-1092
Wed Jun 17 10:45:16 2026
ORA-1092 : opitsk aborting process

这个是一个比较经典的错误,以往的文章中总结了这类错误可能涉及的具体sql语句
在数据库open过程中常遇到ORA-01555汇总
数据库open过程遭遇ORA-1555对应sql语句补充
客户尝试多次重启之后，数据库报ORA-600 2662错误

Wed Jun 17 10:55:34 2026
Thread 1 advanced to log sequence 3 (thread open)
Thread 1 opened at log sequence 3
  Current log# 3 seq# 3 mem# 0: /oradata/orcl/redo03.log
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Wed Jun 17 10:55:34 2026
SMON: enabling cache recovery
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_6707.trc  (incident=117868):
ORA-00600: internal error code, arguments: [2662], [0], [1838441753], [0], [1838486139], [12583040], 
Incident details in: /u01/oracle/diag/rdbms/orcl/orcl/incident/incdir_117868/orcl_ora_6707_i117868.trc
Wed Jun 17 10:55:45 2026
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_6707.trc:
ORA-00600: internal error code, arguments: [2662], [0], [1838441753], [0], [1838486139], [12583040], 
Errors in file /u01/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_6707.trc:
ORA-00600: internal error code, arguments: [2662], [0], [1838441753], [0], [1838486139], [12583040], 
Error 600 happened during db open, shutting down database
USER (ospid: 6707): terminating the instance due to error 600
Instance terminated by USER, pid = 6707
ORA-1092 signalled during: alter database open...

客户后续多次重建ctl，强制拉库等操作，一直在ORA-600 2662上面循环，后面终于出现了ORA-600 4193/4194错误，数据库没有正常open成功,至此客户放弃恢复尝试。
我们接手故障之后,设置undo手工管理模式,然后直接启动库成功
open1
然后使用expdp导出数据,完成本次恢复工作

发表在 Oracle备份恢复 | 标签为 , , , , | 评论关闭

硬件故障后数据文件大小不对故障处理—Oracle碎片扫描恢复

发表于 2026 年 6 月 7 日 由 惜分飞

有硬件恢复圈朋友找到我,说硬件恢复之后dbv报dbv-00102错误,让我给看看是否可以处理
dbv-00102

这个是oracle dbv中一种常见错误,一般是由于block 0 不对,或者是由于文件大小不对引起,让把恢复文件发给我,进行检查

SQL> select name,bytes/1024/1024/1024 from v$datafile_header;

NAME                                                                             BYTES/1024/1024/1024
-------------------------------------------------------------------------------- --------------------
H:\BAIDUNETDISK\ORADATA\XXXXORCL\SYSTEM01.DBF                                             2.080078125
H:\BAIDUNETDISK\ORADATA\XXXXORCL\SYSAUX01.DBF                                             2.880859375
H:\BAIDUNETDISK\ORADATA\XXXXORCL\UNDOTBS01.DBF                                           9.0087890625
H:\BAIDUNETDISK\ORADATA\XXXXORCL\USERS01.DBF                                          31.993408203125
H:\BAIDUNETDISK\ORADATA\XXXXORCL\USERS02.DBF                                                8.1640625
H:\BAIDUNETDISK\ORADATA\XXXXORCL\USERS03.DBF                                              7.958984375
H:\BAIDUNETDISK\ORADATA\XXXXORCL\USERS04.DBF                                              7.958984375
H:\BAIDUNETDISK\ORADATA\XXXXORCL\USERS05.DBF                                                 7.890625

已选择8行。

确定USER02-USERS05的dbf文件实际大小(数据文件头记录)在8G左右,但是目前恢复出来的文件大小只有4G左右
4g

在恢复工具中直接查看文件大小情况
rs
这里比较明显rs中虽然显示文件状态良好,但是实际大小也不对(得出经验:以后恢复中不能太依赖这个状态),根据反馈现场是三个盘的raid5,中途做了一次强制上线,然后客户也使用win pe拷贝过一次数据,大小和现在一样,也是少了近4G.第一反应可能是由于raid盘弄的不对,但是经过对其他文件的确认,多完全没有问题,排除了盘错误的问题,怀疑是由于文件系统异常导致,对于这种的情况,文件系统层面肯定无法恢复,考虑使用自研的OraScan工具进行扫描(OraScan(Oracle 碎片扫描工具) 使用说明)
ora1
ora2
通过OraScan扫描找到相关block,并提取出来数据文件
file
使用dbv检测文件

C:\Users\XFF>dbv file=H:\BaiduNetdisk\xff\YFKJORCL.USERS.4.7.4.N.DBF

DBVERIFY: Release 11.2.0.4.0 - Production on 星期日 6月 7 18:06:30 2026

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

DBVERIFY - 开始验证: FILE = H:\BAIDUNETDISK\XFF\YFKJORCL.USERS.4.7.4.N.DBF


DBVERIFY - 验证完成

检查的页总数: 1043200
处理的页总数 (数据): 67167
失败的页总数 (数据): 0
处理的页总数 (索引): 37995
失败的页总数 (索引): 0
处理的页总数 (其他): 861109
处理的总页数 (段)  : 0
失败的总页数 (段)  : 0
空的页总数: 76929
标记为损坏的总页数: 0
流入的页总数: 0
加密的总页数        : 0
最高块 SCN            : 347454063 (0.347454063)

把文件拷贝替换掉之前恢复的USERS02-USER05.DBF,然后尝试打开数据库

SQL> recover database ;
完成介质恢复。
SQL> alter database open ;
alter database open
*
第 1 行出现错误:
ORA-03113: 通信通道的文件结尾
进程 ID: 3308
会话 ID: 14 序列号: 3

查看alert日志分析原因

Sun Jun 07 14:43:51 2026
Recovery of Online Redo Log: Thread 1 Group 2 Seq 36464 Reading mem 0
  Mem# 0: H:\BAIDUNETDISK\ORADATA\YFKJORCL\REDO02.LOG
Completed: ALTER DATABASE RECOVER  database   
alter database open 
Beginning crash recovery of 1 threads
 parallel recovery started with 19 processes
Started redo scan
Completed redo scan
 read 2353 KB redo, 0 data blocks need recovery
Started redo application at
 Thread 1: logseq 36464, block 15876
Recovery of Online Redo Log: Thread 1 Group 2 Seq 36464 Reading mem 0
  Mem# 0: H:\BAIDUNETDISK\ORADATA\YFKJORCL\REDO02.LOG
Completed redo application of 0.00MB
Completed crash recovery at
 Thread 1: logseq 36464, block 20582, scn 347475303
 0 data blocks read, 0 data blocks written, 2353 redo k-bytes read
Sun Jun 07 14:43:57 2026
Errors in file c:\app\xff\diag\rdbms\yfkjorcl\o11201\trace\o11201_lgwr_2204.trc:
ORA-00314: ?? 3 (???? 1) ??? sequence# 36462 ? 32025 ???
ORA-00312: ???? 3 ?? 1: 'H:\BAIDUNETDISK\ORADATA\YFKJORCL\REDO03.LOG'
Errors in file c:\app\xff\diag\rdbms\yfkjorcl\o11201\trace\o11201_lgwr_2204.trc:
ORA-00314: ?? 3 (???? 1) ??? sequence# 36462 ? 32025 ???
ORA-00312: ???? 3 ?? 1: 'H:\BAIDUNETDISK\ORADATA\YFKJORCL\REDO03.LOG'
Errors in file c:\app\xff\diag\rdbms\yfkjorcl\o11201\trace\o11201_ora_3308.trc:
ORA-00314: 日志 1 (用于线程 ) 要求的 sequence#  与  不匹配
ORA-00312: 联机日志 3 线程 1: 'H:\BAIDUNETDISK\ORADATA\YFKJORCL\REDO03.LOG'
USER (ospid: 3308): terminating the instance due to error 314
Sun Jun 07 14:44:02 2026
Instance terminated by USER, pid = 3308

由于redo group 异常导致库无法正常open,但是由于已经recover database成功,因此大概率可以clear该redo 组

SQL> select group#,status from v$log;

    GROUP# STATUS
---------- ----------------
         1 INACTIVE
         3 INACTIVE
         2 CURRENT

SQL> alter database clear logfile group 3;

数据库已更改。

SQL> alter database open;

数据库已更改。

数据库open成功，然后使用expdp导出数据,完成本次恢复任务.

发表在 非常规恢复 | 标签为 , , , | 评论关闭

1.5T MySQL数据库完美恢复

发表于 2026 年 6 月 6 日 由 惜分飞

有客户MySQL数据库异常无法正常启动,需要提供恢复支持,当时提供的错误日志信息为:log sequence number xxxx is in the future
Q15

2026-06-03T13:35:02.368514Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2026-06-03T13:35:02.369669Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=521127] log sequence number 15319315659882 is in the future! Current system log sequence number 6712970192343.
从头分析mysql的日志，发现最初情况为:

---TRANSACTION 8424429306, ACTIVE 259 sec truncating table
mysql tables in use 1, locked 1
0 lock struct(s), heap size 1136, 0 row lock(s)
MySQL thread id 4513911, OS thread handle 21996, query id 4194188849 localhost 127.0.0.1 root System lock
TRUNCATE TABLE xxxx
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: complete io for buf page (read thread)
I/O thread 3 state: wait Windows aio (read thread)
I/O thread 4 state: wait Windows aio (read thread)
I/O thread 5 state: complete io for buf page (read thread)
I/O thread 6 state: wait Windows aio (write thread)
I/O thread 7 state: wait Windows aio (write thread)
I/O thread 8 state: wait Windows aio (write thread)
I/O thread 9 state: wait Windows aio (write thread)
Pending normal aio reads: [2, 0, 0, 3] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
908141629 OS file reads, 8774070813 OS file writes, 2977363738 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
InnoDB: ###### Diagnostic info printed to the standard error stream
2026-06-03T06:37:25.679003Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 17216 has waited at btr0sea.ic line 128 for 258  seconds the semaphore:
S-lock on RW-latch at 0000017F19122E18 created in file btr0sea.cc line 195
a writer (thread id 8340) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file g:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\include\btr0sea.ic line 90
2026-06-03T06:37:25.681739Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 28160 has waited at btr0sea.ic line 128 for 241  seconds the semaphore:
S-lock on RW-latch at 0000017F19123598 created in file btr0sea.cc line 195
a writer (thread id 13620) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file G:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\btr\btr0cur.cc line 3874
2026-06-03T06:37:25.684495Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 23052 has waited at btr0sea.ic line 128 for 253  seconds the semaphore:
S-lock on RW-latch at 0000017F19123598 created in file btr0sea.cc line 195
a writer (thread id 13620) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file G:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\btr\btr0cur.cc line 3874
2026-06-03T06:37:25.687586Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 28480 has waited at btr0sea.ic line 128 for 272  seconds the semaphore:
S-lock on RW-latch at 0000017F19122E18 created in file btr0sea.cc line 195
a writer (thread id 8340) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file g:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\include\btr0sea.ic line 90
2026-06-03T06:37:25.689857Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 2868 has waited at buf0flu.cc line 1209 for 262  seconds the semaphore:
SX-lock on RW-latch at 00000179B38E0DC0 created in file buf0buf.cc line 1460
a writer (thread id 1008) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: f0000000
Last time read locked in file ibuf0ibuf.cc line 4552
Last time write locked in file G:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\ibuf\ibuf0ibuf.cc line 406
…………………………
2026-06-03T06:37:56.919054Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 13620 has waited at btr0sea.ic line 90 for 303  seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0000017F19123598 created in file btr0sea.cc line 195
a writer (thread id 13620) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file G:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\btr\btr0cur.cc line 3874
2026-06-03T06:37:56.921090Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 24268 has waited at btr0sea.ic line 128 for 252  seconds the semaphore:
S-lock on RW-latch at 0000017F19122E18 created in file btr0sea.cc line 195
a writer (thread id 8340) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file g:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\include\btr0sea.ic line 90
2026-06-03T06:37:56.923175Z 0 [Warning] InnoDB: A long semaphore wait:
--Thread 15984 has waited at btr0sea.ic line 128 for 302  seconds the semaphore:
S-lock on RW-latch at 0000017F19122CD8 created in file btr0sea.cc line 195
a writer (thread id 5420) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file G:\ade\build\sb_0-34537258-1560180832.84\mysql-5.7.27\storage\innobase\btr\btr0cur.cc line 3874
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
2026-06-03T07:04:50.616385Z 0 [Note] MySQL: Normal shutdown

2026-06-03T07:04:50.617251Z 0 [Note] Giving 97 client threads a chance to die gracefully
2026-06-03T07:54:31.982035Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use 
--explicit_defaults_for_timestamp server option (see documentation for more details).
2026-06-03T07:54:31.983047Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' 
sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2026-06-03T07:54:31.983057Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2026-06-03T07:54:31.983098Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2026-06-03T07:54:31.985272Z 0 [Note] MySQL (mysqld 5.7.27) starting as process 832 ...
2026-06-03T07:54:32.054771Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2026-06-03T07:54:32.055435Z 0 [Note] InnoDB: Uses event mutexes
2026-06-03T07:54:32.055728Z 0 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2026-06-03T07:54:32.056143Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2026-06-03T07:54:32.057581Z 0 [Note] InnoDB: Number of pools: 1
2026-06-03T07:54:32.058963Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2026-06-03T07:54:32.063255Z 0 [Note] InnoDB: Initializing buffer pool, total size = 40G, instances = 8, chunk size = 128M
2026-06-03T07:54:34.619212Z 0 [Note] InnoDB: Completed initialization of buffer pool
2026-06-03T07:54:35.420695Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2026-06-03T07:54:36.121477Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 15319438590791
2026-06-03T07:54:36.449855Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319443833344
2026-06-03T07:54:36.847204Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319449076224
2026-06-03T07:54:37.263455Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319454319104
2026-06-03T07:54:37.544475Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319459561984
2026-06-03T07:54:37.678504Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319463095246
2026-06-03T07:54:37.681262Z 0 [Note] InnoDB: Database was not shutdown normally!
2026-06-03T07:54:37.681755Z 0 [Note] InnoDB: Starting crash recovery.
2026-06-03T07:54:38.088953Z 0 [Note] InnoDB: 2 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
2026-06-03T07:54:38.089913Z 0 [Note] InnoDB: Trx id counter is 8424438528
2026-06-03T07:54:38.090288Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 …… 91 92 93 94 95 96 97 98 99 
2026-06-03T07:54:42.043861Z 0 [Note] InnoDB: Apply batch completed
2026-06-03T07:54:42.295726Z 0 [Note] InnoDB: Rolling back trx with id 8424429306, 0 rows to undo
2026-06-03T07:54:42.298212Z 0 [Note] InnoDB: Rollback of trx with id 8424429306 completed
2026-06-03T07:55:19.432722Z 0 [Note] InnoDB: Completing truncate for table with id (8714) residing in file-per-table tablespace with id (6005)
2026-06-03T07:55:30.963664Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90593936, which exceeds the log group capacity 90593280.
2026-06-03T07:55:47.442228Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90602582, which exceeds the log group capacity 90593280.
2026-06-03T07:56:05.422243Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90609452, which exceeds the log group capacity 90593280.
2026-06-03T07:56:27.643550Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90621740, which exceeds the log group capacity 90593280.
2026-06-03T07:56:47.845714Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90627886, which exceeds the log group capacity 90593280.
2026-06-03T07:57:04.714691Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90639662, which exceeds the log group capacity 90593280.
2026-06-03T07:57:26.028889Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90645808, which exceeds the log group capacity 90593280.
2026-06-03T07:57:42.796901Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90655262, which exceeds the log group capacity 90593280.
2026-06-03T07:58:04.513110Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90670384, which exceeds the log group capacity 90593280.
2026-06-03T07:58:20.675070Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90689842, which exceeds the log group capacity 90593280.
2026-06-03T07:58:39.362158Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90699949, which exceeds the log group capacity 90593280.
2026-06-03T07:58:57.146181Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90707243, which exceeds the log group capacity 90593280.
2026-06-03T07:59:15.226281Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90731065, which exceeds the log group capacity 90593280.
2026-06-03T07:59:32.902269Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90751406, which exceeds the log group capacity 90593280.
2026-06-03T07:59:55.020833Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use 
--explicit_defaults_for_timestamp server option (see documentation for more details).
2026-06-03T07:59:55.022839Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' 
sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2026-06-03T07:59:55.022856Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2026-06-03T07:59:55.022918Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2026-06-03T07:59:55.028372Z 0 [Note] MySQL (mysqld 5.7.27) starting as process 2532 ...
2026-06-03T07:59:55.078201Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2026-06-03T07:59:55.078998Z 0 [Note] InnoDB: Uses event mutexes
2026-06-03T07:59:55.079491Z 0 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2026-06-03T07:59:55.080092Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2026-06-03T07:59:55.084872Z 0 [Note] InnoDB: Number of pools: 1
2026-06-03T07:59:55.090793Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2026-06-03T07:59:55.096910Z 0 [Note] InnoDB: Initializing buffer pool, total size = 40G, instances = 8, chunk size = 128M
2026-06-03T07:59:57.966267Z 0 [Note] InnoDB: Completed initialization of buffer pool
2026-06-03T07:59:58.778551Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2026-06-03T07:59:59.348188Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 15319447826657
2026-06-03T07:59:59.942491Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319453069312
2026-06-03T08:00:00.233703Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319458312192
2026-06-03T08:00:00.470153Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319463555072
2026-06-03T08:00:01.158338Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319468797952
2026-06-03T08:00:01.852263Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319474040832
2026-06-03T08:00:02.555075Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319479283712
2026-06-03T08:00:03.289043Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319484526592
2026-06-03T08:00:04.031381Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319489769472
2026-06-03T08:00:04.754714Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319495012352
2026-06-03T08:00:05.533650Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319500255232
2026-06-03T08:00:06.253542Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319505498112
2026-06-03T08:00:06.883691Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319510740992
2026-06-03T08:00:07.603988Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319515983872
2026-06-03T08:00:08.268531Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319521226752
2026-06-03T08:00:08.967662Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319526469632
2026-06-03T08:00:09.323566Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 15319529184727
2026-06-03T08:00:09.328240Z 0 [Note] InnoDB: Database was not shutdown normally!
2026-06-03T08:00:09.328844Z 0 [Note] InnoDB: Starting crash recovery.
2026-06-03T08:00:09.730171Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
2026-06-03T08:00:09.731034Z 0 [Note] InnoDB: Trx id counter is 8424439040
2026-06-03T08:00:09.731402Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 …… 94 95 96 97 98 99 
2026-06-03T08:00:17.587182Z 0 [Note] InnoDB: Apply batch completed
2026-06-03T08:01:02.988241Z 0 [Note] InnoDB: Completing truncate for table with id (8714) residing in file-per-table tablespace with id (6005)
2026-06-03T08:01:07.965314Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90593580, which exceeds the log group capacity 90593280.
2026-06-03T08:01:25.945332Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90599727, which exceeds the log group capacity 90593280.
2026-06-03T08:01:43.117294Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90610481, which exceeds the log group capacity 90593280.
2026-06-03T08:02:05.338558Z 0 [ERROR] InnoDB: The age of the last checkpoint is 90622769, which exceeds the log group capacity 90593280.

从这里看，最初是truncate table xxxx,然后由于被阻塞了无法truncate成功,可以就关闭了mysql服务,然后启动库就没有成功,然后就是加上了innodb_force_recovery出现了上述截图的错误.尝试进行强制拉库,遭遇以下错误

2026-06-04T07:05:59.924315Z 0 [Note] MySQL (mysqld 5.7.27) starting as process 8764 ...
2026-06-04T07:05:59.944187Z 0 [Warning] option 'innodb-purge-threads': unsigned value 0 adjusted to 1
2026-06-04T07:05:59.947611Z 0 [Note] InnoDB: Started in read only mode
2026-06-04T07:05:59.948012Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2026-06-04T07:05:59.948485Z 0 [Note] InnoDB: Uses event mutexes
2026-06-04T07:05:59.948825Z 0 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2026-06-04T07:05:59.949329Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2026-06-04T07:05:59.950087Z 0 [Note] InnoDB: Number of pools: 1
2026-06-04T07:05:59.950587Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2026-06-04T07:05:59.950987Z 0 [Note] InnoDB: Disabling background log and ibuf IO write threads.
2026-06-04T07:05:59.952835Z 0 [Note] InnoDB: Initializing buffer pool, total size = 512M, instances = 1, chunk size = 128M
2026-06-04T07:05:59.980631Z 0 [Note] InnoDB: Completed initialization of buffer pool
2026-06-04T07:06:00.012856Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2026-06-04T07:06:00.013649Z 0 [Note] InnoDB: The user has set SRV_FORCE_NO_LOG_REDO on, skipping log redo
2026-06-04T07:06:00.019299Z 0 [Note] InnoDB: Completing truncate for table with id (8714) residing in file-per-table tablespace with id (6005)
07:06:00 UTC - mysqld got exception 0xc0000005 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=200
thread_count=0
connection_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 87429 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
7ff67eaba97e    mysqld.exe!std::operator<<<std::char_traits<char> >()[ostream:791]
7ff67f1ffd49    mysqld.exe!os_file_create_subdirs_if_needed()[os0file.cc:2013]
7ff67f22e967    mysqld.exe!fil_ibd_create()[fil0fil.cc:3530]
7ff67f2afdd7    mysqld.exe!truncate_t::fixup_tables_in_non_system_tablespace()[row0trunc.cc:2274]
7ff67f1c563a    mysqld.exe!innobase_start_or_create_for_mysql()[srv0start.cc:2346]
7ff67f12ea40    mysqld.exe!innobase_init()[ha_innodb.cc:4077]
7ff67e9b783e    mysqld.exe!ha_initialize_handlerton()[handler.cc:840]
7ff67eab7228    mysqld.exe!plugin_initialize()[sql_plugin.cc:1229]
7ff67eab8790    mysqld.exe!plugin_register_builtin_and_init_core_se()[sql_plugin.cc:1589]
7ff67e972de3    mysqld.exe!init_server_components()[mysqld.cc:4080]
7ff67e977da5    mysqld.exe!win_main()[mysqld.cc:4773]
7ff67e975705    mysqld.exe!mysql_service()[mysqld.cc:5226]
7ff80e734da7    MSVCR120.dll!_beginthread()
7ff80e734e60    MSVCR120.dll!_endthread()
7ff84e4d84d4    KERNEL32.DLL!BaseThreadInitThunk()
7ff850cb1791    ntdll.dll!RtlUserThreadStart()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

在启动过程中需要去完成truncate操作,但是由于强制拉库是只读状态导致无法完成,直接启动失败.如果非只读状态拉库,启动过程包InnoDB: Corruption of an index tree: table `innodb_change_buffer` index `CLUST_IND`, father ptr page no 111415, child page no 517749异常

2026-06-04T13:35:46.447160Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace 
but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html 
for information about forcing recovery.
2026-06-04T13:35:46.448525Z 0 [ERROR] InnoDB: Corruption of an index tree: table `innodb_change_buffer` index `CLUST_IND`, 
father ptr page no 111415, child page no 517749
PHYSICAL RECORD: n_fields 6; 1-byte offsets; info bits 0
 0: len 4; hex 00001775; asc    u;;
 1: len 1; hex 00; asc  ;;
 2: len 4; hex 00e78555; asc    U;;
 3: len 16; hex 000400010c0f0190002d860800088000; asc          -      ;;
 4: len 29; hex 323032362d30332d31345f3132325f315f323032363033313432303136; asc 2026-03-14_122_1_202603142016;;
 5: len 8; hex 800000001b26cad6; asc      &  ;;
2026-06-04T13:35:46.450738Z 0 [Note] InnoDB: n_owned: 0; heap_no: 2; next rec: 211
PHYSICAL RECORD: n_fields 7; 1-byte offsets; info bits 0
 0: len 4; hex 00001775; asc    u;;
 1: len 1; hex 00; asc  ;;
 2: len 4; hex 00e78555; asc    U;;
 3: len 16; hex 000400010c0f0190002d860800088000; asc          -      ;;
 4: len 29; hex 323032362d30332d31345f3132325f315f323032363033313432303136; asc 2026-03-14_122_1_202603142016;;
 5: len 8; hex 800000001b26cad6; asc      &  ;;
 6: len 4; hex 0001b337; asc    7;;
2026-06-04T13:35:46.452647Z 0 [Note] InnoDB: n_owned: 0; heap_no: 147; next rec: 14554
2026-06-04T13:35:46.453038Z 0 [ERROR] [FATAL] InnoDB: You should dump + drop + reimport the table to fix the corruption. 
If the crash happens at database startup. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html 
for information about forcing recovery. Then dump + drop + reimport.
2026-06-04 21:35:46 0x828  InnoDB: Assertion failure in thread 2088 in file ut0ut.cc line 910
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
13:35:46 UTC - mysqld got exception 0x80000003 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=200
thread_count=0
connection_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 87429 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
7ff7c7794312    mysqld.exe!my_sigabrt_handler()[my_thr_init.c:449]
7fffaf31ec9d    MSVCR120.dll!raise()
7fffaf324874    MSVCR120.dll!abort()
7ff7c78b07e4    mysqld.exe!ut_dbg_assertion_failed()[ut0dbg.cc:67]
7ff7c78b09c1    mysqld.exe!ib::fatal::~fatal()[ut0ut.cc:910]
7ff7c790a794    mysqld.exe!btr_page_get_father_node_ptr_func()[btr0btr.cc:799]
7ff7c790a28e    mysqld.exe!btr_page_get_father()[btr0btr.cc:854]
7ff7c7906cca    mysqld.exe!btr_compress()[btr0btr.cc:3577]
7ff7c7913a3e    mysqld.exe!btr_cur_compress_if_useful()[btr0cur.cc:5068]
7ff7c7917f7c    mysqld.exe!btr_cur_pessimistic_delete()[btr0cur.cc:5403]
7ff7c79583f9    mysqld.exe!ibuf_delete_rec()[ibuf0ibuf.cc:4385]
7ff7c795805e    mysqld.exe!ibuf_delete_for_discarded_space()[ibuf0ibuf.cc:4833]
7ff7c78d51a8    mysqld.exe!fil_recreate_tablespace()[fil0fil.cc:2265]
7ff7c794fe06    mysqld.exe!truncate_t::fixup_tables_in_non_system_tablespace()[row0trunc.cc:2297]
7ff7c786563a    mysqld.exe!innobase_start_or_create_for_mysql()[srv0start.cc:2346]
7ff7c77cea40    mysqld.exe!innobase_init()[ha_innodb.cc:4077]
7ff7c705783e    mysqld.exe!ha_initialize_handlerton()[handler.cc:840]
7ff7c7157228    mysqld.exe!plugin_initialize()[sql_plugin.cc:1229]
7ff7c7158790    mysqld.exe!plugin_register_builtin_and_init_core_se()[sql_plugin.cc:1589]
7ff7c7012de3    mysqld.exe!init_server_components()[mysqld.cc:4080]
7ff7c7017da5    mysqld.exe!win_main()[mysqld.cc:4773]
7ff7c7015705    mysqld.exe!mysql_service()[mysqld.cc:5226]
7fffaf2d4da7    MSVCR120.dll!_beginthread()
7fffaf2d4e60    MSVCR120.dll!_endthread()
7fffd0f784d4    KERNEL32.DLL!BaseThreadInitThunk()
7fffd3b91791    ntdll.dll!RtlUserThreadStart()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

基于这种两种情况:
2026-06-04T13:35:46.448525Z 0 [ERROR] InnoDB: Corruption of an index tree: table `innodb_change_buffer` index `CLUST_IND`, father ptr page no 111415, child page no 517749和InnoDB: Completing truncate for table with id (8714) residing in file-per-table tablespace with id (6005)异常形成了相互死循环,无法直接强制拉库.
这个库有1.5T如果通过工具提取效率有点低
data

对于这样的情况,使用ibd的discard+import功能进行处理,参考相关文章:
frm和ibd文件数据库恢复
运气不错,这个客户的所有库通过这种方法导入ibd文件（部分temp结尾的临时表数据可以不用恢复,占据空间较大）之后,然后通过mysqldump顺利导出所有数据,完成本次恢复任务
sql
发表在 MySQL恢复 | 标签为 , , , , , | 评论关闭