Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Cannot Reproduce
-
11.0
Description
Test setup:
- Single SQL input thread
- The original run client was pquery (not required)
- About 18k lines were processed before kill -9 of server (runtime: 10 seconds)
- A copy of the data directory was taken before the first crash recovery attempt
- The default server storage engine was InnoDB (unless changed in the SQL)
- This crash recovery issue is readily reproducible using the original data directory
- The branch in use was bb-11.0-oalter (
MDEV-16329), likely unrelated - On startup, crash recovery fails with:
|
11.0.1 bb-11.0-oalter f9b33ac570337be320f718d52fd88d301a2bc1e7 |
2023-02-25 12:11:51 0 [Note] InnoDB: Initializing buffer pool, total size = 300.000MiB, chunk size = 4.688MiB
|
2023-02-25 12:11:51 0 [Note] InnoDB: Completed initialization of buffer pool
|
2023-02-25 12:11:51 0 [Note] InnoDB: File system buffers for log disabled (block size=4096 bytes)
|
2023-02-25 12:11:51 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=989138
|
2023-02-25 12:11:51 0 [Note] InnoDB: Ignoring a doublewrite copy of page [page id: space=71, page number=3] with future log sequence number 1399073
|
2023-02-25 12:11:51 0 [Note] InnoDB: Ignoring a doublewrite copy of page [page id: space=191, page number=3] with future log sequence number 1420843
|
2023-02-25 12:11:51 0 [Note] InnoDB: Ignoring a doublewrite copy of page [page id: space=183, page number=3] with future log sequence number 1397557
|
2023-02-25 12:11:51 0 [Note] InnoDB: Ignoring a doublewrite copy of page [page id: space=45, page number=3] with future log sequence number 1479977
|
2023-02-25 12:11:51 0 [Note] InnoDB: Ignoring a doublewrite copy of page [page id: space=45, page number=2] with future log sequence number 1479977
|
2023-02-25 12:11:51 0 [Note] InnoDB: Ignoring a doublewrite copy of page [page id: space=3, page number=59] with future log sequence number 1485497
|
2023-02-25 12:11:51 0 [ERROR] InnoDB: Page [page id: space=3, page number=59] log sequence number 1485497 is in the future! Current system log sequence number 1376107.
|
2023-02-25 12:11:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
|
2023-02-25 12:11:51 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 424 row operations to undo
|
2023-02-25 12:11:51 0 [Note] InnoDB: Trx id counter is 1276
|
2023-02-25 12:11:51 0 [Note] InnoDB: Starting final batch to recover 68 pages from redo log.
|
2023-02-25 12:11:51 0 [Note] InnoDB: Last binlog file './binlog.000001', position 106953
|
2023-02-25 12:11:51 0 [Note] InnoDB: Opened 3 undo tablespaces
|
2023-02-25 12:11:51 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
|
2023-02-25 12:11:51 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
|
2023-02-25 12:11:51 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
|
2023-02-25 12:11:51 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
|
2023-02-25 12:11:51 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
|
mysqld: /test/bb-11.0-oalter_dbg/storage/innobase/mtr/mtr0mtr.cc:352: void mtr_t::commit(): Assertion `mach_read_from_8(b->page.frame + 16U) <= m_commit_lsn' failed.
|
|
11.0.1 bb-11.0-oalter f9b33ac570337be320f718d52fd88d301a2bc1e7 |
Program terminated with signal SIGABRT, Aborted.
|
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22422564496960) at ./nptl/pthread_kill.c:44
|
44 ./nptl/pthread_kill.c: No such file or directory.
|
[Current thread is 1 (Thread 0x1464a8fde640 (LWP 4184421))]
|
(gdb) bt
|
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22422564496960) at ./nptl/pthread_kill.c:44
|
#1 __pthread_kill_internal (signo=6, threadid=22422564496960) at ./nptl/pthread_kill.c:78
|
#2 __GI___pthread_kill (threadid=22422564496960, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
|
#3 0x00001464cb270476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
|
#4 0x00001464cb2567f3 in __GI_abort () at ./stdlib/abort.c:79
|
#5 0x00001464cb25671b in __assert_fail_base (fmt=0x1464cb40b150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
|
assertion=0x557403332c70 "mach_read_from_8(b->page.frame + 16U) <= m_commit_lsn",
|
file=0x557403333b28 "/test/bb-11.0-oalter_dbg/storage/innobase/mtr/mtr0mtr.cc", line=352, function=<optimized out>)
|
at ./assert/assert.c:92
|
#6 0x00001464cb267e96 in __GI___assert_fail (
|
assertion=0x557403332c70 "mach_read_from_8(b->page.frame + 16U) <= m_commit_lsn",
|
file=0x557403333b28 "/test/bb-11.0-oalter_dbg/storage/innobase/mtr/mtr0mtr.cc", line=352,
|
function=0x557403332169 "void mtr_t::commit()") at ./assert/assert.c:101
|
#7 0x0000557402c50aba in mtr_t::commit (this=this@entry=0x1464a8fdcef0)
|
at /test/bb-11.0-oalter_dbg/storage/innobase/mtr/mtr0mtr.cc:352
|
#8 0x0000557402d90830 in trx_undo_truncate_end (undo=..., limit=0, is_temp=is_temp@entry=false)
|
at /test/bb-11.0-oalter_dbg/storage/innobase/trx/trx0undo.cc:869
|
#9 0x0000557402d908e6 in trx_undo_try_truncate (trx=...) at /test/bb-11.0-oalter_dbg/storage/innobase/trx/trx0undo.cc:882
|
#10 0x0000557402d39bd7 in row_undo_rec_get (node=0x146484001860)
|
at /test/bb-11.0-oalter_dbg/storage/innobase/row/row0undo.cc:296
|
#11 row_undo (thr=0x146484001680, node=0x146484001860) at /test/bb-11.0-oalter_dbg/storage/innobase/row/row0undo.cc:390
|
#12 row_undo_step (thr=thr@entry=0x146484001680) at /test/bb-11.0-oalter_dbg/storage/innobase/row/row0undo.cc:452
|
#13 0x0000557402c9608e in que_thr_step (thr=0x146484001680) at /test/bb-11.0-oalter_dbg/storage/innobase/que/que0que.cc:595
|
#14 que_run_threads_low (thr=0x146484001680) at /test/bb-11.0-oalter_dbg/storage/innobase/que/que0que.cc:653
|
#15 que_run_threads (thr=0x146484001680) at /test/bb-11.0-oalter_dbg/storage/innobase/que/que0que.cc:673
|
#16 0x0000557402d796bc in trx_rollback_active (trx=trx@entry=0x1464c9297b80)
|
at /test/bb-11.0-oalter_dbg/storage/innobase/trx/trx0roll.cc:608
|
#17 0x0000557402d7a3dc in trx_rollback_recovered (all=all@entry=true)
|
at /test/bb-11.0-oalter_dbg/storage/innobase/trx/trx0roll.cc:746
|
#18 0x0000557402d7a7c8 in trx_rollback_all_recovered () at /test/bb-11.0-oalter_dbg/storage/innobase/trx/trx0roll.cc:792
|
#19 0x0000557402ef0b6f in tpool::task_group::execute (this=0x55740433d1e0 <rollback_all_recovered_group>,
|
t=t@entry=0x55740433d1c0 <rollback_all_recovered_task>) at /test/bb-11.0-oalter_dbg/tpool/task_group.cc:70
|
#20 0x0000557402ef0dc7 in tpool::task::execute (this=0x55740433d1c0 <rollback_all_recovered_task>)
|
at /test/bb-11.0-oalter_dbg/tpool/task.cc:32
|
#21 0x0000557402eeeb52 in tpool::thread_pool_generic::worker_main (this=0x557404cf1f40, thread_var=0x557404cf2270)
|
at /test/bb-11.0-oalter_dbg/tpool/tpool_generic.cc:580
|
#22 0x0000557402eefece in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__t=<optimized out>, __f=<optimized out>) at /usr/include/c++/11/bits/invoke.h:74
|
#23 std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>
|
(__fn=<optimized out>) at /usr/include/c++/11/bits/invoke.h:96
|
#24 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=<optimized out>) at /usr/include/c++/11/bits/std_thread.h:253
|
#25 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=<optimized out>) at /usr/include/c++/11/bits/std_thread.h:260
|
#26 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool:
|
:thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=<optimized out>) at /usr/include/c++/11/bits/std_thread.h:211
|
#27 0x00001464cb6192b3 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
|
#28 0x00001464cb2c2b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
|
#29 0x00001464cb354a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
|
A full copy of the data dir is available in this ticket, allowing 'first startup after the crash' to be attempted as often as necessary to locate the bug