Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Incomplete
-
10.6.5, 10.7.1
-
Linux 5.15.6 on a BTRFS filesystem
Description
2022-01-09 9:46:34 0 [Note] /usr/sbin/mariadbd (server 10.6.5-MariaDB-1:10.6.5+maria~bullseye-log) starting as process 1834 ...
|
2022-01-09 9:46:34 0 [Warning] You need to use --log-bin to make --binlog-format work.
|
2022-01-09 9:46:34 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2022-01-09 9:46:34 0 [Note] InnoDB: Number of pools: 1
|
2022-01-09 9:46:34 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2022-01-09 9:46:34 0 [Note] InnoDB: Using liburing
|
2022-01-09 9:46:34 0 [Note] InnoDB: Initializing buffer pool, total size = 20401094656, chunk size = 134217728
|
2022-01-09 9:46:34 0 [Note] InnoDB: Completed initialization of buffer pool
|
2022-01-09 9:46:34 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=27704733209067,27704733209067
|
2022-01-09 9:46:35 0 [Note] InnoDB: 19 transaction(s) which must be rolled back or cleaned up in total 27751 row operations to undo
|
2022-01-09 9:46:35 0 [Note] InnoDB: Trx id counter is 113422811288
|
2022-01-09 9:46:35 0 [Note] InnoDB: Starting final batch to recover 14 pages from redo log.
|
2022-01-09 9:46:35 0 [Note] InnoDB: Last binlog file '/var/log/mysql/mysql-bin.000314', position 5935572
|
2022-01-09 9:46:35 0 [Note] InnoDB: 128 rollback segments are active.
|
2022-01-09 9:46:35 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
|
2022-01-09 9:46:35 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
|
2022-01-09 9:46:35 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2022-01-09 9:46:35 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2022-01-09 9:46:35 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2022-01-09 9:46:35 0 [Note] InnoDB: 10.6.5 started; log sequence number 27704733225827; transaction id 113422811289
|
2022-01-09 9:46:35 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
|
2022-01-09 9:46:35 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2022-01-09 9:46:35 0 [Warning] 'innodb-buffer-pool-instances' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
|
2022-01-09 9:46:35 0 [Warning] 'innodb-log-files-in-group' was removed. It does nothing now and exists only for compatibility with old my.cnf files.
|
2022-01-09 9:46:35 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
|
2022-01-09 9:46:35 0 [Note] Server socket created on IP: '0.0.0.0'.
|
2022-01-09 9:46:35 0 [Note] /usr/sbin/mariadbd: ready for connections.
|
Version: '10.6.5-MariaDB-1:10.6.5+maria~bullseye-log' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
|
2022-01-09 09:46:35 0x7f60f12f8700 InnoDB: Assertion failure in file ./storage/innobase/btr/btr0cur.cc line 297
|
InnoDB: Failing assertion: btr_page_get_next(latch_leaves.blocks[0]->frame) == block->page.id().page_no()
|
InnoDB: We intentionally generate a memory trap.
|
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
|
InnoDB: If you get repeated assertion failures or crashes, even
|
InnoDB: immediately after the mariadbd startup, there may be
|
InnoDB: corruption in the InnoDB tablespace. Please refer to
|
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
|
InnoDB: about forcing recovery.
|
220109 9:46:35 [ERROR] mysqld got signal 6 ;
|
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.
|
|
|
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
|
|
|
We will try our best to scrape up some info that will hopefully help
|
diagnose the problem, but since we have already crashed,
|
something is definitely wrong and this may fail.
|
|
|
Server version: 10.6.5-MariaDB-1:10.6.5+maria~bullseye-log
|
key_buffer_size=134217728
|
read_buffer_size=131072
|
max_used_connections=0
|
max_threads=3074
|
thread_count=0
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6900114 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...
|
stack_bottom = 0x0 thread_stack 0x49000
|
??:0(my_print_stacktrace)[0x559e1209c29e]
|
??:0(handle_fatal_signal)[0x559e11b61bd5]
|
??:0(__restore_rt)[0x7f65dd388140]
|
??:0(gsignal)[0x7f65dced1ce1]
|
??:0(abort)[0x7f65dcebb537]
|
??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x559e11802bc7]
|
??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x559e11805f5e]
|
??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x559e11f7eca9]
|
??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x559e11f0de93]
|
??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x559e11f0def8]
|
??:0(void std::vector<unsigned long, std::allocator<unsigned long> >::_M_realloc_insert<unsigned long>(__gnu_cxx::__normal_iterator<unsigned long*, std::vector<unsigned long, std::allocator<unsigned long> > >, unsigned long&&))[0x559e1202442d]
|
??:0(void std::vector<unsigned long, std::allocator<unsigned long> >::_M_realloc_insert<unsigned long>(__gnu_cxx::__normal_iterator<unsigned long*, std::vector<unsigned long, std::allocator<unsigned long> > >, unsigned long&&))[0x559e120249ac]
|
??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x559e11f1969b]
|
??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x559e11ed128f]
|
??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x559e11f3dbe8]
|
??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x559e11f3efa8]
|
??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x559e118008db]
|
??:0(tpool::task_group::execute(tpool::task*))[0x559e120349c9]
|
??:0(tpool::thread_pool_generic::worker_main(tpool::worker_data*))[0x559e12033c1f]
|
??:0(std::error_code::default_error_condition() const)[0x7f65dd26fed0]
|
??:0(start_thread)[0x7f65dd37cea7]
|
??:0(clone)[0x7f65dcf93def]
|
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
|
information that should help you find out what is causing the crash.
|
Writing a core file...
|
Working directory at /var/lib/mysql
|
Resource Limits:
|
Limit Soft Limit Hard Limit Units
|
Max cpu time unlimited unlimited seconds
|
Max file size unlimited unlimited bytes
|
Max data size unlimited unlimited bytes
|
Max stack size 8388608 unlimited bytes
|
Max core file size 0 unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 128343 128343 processes
|
Max open files 35111 35111 files
|
Max locked memory 65536 65536 bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 128343 128343 signals
|
Max msgqueue size 819200 819200 bytes
|
Max nice priority 0 0
|
Max realtime priority 0 0
|
Max realtime timeout unlimited unlimited us
|
Core pattern: core
|
|
|
Aborted
|
Attachments
Issue Links
- is duplicated by
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
MDEV-23599 btrfs coming to Fedora 33 - soon October 2020
-
- Closed
-
Activity
After starting the database with innodb_force_recovery=3
I find that it works normal for most operations, except for one table: menu_bgroup.
Even the simplest update queries on that table result in a lock timeout.
From the output of the innodb engine status:
Update menu_bgroup FORCE INDEX(url) set counter = 1586 where url = 'pa_ownstock_all.php' and displaycounter = 1
------- TRX HAS BEEN WAITING 10048877 ns FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 155278 page no 585 n bits 152 index PRIMARY of table `menu_bgroup` trx id 113426929208 lock_mode X locks rec but not gap waiting
Record lock, heap no 43 PHYSICAL RECORD: n_fields 23; compact format; info bits 0
0: len 4; hex 8000ad0c; asc ;;
1: len 6; hex 001a68b9a235; asc h 5;;
2: len 7; hex 5c000240c3042b; asc \ @ +;;
3: len 6; hex 504120416c6c; asc PA All;;
4: len 4; hex 80000001; asc ;;
5: len 4; hex 80000042; asc B;;
6: len 19; hex 70615f6f776e73746f636b5f616c6c2e706870; asc pa_ownstock_all.php;;
7: len 4; hex 80000000; asc ;;
8: len 4; hex 80000001; asc ;;
9: len 4; hex 800005cf; asc ;;
10: len 4; hex 80000029; asc );;
11: len 4; hex 80000000; asc ;;
12: len 0; hex ; asc ;;
13: len 4; hex 80000000; asc ;;
14: len 4; hex 80000000; asc ;;
15: len 4; hex 80000000; asc ;;
16: len 4; hex 80000000; asc ;;
17: len 4; hex 80000000; asc ;;
18: len 1; hex 80; asc ;;
19: len 1; hex 81; asc ;;
20: SQL NULL;
21: len 1; hex 80; asc ;;
22: len 1; hex 80; asc ;;
------------------
---TRANSACTION (0x7ffb20380730), ACTIVE 23 sec fetching rows
mysql tables in use 1, locked 0
0 lock struct(s), heap size 1128, 0 row lock(s)
Does that explain why the query seems to wait forever on a lock?
There are no other queries write-locking that table.
Yes, there numerous read queries on that table.
The cause of the assertion failure is some corruption. The cause of the corruption could be anywhere, including hardware malfunction (such as failing RAM or hard disk), a bug in the file system, or a bug in MariaDB Server.
Unfortunately, the built-in stack trace in the crash report is invalid. The corruption could be identified better if you started the database server inside a debugger, and then got a stack trace from the debugger. Or if you enabled core dumps and checked the stack trace from the core dump. https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/
The setting innodb_force_recovery=3 will prevent a rollback of any incomplete transactions that were recovered based on undo logs. Those transactions will continue to hold locks on the records that they had durably modified.
Something similar was reported in MDEV-18606, obviously for a much older Linux kernel.
This isn't the kernel bug in MDEV-27900 as the error showed up much later and would have shown up as an early failure to read ./ibdata1 during the innodb initialization rather (unless recovery maybe reads ibdata1 later?).
We really need a core backtrace to start investigating this further.
I tried an upgrade to MariaDB 10.7.1
Same problem.
The database starts only when I set innodb_force_recovery=3
This is true for both 10.6.5 and for 10.7.1