有客户MySQL数据库异常无法正常启动,需要提供恢复支持,当时提供的错误日志信息为:log sequence number xxxx is in the future
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:
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:
InnoDB: Pending preads 0, pwrites 0
InnoDB:
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出现了上述截图的错误.尝试进行强制拉库,遭遇以下错误
在启动过程中需要去完成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.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如果通过工具提取效率有点低
对于这样的情况,使用ibd的discard+import功能进行处理,参考相关文章:
frm和ibd文件数据库恢复
运气不错,这个客户的所有库通过这种方法导入ibd文件（部分temp结尾的临时表数据可以不用恢复,占据空间较大）之后,然后通过mysqldump顺利导出所有数据,完成本次恢复任务
此内容由惯性聚合(RSS阅读器)自动聚合整理，仅供阅读参考。 原文来自 — 版权归原作者所有。