Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Incomplete
-
10.5.13, 10.7.1
-
None
-
Fedora 34, 64bit
Description
I was using my nextcloud instance as normal, until I suddenly got a status 500 code in my browser. Went to investigate, as I had changed nothing about my setup or anything.
When I finally got to the mariadb.log file, the first error looks like this:
2022-02-07 17:24:05 0 [ERROR] InnoDB: Unable to find a record to delete-mark |
InnoDB: tuple DATA TUPLE: 2 fields; |
0: len 8; hex 80000000005d205c; asc ] \;; |
1: len 8; hex 8000000000023902; asc 9 ;; |
|
|
InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0 |
0: len 8; hex 80000000005d205c; asc ] \;; |
1: len 8; hex 8000000000020100; asc ;; |
2022-02-07 17:24:06 0 [ERROR] InnoDB: page [page id: space=12, page number=492] (379 records, index id 913). |
2022-02-07 17:24:06 0 [ERROR] InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ |
2022-02-07 17:24:31 0 [ERROR] InnoDB: Corruption of an index tree: table `nextcloud`.`oc_filecache` index `fs_size`, father ptr page no 2211, child page no 492 |
PHYSICAL RECORD: n_fields 2; compact format; info bits 0 |
0: len 8; hex 800000000000615e; asc a^;; |
1: len 8; hex 338000000000014e; asc 3 N;; |
2022-02-07 17:24:31 0 [Note] InnoDB: n_owned: 0; heap_no: 380; next rec: 125 |
PHYSICAL RECORD: n_fields 3; compact format; info bits 0 |
0: len 8; hex 8000000000004a97; asc J ;; |
1: len 8; hex 800000000000fac4; asc ;; |
2: len 4; hex 000008a3; asc ;; |
2022-02-07 17:24:31 0 [Note] InnoDB: n_owned: 0; heap_no: 66; next rec: 1750 |
2022-02-07 17:24:31 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery. Then dump + drop + reimport. |
220207 17:24:31 [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.5.13-MariaDB |
key_buffer_size=134217728 |
read_buffer_size=131072 |
max_used_connections=52 |
max_threads=153 |
thread_count=34 |
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467872 K bytes of memory |
Hope that's ok; if not, decrease some variables in the equation. |
|
|
Thread pointer: 0x559eec6fc5c8 |
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 = 0x7fa606813b38 thread_stack 0x49000 |
/usr/libexec/mariadbd(my_print_stacktrace+0x3f)[0x559eea7ba7bf] |
/usr/libexec/mariadbd(handle_fatal_signal+0x4d8)[0x559eea313638] |
??:0(__restore_rt)[0x7fa62d2b0a20] |
:0(__GI_raise)[0x7fa62cd9f2a2] |
:0(__GI_abort)[0x7fa62cd888a4] |
??:0(wsrep_write_dummy_event_low(THD*, char const*))[0x559ee9f29842] |
??:0(wsrep_write_dummy_event_low(THD*, char const*))[0x559ee9f4da0d] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea6bd69a] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea6d4752] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea6e1019] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea67d032] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea682b96] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea683764] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea64907a] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x559eea69c092] |
??:0(tpool::task_group::execute(tpool::task*))[0x559eea74fc61] |
??:0(tpool::thread_pool_generic::worker_main(tpool::worker_data*))[0x559eea74fe8e] |
??:0(std::error_code::default_error_condition() const)[0x7fa62d150c84] |
??:0(start_thread)[0x7fa62d2a6299] |
:0(__GI___clone)[0x7fa62ce62353] |
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x0): (null) |
Connection ID (thread ID): 0 |
Status: NOT_KILLED
|
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on,not_null_range_scan=off |
|
|
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.
|
|
|
We think the query pointer is invalid, but we will try to print it anyway. |
Query:
|
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 unlimited unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 39677 39677 processes |
Max open files 32186 32186 files |
Max locked memory 65536 65536 bytes |
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 39677 39677 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: |/usr/lib/systemd/systemd-coredump %P %u %g %s %t %c %h
|
There are many other errors after that however, they are all the same (endless tries of starting mariadb):
2022-02-07 17:26:31 0 [Note] InnoDB: Uses event mutexes |
2022-02-07 17:26:31 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 |
2022-02-07 17:26:31 0 [Note] InnoDB: Number of pools: 1 |
2022-02-07 17:26:31 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions |
2022-02-07 17:26:31 0 [Note] InnoDB: Using Linux native AIO |
2022-02-07 17:26:31 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728 |
2022-02-07 17:26:31 0 [Note] InnoDB: Completed initialization of buffer pool |
2022-02-07 17:26:40 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=28824091881,28824091881 |
2022-02-07 17:26:46 0 [Note] InnoDB: Read redo log up to LSN=28824222720 |
2022-02-07 17:27:02 0 [Note] InnoDB: Read redo log up to LSN=28829662208 |
2022-02-07 17:27:17 0 [Note] InnoDB: To recover: 620 pages from log |
2022-02-07 17:27:18 0 [Note] InnoDB: 3 transaction(s) which must be rolled back or cleaned up in total 3 row operations to undo |
2022-02-07 17:27:18 0 [Note] InnoDB: Trx id counter is 44702066 |
2022-02-07 17:27:18 0 [Note] InnoDB: Starting final batch to recover 618 pages from redo log. |
220207 17:27:18 [ERROR] mysqld got signal 11 ; |
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.5.13-MariaDB |
key_buffer_size=134217728 |
read_buffer_size=131072 |
max_used_connections=0 |
max_threads=153 |
thread_count=0 |
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467872 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)[0x55d9172db7bf] |
??:0(handle_fatal_signal)[0x55d916e34638] |
??:0(__restore_rt)[0x7fc2acc22a20] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x55d917156cdb] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x55d917162842] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x55d91720563a] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x55d9171474c8] |
??:0(wsrep_write_dummy_event_low(THD*, char const*))[0x55d916a50e28] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x55d91723f0cd] |
??:0(Wsrep_server_service::log_state_change(wsrep::server_state::state, wsrep::server_state::state))[0x55d9171485b2] |
??:0(tpool::task_group::execute(tpool::task*))[0x55d917270c61] |
??:0(tpool::thread_pool_generic::worker_main(tpool::worker_data*))[0x55d917270e8e] |
??:0(std::error_code::default_error_condition() const)[0x7fc2acac2c84] |
??:0(start_thread)[0x7fc2acc18299] |
:0(__GI___clone)[0x7fc2ac7d4353] |
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ containsinformation 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 unlimited unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 39677 39677 processes |
Max open files 32186 32186 files |
Max locked memory 65536 65536 bytes |
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 39677 39677 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: |/usr/lib/systemd/systemd-coredump %P %u %g %s %t %c %h
|
I already tried upgrading MariaDB, but version 10.7 also doesn't work, so I reverted back to 10.5.
If any more/different files/logs/etc are needed, just tell me.
Attachments
Issue Links
- is duplicated by
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
MDEV-27734 Set innodb_change_buffering=none by default
-
- Closed
-
Activity
Thanks for your comment.
I tried adding --innodb-change-buffering=none to my systemd service file, as follows:
ExecStart=/usr/libexec/mariadbd --innodb-change-buffering=none --basedir=/usr $MYSQLD_OPTS $_WSREP_NEW_CLUSTER
|
But it still gives the same error in systemd:
mariadb.service: Main process exited, code=killed, status=11/SEGV |
mariadb.service: Failed with result 'signal'. |
Failed to start MariaDB 10.5 database server. |
The mariadb.log error is still the same. But it tries to roll back 3 transactions as before, isn't that what you wanted me to disable?
Sorry, I forgot a "not" in my previous comment. Secondary indexes that are already corrupted will not be automatically fixed by disabling the change buffering.
Fixed it!
As the first error message stated, it was a problem with nextcloud.oc_filecache. As that can easily be rebuilt, I chose to delete the files directly, as only recovery mode 6 could run (read-only). Using recovery mode 6 I could then mysqldump all contents and delete the whole mysql folder (made backup before). I created a new database and imported the dump via mysql < dump.sql. After that, my nextcloud and gitea (also running with mariadb) seem to be working again.
TriKun, good for you. I think that innodb_force_recovery=3 would have been a safer way to achieve the same. innodb_force_recovery=6 (or deleting ib_logfile0 before
MDEV-27199 disallowed it) is very dangerous, because it can make the data pages really inconsistent with each other.
A minimal work-around could have been
ALTER TABLE nextcloud.oc_filecache DROP INDEX …, DROP INDEX …; |
ALTER TABLE nextcloud.oc_filecache ADD INDEX …; |
and a slightly more "overkill" fix would have been
OPTIMIZE TABLE nextcloud.oc_filecache; |
(rebuilding the entire table, not just the secondary indexes).
MDEV-27949 seems to be a duplicate of this.
I realize that the crash occurred on the rollback of recovered incomplete transactions, which was prompting a change buffer merge. innodb_force_recovery=3 prevents the rollback, but the locks held on the table should prevent DROP INDEX or ALTER TABLE from running. You could have taken an SQL dump of the table (with SELECT), shut down the server, deleted the file oc_filecache.ibd, restarted the server, and finally DROP TABLE nextcloud.oc_filecache; and restoring the SQL dump.
I believe that this error is the first step towards the crash of MDEV-26917.
While analyzing failures from a stress test of the fix MDEV-30009, I may have found a possible explanation of this. The scenario is as follows.
- Some changes were buffered to a secondary index leaf page that was not located in the buffer pool.
- The page was freed (possibly as part of DROP INDEX).
- During ibuf_read_merge_pages(), we reset the bitmap bits but will not remove the change buffer records.
- The same page is allocated and reused for something else.
- The page is evicted from the buffer pool.
- Something is added to the change buffer for the page.
- On a change buffer merge, we will apply both old (bogus) and new entries to the page.
With ROW_FORMAT=COMPRESSED the impact should be more severe, because the estimates of page fullness (a prerequisite to ensure that all buffered inserts will fit into a page) are more pessimistic there, to ensure that no compression overflow will occur. Due to the bogus garbage entries that are being merged, the logic will be broken.
As far as I can tell, all MySQL and MariaDB versions are affected by this. The code changes that were applied in MDEV-20934 did not fix this, because that code would only be executed on shutdown with innodb_fast_shutdown=0.
The bottom line is: When the change buffer is enabled (which it was by default until MDEV-27734 changed), InnoDB will start to work randomly. To stop it from working randomly, you do not use the change buffer.
TriKun, can you still reproduce this with a newer version of MariaDB Server? Note that you should rebuild the affected tables (OPTIMIZE TABLE or similar); otherwise you may see the effects of old corruption.
For ROW_FORMAT=COMPRESSED tables it is known that ROLLBACK may cause corruption. See MDEV-32174.
Does this occur when you run the server with innodb_change_buffering=none (which we plan to set by default, in
MDEV-27734)?Note: You will have to rebuild the affected secondary indexes, by executing DROP INDEX and CREATE INDEX (or ALTER TABLE…ADD INDEX). Disabling the change buffering will only prevent further corruption from being introduced by it, but fix already caused corruption.