[MDEV-22373] Unable to find a record to delete-mark ends up crashing mysqld process after upgrading from 10.1.43 to 10.4 - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Incomplete
Affects Version/s: 10.4.12, 10.4.13, 10.3.28, 10.5.6, 10.5.9
Fix Version/s: N/A
Component/s: Storage Engine - InnoDB, Upgrades
Labels:
- need_feedback
Environment:
debian

Description

We have a very loaded host with a 12TB database and a bunch of views which runs multisource replication and replicates from 8 masters.
This host receives hard queries all the time and usually gets behind on replication - also the innodb purge thread (we only have 1, and we are going to increase it) gets very busy and gets a long list of items to purge.
We upgraded this host today from 10.1.43 to 10.4.12We started mariadb using:

--skip-slave-start

just in case.
At the time of the upgrade, all the replication threads were up-to-date with the master, but one of them, which was around 33k seconds lagged. innodb_history_list_length showed around 1.3 billion items to purge.

The upgrade was done and when we started it we saw a bunch of:

Apr 27 06:29:21 labsdb1011 mysqld[3538]: 2020-04-27  6:29:21 0 [ERROR] InnoDB: Unable to find a record to delete-mark

Apr 27 06:29:21 labsdb1011 mysqld[3538]: InnoDB: tuple DATA TUPLE: 2 fields;

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  0: len 4; hex 013e4784; asc  >G ;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  1: len 4; hex 213c96ad; asc !<  ;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]: InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  0: len 4; hex 013e4784; asc  >G ;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  1: len 4; hex 21372e6c; asc !7.l;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]: 2020-04-27  6:29:21 0 [ERROR] InnoDB: page [page id: space=256581, page number=53240] (636 records, index id 859571).

Apr 27 06:29:21 labsdb1011 mysqld[3538]: 2020-04-27  6:29:21 0 [ERROR] InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

Apr 27 06:29:21 labsdb1011 mysqld[3538]: 2020-04-27  6:29:21 0 [ERROR] InnoDB: Unable to find a record to delete-mark

Apr 27 06:29:21 labsdb1011 mysqld[3538]: InnoDB: tuple DATA TUPLE: 2 fields;

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  0: len 4; hex 013e3fdf; asc  >? ;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  1: len 4; hex 213dcde2; asc !=  ;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]: InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  0: len 4; hex 013e3fdf; asc  >? ;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]:  1: len 4; hex 21276716; asc !'g ;;

Apr 27 06:29:21 labsdb1011 mysqld[3538]: 2020-04-27  6:29:21 0 [ERROR] InnoDB: page [page id: space=256581, page number=53240] (647 records, index id 859571).

Apr 27 06:29:21 labsdb1011 mysqld[3538]: 2020-04-27  6:29:21 0 [ERROR] InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

Apr 27 06:34:49 labsdb1011 mysqld[3538]: 2020-04-27  6:34:49 0 [ERROR] InnoDB: Unable to find a record to delete-mark

Apr 27 06:34:49 labsdb1011 mysqld[3538]: InnoDB: tuple DATA TUPLE: 3 fields;

Apr 27 06:34:49 labsdb1011 mysqld[3538]:  0: len 4; hex 04181a75; asc    u;;

Apr 27 06:34:49 labsdb1011 mysqld[3538]:  1: len 14; hex 3230323030343236313935323230; asc 20200426195220;;

Apr 27 06:34:49 labsdb1011 mysqld[3538]:  2: len 4; hex 18bf0c80; asc     ;;

Apr 27 06:34:49 labsdb1011 mysqld[3538]: InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32

Apr 27 06:34:49 labsdb1011 mysqld[3538]:  0: len 4; hex 04181a75; asc    u;;

Apr 27 06:34:49 labsdb1011 mysqld[3538]:  1: len 14; hex 3230313830353031303434363432; asc 20180501044642;;

Apr 27 06:34:49 labsdb1011 mysqld[3538]:  2: len 4; hex 11d56a47; asc   jG;;

Apr 27 06:34:49 labsdb1011 mysqld[3538]: 2020-04-27  6:34:49 0 [ERROR] InnoDB: page [page id: space=292394, page number=7919199] (539 records, index id 983019).

Apr 27 06:34:49 labsdb1011 mysqld[3538]: 2020-04-27  6:34:49 0 [ERROR] InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

Apr 27 06:40:09 labsdb1011 mysqld[3538]: 2020-04-27  6:40:09 1 [ERROR] InnoDB: tried to purge non-delete-marked record in index `namespace_title_from` of table `trwiki`.`flaggedrevs_tracking`: tuple: TUPLE (info_bits=0, 3 fields): {[4]   <(0x8000033C),[7]Dol  ub(0x446F6CC

Apr 27 06:42:08 labsdb1011 mysqld[3538]: 2020-04-27  6:42:08 10 [ERROR] InnoDB: tried to purge non-delete-marked record in index `tl_backlinks_namespace` of table `arwikiquote`.`templatelinks`: tuple: TUPLE (info_bits=0, 4 fields): {[4]    (0x80000000),[4]    (0x8000000A)

Apr 27 06:44:38 labsdb1011 mysqld[3538]: 2020-04-27  6:44:38 4 [ERROR] InnoDB: tried to purge non-delete-marked record in index `iwl_prefix_title_from` of table `metawiki`.`iwlinks`: tuple: TUPLE (info_bits=0, 3 fields): {[2]pl(0x706C),[14]Wiktor_Suworow(0x57696B746F725F5

The server started fine, but from time to time we're still seeing some:

Apr 27 07:12:49 labsdb1011 mysqld[3538]: 2020-04-27  7:12:49 1 [ERROR] InnoDB: tried to purge non-delete-marked record in index `cat_pages` of table `enwikinews`.`category`: tuple: TUPLE (info_bits=0, 2 fields): {[4]  PM(0x8000504D),[4]   `(0x00040960)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4]  PM(0x8000504D),[4]   `(0x00040960)}

Apr 27 07:14:47 labsdb1011 mysqld[3538]: 2020-04-27  7:14:47 1 [ERROR] InnoDB: tried to purge non-delete-marked record in index `cat_pages` of table `enwikinews`.`category`: tuple: TUPLE (info_bits=0, 2 fields): {[4]    (0x80000009),[4]    (0x0000000E)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4]    (0x80000009),[4]    (0x0000000E)}

Apr 27 07:16:12 labsdb1011 mysqld[3538]: 2020-04-27  7:16:12 1 [ERROR] InnoDB: tried to purge non-delete-marked record in index `pl_backlinks_namespace` of table `cywiki`.`pagelinks`: tuple: TUPLE (info_bits=0, 4 fields): {[4]    (0x80000000),[4]    (0x80000000),[23]Unol_Daleithiau_America(0x556E6F6C5F44616C656974686961755F416D6572696361),[4]  #p(0x00032370)}, record: COMPACT RECORD(info_bits=0, 4 fields): {[4]    (0x80000000),[4]    (0x80000000),[23]Unol_Daleithiau_America(0x556E6F6C5F44616C656974686961755F416D6572696361),[4]  #p(0x00032370)}

Apr 27 07:17:14 labsdb1011 mysqld[3538]: 2020-04-27  7:17:14 1 [ERROR] InnoDB: tried to purge non-delete-marked record in index `cat_pages` of table `enwikinews`.`category`: tuple: TUPLE (info_bits=0, 2 fields): {[4]  PM(0x8000504D),[4]   `(0x00040960)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4]  PM(0x8000504D),[4]   `(0x00040960)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `rc_name_type_patrolled_timestamp` of table `frwikibooks`.`recentchanges` was not found on update: TUPLE (info_bits=0, 5 fields): {[4]    (0x80000002),[1] (0x01)

,[1] (0x00),[14]20200427054352(0x3230323030343237303534333532),[4]    (0x800A0E94)} at: COMPACT RECORD(info_bits=32, 5 fields): {[4]    (0x80000002),[1] (0x01),[1] (0x00),[14]20200426164210(0x3230323030343236313634323130),[4]   \(0x800A0E5C)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `page_timestamp` of table `frwikibooks`.`revision` was not found on update: TUPLE (info_bits=0, 3 fields): {[4]  $ (0x00012407),[14]20200427042010(0x323032303034

3237303432303130),[4]    (0x0009BEA9)} at: COMPACT RECORD(info_bits=0, 3 fields): {[4]  $ (0x00012406),[14]20200426185042(0x3230323030343236313835303432),[4]    (0x0009BE8E)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `usertext_timestamp` of table `frwikibooks`.`revision` was not found on update: TUPLE (info_bits=0, 3 fields): {[0](0x),[14]20200427042010(0x32303230303432373034

32303130),[4]    (0x0009BEA9)} at: COMPACT RECORD(info_bits=0, 3 fields): {[0](0x),[14]20200427004308(0x3230323030343237303034333038),[4]    (0x0009BEA8)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `rev_page_id` of table `frwikibooks`.`revision` was not found on update: TUPLE (info_bits=0, 2 fields): {[4]  $ (0x00012407),[4]    (0x0009BEA9)} at: COMPACT REC

ORD(info_bits=0, 2 fields): {[4]  $ (0x00012406),[4]    (0x0009BE8E)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `page_timestamp` of table `frwikibooks`.`revision` was not found on update: TUPLE (info_bits=0, 3 fields): {[4]  $ (0x00012407),[14]20200427042131(0x323032303034

3237303432313331),[4]    (0x0009BEAA)} at: COMPACT RECORD(info_bits=0, 3 fields): {[4]  $ (0x00012406),[14]20200426185042(0x3230323030343236313835303432),[4]    (0x0009BE8E)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `usertext_timestamp` of table `frwikibooks`.`revision` was not found on update: TUPLE (info_bits=0, 3 fields): {[0](0x),[14]20200427042131(0x32303230303432373034

32313331),[4]    (0x0009BEAA)} at: COMPACT RECORD(info_bits=0, 3 fields): {[0](0x),[14]20200427004308(0x3230323030343237303034333038),[4]    (0x0009BEA8)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `rev_page_id` of table `frwikibooks`.`revision` was not found on update: TUPLE (info_bits=0, 2 fields): {[4]  $ (0x00012407),[4]    (0x0009BEAA)} at: COMPACT RECORD(info_bits=0, 2 fields): {[4]  $ (0x00012406),[4]    (0x0009BE8E)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `revcomment_comment_id` of table `frwikibooks`.`revision_comment_temp` was not found on update: TUPLE (info_bits=0, 2 fields): {[8]        (0x0000000000000001),[4]    (0x0009BEAA)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8]        (0x0000000000000001),[4]    (0x0009BE9D)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `page_actor_timestamp` of table `frwikibooks`.`revision_actor_temp` was not found on update: TUPLE (info_bits=0, 4 fields): {[4]  $ (0x00012407),[8]      P (0x000000000002501C),[14]20200427042010(0x3230323030343237303432303130),[4]    (0x0009BEA9)} at: COMPACT RECORD(info_bits=0, 4 fields): {[4]  $ (0x00012406),[8]       f(0x0000000000000566),[14]20200426185042(0x3230323030343236313835303432),[4]    (0x0009BE8E)}

Apr 27 07:42:03 labsdb1011 mysqld[3538]: 2020-04-27  7:42:03 2400 [ERROR] Master 's3': InnoDB: Record in index `page_actor_timestamp` of table `frwikibooks`.`revision_actor_temp` was not found on update: TUPLE (info_bits=0, 4 fields): {[4]  $ (0x00012407),[8]      P (0x000000000002501C),[14]20200427042131(0x3230323030343237303432313331),[4]    (0x0009BEAA)} at: COMPACT RECORD(info_bits=0, 4 fields): {[4]  $ (0x00012406),[8]       f(0x0000000000000566),[14]20200426185042(0x3230323030343236313835303432),[4]    (0x0009BE8E)}

Apr 27 07:42:04 labsdb1011 mysqld[3538]: 2020-04-27  7:42:04 0 [ERROR] InnoDB: Unable to find a record to delete-mark

After a while mysql totally crashed:

Apr 27 07:45:51 labsdb1011 mysqld[3538]: InnoDB: tuple DATA TUPLE: 3 fields;

Apr 27 07:45:51 labsdb1011 mysqld[3538]:  0: len 4; hex 001bbe4d; asc    M;;

Apr 27 07:45:51 labsdb1011 mysqld[3538]:  1: len 40; hex 687474703a2f2f7777772e7371756172652d656e69782e636f2e6a702f736d6172742f6368726f6e; asc http://www.square-enix.co.jp/smart/chron;;

Apr 27 07:45:51 labsdb1011 mysqld[3538]:  2: len 4; hex 005df5a9; asc  ]  ;;

Apr 27 07:45:51 labsdb1011 mysqld[3538]: InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32

Apr 27 07:45:51 labsdb1011 mysqld[3538]:  0: len 4; hex 001bbe4d; asc    M;;

Apr 27 07:45:51 labsdb1011 mysqld[3538]:  1: len 30; hex 687474703a2f2f7777772e7370656369616c6f6c796d706963732e6f7267; asc http://www.specialolympics.org; (total 31 bytes);

Apr 27 07:45:51 labsdb1011 mysqld[3538]:  2: len 4; hex 005deb02; asc  ]  ;;

Apr 27 07:45:51 labsdb1011 mysqld[3538]: 2020-04-27  7:45:51 0 [ERROR] InnoDB: page [page id: space=326966, page number=118166] (172 records, index id 1207580).

Apr 27 07:45:51 labsdb1011 mysqld[3538]: 2020-04-27  7:45:51 0 [ERROR] InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

Apr 27 07:45:56 labsdb1011 mysqld[3538]: 2020-04-27 07:45:56 0x7f5e502f6700  InnoDB: Assertion failure in file /root/mariadb-10.4.12/storage/innobase/row/row0ins.cc line 263

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: Failing assertion: !cursor->index->is_committed()

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: We intentionally generate a memory trap.

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: If you get repeated assertion failures or crashes, even

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: immediately after the mysqld startup, there may be

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: corruption in the InnoDB tablespace. Please refer to

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/

Apr 27 07:45:56 labsdb1011 mysqld[3538]: InnoDB: about forcing recovery.

Apr 27 07:45:56 labsdb1011 mysqld[3538]: 200427  7:45:56 [ERROR] mysqld got signal 6 ;

Apr 27 07:45:56 labsdb1011 mysqld[3538]: This could be because you hit a bug. It is also possible that this binary

Apr 27 07:45:56 labsdb1011 mysqld[3538]: or one of the libraries it was linked against is corrupt, improperly built,

Apr 27 07:45:56 labsdb1011 mysqld[3538]: or misconfigured. This error can also be caused by malfunctioning hardware.

Apr 27 07:45:56 labsdb1011 mysqld[3538]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs

Apr 27 07:45:56 labsdb1011 mysqld[3538]: We will try our best to scrape up some info that will hopefully help

Apr 27 07:45:56 labsdb1011 mysqld[3538]: diagnose the problem, but since we have already crashed,

Apr 27 07:45:56 labsdb1011 mysqld[3538]: something is definitely wrong and this may fail.

Apr 27 07:45:56 labsdb1011 mysqld[3538]: Server version: 10.4.12-MariaDB

Apr 27 07:45:56 labsdb1011 mysqld[3538]: key_buffer_size=134217728

Apr 27 07:45:56 labsdb1011 mysqld[3538]: read_buffer_size=131072

Apr 27 07:45:56 labsdb1011 mysqld[3538]: max_used_connections=48

Apr 27 07:45:56 labsdb1011 mysqld[3538]: max_threads=1026

Apr 27 07:45:56 labsdb1011 mysqld[3538]: thread_count=76

Apr 27 07:45:56 labsdb1011 mysqld[3538]: It is possible that mysqld could use up to

Apr 27 07:45:56 labsdb1011 mysqld[3538]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2388976 K  bytes of memory

Apr 27 07:45:56 labsdb1011 mysqld[3538]: Hope that's ok; if not, decrease some variables in the equation.

Apr 27 07:45:56 labsdb1011 mysqld[3538]: Thread pointer: 0x7f5a240014f8

Apr 27 07:45:56 labsdb1011 mysqld[3538]: Attempting backtrace. You can use the following information to find out

Apr 27 07:45:56 labsdb1011 mysqld[3538]: where mysqld died. If you see no messages after this, something went

Apr 27 07:45:56 labsdb1011 mysqld[3538]: terribly wrong...

Apr 27 07:45:56 labsdb1011 mysqld[3538]: stack_bottom = 0x7f5e502f4e98 thread_stack 0x30000

Apr 27 07:45:57 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(my_print_stacktrace+0x2e)[0x55d21bbee5ee]

Apr 27 07:45:58 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(handle_fatal_signal+0x54d)[0x55d21b6e413d]

Apr 27 07:45:58 labsdb1011 mysqld[3538]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x12730)[0x7fc506732730]

Apr 27 07:45:59 labsdb1011 mysqld[3538]: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x10b)[0x7fc505d9a7bb]

Apr 27 07:45:59 labsdb1011 mysqld[3538]: /lib/x86_64-linux-gnu/libc.so.6(abort+0x121)[0x7fc505d85535]

Apr 27 07:46:00 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0x5a10e5)[0x55d21b3d90e5]

Apr 27 07:46:00 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0x58fe9b)[0x55d21b3c7e9b]

Apr 27 07:46:01 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0xaf46e0)[0x55d21b92c6e0]

Apr 27 07:46:01 labsdb1011 CRON[14110]: (prometheus) CMD (/usr/local/bin/prometheus-puppet-agent-stats --outfile /var/lib/prometheus/node.d/puppet_agent.prom)

Apr 27 07:46:01 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0xb27a78)[0x55d21b95fa78]

Apr 27 07:46:02 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0xb2d40f)[0x55d21b96540f]

Apr 27 07:46:02 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0xb0555c)[0x55d21b93d55c]

Apr 27 07:46:03 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0xa5549c)[0x55d21b88d49c]

Apr 27 07:46:03 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(_ZN7handler13ha_update_rowEPKhS1_+0x123)[0x55d21b6f0923]

Apr 27 07:46:04 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEP14rpl_group_info+0x243)[0x55d21b7e4183]

Apr 27 07:46:04 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x25d)[0x55d21b7d747d]

Apr 27 07:46:05 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0x5faac8)[0x55d21b432ac8]

Apr 27 07:46:05 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(handle_slave_sql+0x169a)[0x55d21b43bc6a]

Apr 27 07:46:06 labsdb1011 mysqld[3538]: /opt/wmf-mariadb104/bin/mysqld(+0xd66f8b)[0x55d21bb9ef8b]

Apr 27 07:46:07 labsdb1011 mysqld[3538]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x7fa3)[0x7fc506727fa3]

Apr 27 07:46:07 labsdb1011 mysqld[3538]: /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7fc505e5c4cf]

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Trying to get some variables.

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Some pointers may be invalid and cause the dump to abort.

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Query (0x0):

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Connection ID (thread ID): 2400

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Status: NOT_KILLED

Apr 27 07:46:07 labsdb1011 mysqld[3538]: 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

Apr 27 07:46:07 labsdb1011 mysqld[3538]: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains

Apr 27 07:46:07 labsdb1011 mysqld[3538]: information that should help you find out what is causing the crash.

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Writing a core file...

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Working directory at /srv/sqldata

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Resource Limits:

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Limit                     Soft Limit           Hard Limit           Units

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max cpu time              unlimited            unlimited            seconds

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max file size             unlimited            unlimited            bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max data size             unlimited            unlimited            bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max stack size            8388608              unlimited            bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max core file size        0                    0                    bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max resident set          unlimited            unlimited            bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max processes             2063395              2063395              processes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max open files            200001               200001               files

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max locked memory         65536                65536                bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max address space         unlimited            unlimited            bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max file locks            unlimited            unlimited            locks

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max pending signals       2063395              2063395              signals

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max msgqueue size         819200               819200               bytes

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max nice priority         0                    0

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max realtime priority     0                    0

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Max realtime timeout      unlimited            unlimited            us

Apr 27 07:46:07 labsdb1011 mysqld[3538]: Core pattern: /var/tmp/core/core.%h.%e.%p.%t

mysql_upgrade was run.
Could this be related to ~~MDEV-11802~~?

Attachments

Issue Links

is caused by

MDEV-21069 Crash on DROP TABLE if the data file is corrupted

Closed

relates to

MDEV-22759 Failing assertion: !cursor->index->is_committed() upon update on table with HASH index

Closed

MDEV-22924 Warning InnoDB: Index 'Marvão_idx3' contains 36 entries, should be 37.

Closed

MDEV-24402 CHECK TABLE may miss some cases of index inconsistencies

Closed

MDEV-25344 Two hosts crashed at the same time with: Failing assertion: !cursor->index->is_committed()

Closed

MDEV-25869 Change buffer entries for secondary indexes are lost on InnoDB restart

Closed

MDEV-26746 InnoDB: Unable to find a record to delete-mark

Closed

MDEV-27987 "[ERROR] InnoDB: Unable to find a record to delete-mark" shortly after upgrading slave from 10.5.10 to 10.6.5

Closed

MDEV-9663 InnoDB assertion failure: *cursor->index->name == TEMP_INDEX_PREFIX, or !cursor->index->is_committed()

Closed

MDEV-13542 Crashing on a corrupted page is unhelpful

Closed

MDEV-21790 secondary index corruption after 10.3.21 upgrade from 5.5

Closed

MDEV-24449 Corruption of system tablespace or last recovered page

Closed

MDEV-25783 CHECK TABLE harvests InnoDB: Index 'abdcef' contains 10001 entries, should be 10000

Closed

MDEV-25796 Failing assertion: !cursor->index->is_committed() in row0ins.cc

Open

mentioned in: Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...

(9 relates to, 21 mentioned in)

Activity

Ascending order - Click to sort in descending order

View 102 older comments

Marko Mäkelä added a comment - 2021-09-29 05:45

I am closing this due to lack of feedback. I believe that the related problems have been fixed already; see my comment on 2021-06-07 for details.

Marko Mäkelä added a comment - 2021-09-29 05:45 I am closing this due to lack of feedback. I believe that the related problems have been fixed already; see my comment on 2021-06-07 for details.

Manuel Arostegui added a comment - 2021-09-29 05:52 - edited

For what is worth, today we just had a crash on 10.4.21 (this host was just upgraded from 10.1).

Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29  0:24:49 55 [ERROR] InnoDB: In pages [page id: space=1059, page number=3618135] and [page id: space=1059, page number=3618150] of index `wbt_item_terms_item_id` of table `wikidatawiki`.`wbt_item_terms`

Sep 29 00:24:49 db2080 mysqld[4266]: InnoDB: records in wrong order on adjacent pages

Sep 29 00:24:49 db2080 mysqld[4266]: InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0

Sep 29 00:24:49 db2080 mysqld[4266]:  0: len 4; hex 00fc7d70; asc   }p;;

Sep 29 00:24:49 db2080 mysqld[4266]:  1: len 8; hex 00000000fae2d10c; asc         ;;

Sep 29 00:24:49 db2080 mysqld[4266]: InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0

Sep 29 00:24:49 db2080 mysqld[4266]:  0: len 4; hex 0066ad08; asc  f  ;;

Sep 29 00:24:49 db2080 mysqld[4266]:  1: len 8; hex 00000000aea663dc; asc       c ;;

Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29  0:24:49 55 [ERROR] InnoDB: Corruption of an index tree: table `wikidatawiki`.`wbt_item_terms` index `wbt_item_terms_item_id`, father ptr page no 3618114, child page no 3618150

Sep 29 00:24:49 db2080 mysqld[4266]: PHYSICAL RECORD: n_fields 2; compact format; info bits 0

Sep 29 00:24:49 db2080 mysqld[4266]:  0: len 4; hex 0066ad08; asc  f  ;;

Sep 29 00:24:49 db2080 mysqld[4266]:  1: len 8; hex 00000000aea663dc; asc       c ;;

Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29  0:24:49 55 [Note] InnoDB: n_owned: 0; heap_no: 466; next rec: 125

Sep 29 00:24:49 db2080 mysqld[4266]: PHYSICAL RECORD: n_fields 3; compact format; info bits 0

Sep 29 00:24:49 db2080 mysqld[4266]:  0: len 4; hex 0066ad02; asc  f  ;;

Sep 29 00:24:49 db2080 mysqld[4266]:  1: len 8; hex 000000000ec51a93; asc         ;;

Sep 29 00:24:49 db2080 mysqld[4266]:  2: len 4; hex 00373542; asc  75B;;

Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29  0:24:49 55 [Note] InnoDB: n_owned: 0; heap_no: 351; next rec: 7475

Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29  0:24:49 55 [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 in

Sep 29 00:24:49 db2080 mysqld[4266]: 210929  0:24:49 [ERROR] mysqld got signal 6 ;

Whether this corruption was already present and it simply crashed after the upgrade (and during mysqlcheck)...that's hard to know (we've been running innodb_change_buffering = none for months though).

Manuel Arostegui added a comment - 2021-09-29 05:52 - edited For what is worth, today we just had a crash on 10.4.21 (this host was just upgraded from 10.1). Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29 0:24:49 55 [ERROR] InnoDB: In pages [page id: space=1059, page number=3618135] and [page id: space=1059, page number=3618150] of index `wbt_item_terms_item_id` of table `wikidatawiki`.`wbt_item_terms` Sep 29 00:24:49 db2080 mysqld[4266]: InnoDB: records in wrong order on adjacent pages Sep 29 00:24:49 db2080 mysqld[4266]: InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0 Sep 29 00:24:49 db2080 mysqld[4266]: 0: len 4; hex 00fc7d70; asc }p;; Sep 29 00:24:49 db2080 mysqld[4266]: 1: len 8; hex 00000000fae2d10c; asc ;; Sep 29 00:24:49 db2080 mysqld[4266]: InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0 Sep 29 00:24:49 db2080 mysqld[4266]: 0: len 4; hex 0066ad08; asc f ;; Sep 29 00:24:49 db2080 mysqld[4266]: 1: len 8; hex 00000000aea663dc; asc c ;; Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29 0:24:49 55 [ERROR] InnoDB: Corruption of an index tree: table `wikidatawiki`.`wbt_item_terms` index `wbt_item_terms_item_id`, father ptr page no 3618114, child page no 3618150 Sep 29 00:24:49 db2080 mysqld[4266]: PHYSICAL RECORD: n_fields 2; compact format; info bits 0 Sep 29 00:24:49 db2080 mysqld[4266]: 0: len 4; hex 0066ad08; asc f ;; Sep 29 00:24:49 db2080 mysqld[4266]: 1: len 8; hex 00000000aea663dc; asc c ;; Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29 0:24:49 55 [Note] InnoDB: n_owned: 0; heap_no: 466; next rec: 125 Sep 29 00:24:49 db2080 mysqld[4266]: PHYSICAL RECORD: n_fields 3; compact format; info bits 0 Sep 29 00:24:49 db2080 mysqld[4266]: 0: len 4; hex 0066ad02; asc f ;; Sep 29 00:24:49 db2080 mysqld[4266]: 1: len 8; hex 000000000ec51a93; asc ;; Sep 29 00:24:49 db2080 mysqld[4266]: 2: len 4; hex 00373542; asc 75B;; Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29 0:24:49 55 [Note] InnoDB: n_owned: 0; heap_no: 351; next rec: 7475 Sep 29 00:24:49 db2080 mysqld[4266]: 2021-09-29 0:24:49 55 [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 in Sep 29 00:24:49 db2080 mysqld[4266]: 210929 0:24:49 [ERROR] mysqld got signal 6 ; Whether this corruption was already present and it simply crashed after the upgrade (and during mysqlcheck )...that's hard to know (we've been running innodb_change_buffering = none for months though).

Marko Mäkelä added a comment - 2021-09-29 07:32

marostegui, in ~~MDEV-9663~~ you can find many tickets reporting some inconsistency of index trees. Most of them are related to change buffering, and the open ones are mostly related to indexed virtual columns (~~MDEV-5800~~, MariaDB 10.2). If you have a backup of the data before upgrading, I think that it would be useful to run CHECK TABLE on that, before enabling any writes. My best guess for this corruption would be the recovery race conditions that were fixed in ~~MDEV-24449~~ and ~~MDEV-24709~~. In that case, this corruption would have been dormant until you ran CHECK TABLE (without QUICK). If you never ran CHECK TABLE before upgrading, it is plausible that you never experienced other failures due to these non-leaf secondary index pages.

Apart from bugs related to change buffering, there was ~~MDEV-18272~~, but it would cause a different type of failure, and I do not think that normal applications should be affected by it.

Marko Mäkelä added a comment - 2021-09-29 07:32 marostegui , in MDEV-9663 you can find many tickets reporting some inconsistency of index trees. Most of them are related to change buffering, and the open ones are mostly related to indexed virtual columns ( MDEV-5800 , MariaDB 10.2). If you have a backup of the data before upgrading, I think that it would be useful to run CHECK TABLE on that, before enabling any writes. My best guess for this corruption would be the recovery race conditions that were fixed in MDEV-24449 and MDEV-24709 . In that case, this corruption would have been dormant until you ran CHECK TABLE (without QUICK ). If you never ran CHECK TABLE before upgrading, it is plausible that you never experienced other failures due to these non-leaf secondary index pages. Apart from bugs related to change buffering, there was MDEV-18272 , but it would cause a different type of failure, and I do not think that normal applications should be affected by it.

Marko Mäkelä added a comment - 2021-09-29 08:39

For the record, I believe that the original reported problem was caused by ~~MDEV-21069~~ and fixed by ~~MDEV-25869~~. The reported server version number 10.4.12, 10.4.13, 10.3.28 match that. The reported 10.5.6 and 10.5.9 failures ought to be due to ~~MDEV-25783~~.

Marko Mäkelä added a comment - 2021-09-29 08:39 For the record, I believe that the original reported problem was caused by MDEV-21069 and fixed by MDEV-25869 . The reported server version number 10.4.12, 10.4.13, 10.3.28 match that. The reported 10.5.6 and 10.5.9 failures ought to be due to MDEV-25783 .

Marko Mäkelä added a comment - 2021-09-29 08:53 - edited

I am sorry if my intentions were unclear, but I was looking for feedback of the type “yes, the ~~MDEV-25869~~ fix seems to work.” marostegui reported that he had set innodb_change_buffering=none, which means that he would not be able to encounter this class of bugs anymore, whether they are fixed or not. So, I was waiting for that kind of feedback from other affected users. It was surprisingly hard to repeat these types of errors in our internal testing. So, I was expecting some ‘statistical validation’ from the community. I closed this basically assuming that “no news is good news.”

For future corruption reports, I suggest that new bugs be filed. Before upgrading from an older major version of MariaDB server, I suggest a normal clean shutdown (and backing up the data, just in case). I would suggest to avoid innodb_fast_shutdown=0; it is unnecessary now that ~~MDEV-15912~~ has been fixed, and it might make dormant corruption worse.

Marko Mäkelä added a comment - 2021-09-29 08:53 - edited I am sorry if my intentions were unclear, but I was looking for feedback of the type “yes, the MDEV-25869 fix seems to work.” marostegui reported that he had set innodb_change_buffering=none , which means that he would not be able to encounter this class of bugs anymore, whether they are fixed or not. So, I was waiting for that kind of feedback from other affected users. It was surprisingly hard to repeat these types of errors in our internal testing. So, I was expecting some ‘statistical validation’ from the community. I closed this basically assuming that “no news is good news.” For future corruption reports, I suggest that new bugs be filed. Before upgrading from an older major version of MariaDB server, I suggest a normal clean shutdown (and backing up the data, just in case). I would suggest to avoid innodb_fast_shutdown=0 ; it is unnecessary now that MDEV-15912 has been fixed, and it might make dormant corruption worse.

People

Assignee:: Marko Mäkelä

Reporter:: Manuel Arostegui

Votes:: 9 Vote for this issue

Watchers:: 36 Start watching this issue

Dates

Created:: 2020-04-27 07:57

Updated:: 2024-09-06 09:59

Resolved:: 2021-09-29 05:45

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server