[MDEV-25796] Failing assertion: !cursor->index->is_committed() in row0ins.cc Created: 2021-05-27  Updated: 2022-06-22

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4.19
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Alex Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 0
Labels: None
Environment:

Debian Buster


Attachments: PNG File HDD utilisation after enabling change buffer.png    
Issue Links:
Relates
relates to MDEV-22373 Unable to find a record to delete-mar... Closed
relates to MDEV-25869 Change buffer entries for secondary i... Closed
relates to MDEV-26977 mariadb 10.5.12 reboot loop in AWS | ... Closed
relates to MDEV-27734 Set innodb_change_buffering=none by d... Closed
relates to MDEV-27744 LPAD in vcol created in ORACLE mode m... Closed
relates to MDEV-27987 "[ERROR] InnoDB: Unable to find a rec... Closed

 Description    

2021-05-27 11:26:07 0x7f18d2013700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.4.19/storage/innobase/row/row0ins.cc line 218
 
InnoDB: Failing assertion: !cursor->index->is_committed()
 
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 mysqld 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.
 
210527 11:26:07 [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.4.19-MariaDB-1:10.4.19+maria~buster-log
 
key_buffer_size=131072
 
read_buffer_size=131072
 
max_used_connections=1624
 
max_threads=5002
 
thread_count=1640
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11008450 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f17f05735d8
 
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 = 0x7f18d2012dd8 thread_stack 0x49000
 
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5644a8906f0e]
 
/usr/sbin/mysqld(handle_fatal_signal+0x54d)[0x5644a83f6fbd]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12730)[0x7f4c83c80730]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x10b)[0x7f4c837d67bb]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x121)[0x7f4c837c1535]
 
/usr/sbin/mysqld(+0x5b4700)[0x5644a80e9700]
 
/usr/sbin/mysqld(+0x5a2a9e)[0x5644a80d7a9e]
 
/usr/sbin/mysqld(+0xb1158e)[0x5644a864658e]
 
/usr/sbin/mysqld(+0xb11c76)[0x5644a8646c76]
 
/usr/sbin/mysqld(+0xb23afb)[0x5644a8658afb]
 
/usr/sbin/mysqld(+0xa6cfd5)[0x5644a85a1fd5]
 
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPKh+0x1af)[0x5644a8402fff]
 
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x1ad)[0x5644a81b464d]
 
/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0xabf)[0x5644a81baf3f]
 
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x3636)[0x5644a81ea636]
 
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x1e9)[0x5644a81eeb09]
 
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0x17f5)[0x5644a81f11d5]
 
/usr/sbin/mysqld(_Z10do_commandP3THD+0x13a)[0x5644a81f23ba]
 
/usr/sbin/mysqld(_Z24do_handle_one_connectionP7CONNECT+0x233)[0x5644a82d64a3]
 
/usr/sbin/mysqld(handle_one_connection+0x3d)[0x5644a82d659d]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7fa3)[0x7f4c83c75fa3]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f4c838984cf]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f17f0579930): insert ignore into listing (id,type,salesman,l) values (43284937,15389,354744,"2021-05-27 11:25:53"),(46976667,14257,321914,"2021-05-27 11:25:50"),(59124647,14683,336558,"2021-05-27 11:25:52"),(74179242,13467,569131,"2021-05-27 11:25:18"),(83293122,2186,336558,"2021-05-27 11:25:25"),(98548682,14685,336558,"2021-05-27 11:25:41"),(108276337,1795,339766,"2021-05-27 11:25:50"),(108535722,14683,336558,"2021-05-27 11:25:52"),(124098502,15202,336558,"2021-05-27 11:25:10"),(132142832,13053,519582,"2021-05-27 11:25:27"),(153330807,15323,519582,"2021-05-27 11:25:15"),(163292162,15389,354744,"2021-05-27 11:25:52"),(164598142,15397,354744,"2021-05-27 11:25:53"),(169325892,2230,519582,"2021-05-27 11:25:15"),(180647207,16144,519582,"2021-05-27 11:25:14"),(183833512,2661,519582,"2021-05-27 11:25:04"),(183871592,14816,519582,"2021-05-27 11:25:04"),(202487292,15389,354744,"20
 
21-05-27 11:25:52"),(203071587,15389,354744,"2021-05-27 11:25:53"),(203072967,15389,354744,"2021-05-27 11:25:53"),(208207257,14385,519582,"2021-05-27 11:25:26"),(210784182,14385,519582,"2021-05-27 11:25:23"),(216390437,13285,519582,"2021-05-27 11:25:14"),(217873877,2657,519582,"2021-05-27 11:25:14"),(222547557,11534,519582,"2021-05-27 11:25:03"),(222549277
 
,2326,519582,"2021-05-27 11:25:03"),(224041982,12346,519582,"2021-05-27 11:25:14"),(224090257,12968,519582,"2021-05-27 11:25:25"),(225865867,13775,921672,"2021-05-27 11:25:14"),(2
 
26408437,13455,534960,"2021-05-27 11:25:09"),(227050127,13455,534960,"2021-05-27 11:25:10"),(227870662,15389,354744,"2021-05-27 11:25:52"),(229697237,14034,569131,"2021-05-27 11:2
 
5:15"),(229977642,15427,921672,"2021-05-27 11:25:31"),(231815522,14385,519582,"2021-05-27 11:25:26"),(231843492,2666,519582,"2021-05-27 11:25:14"),(234580232,13467,534960,"2021-05
 
-27 11:25:34"),(234582992,14385,519582,"2021-05-27 11:25:34"),(234612197,13810,564261,"2021-05-27 11:25:48"),(234612287,13810,564261,"2021-05-27 11:25:48"),(234612322,13810,564261
 
,"2021-05-27 11:25:48"),(234612527,14899,564261,"2021-05-27 11:25:48"),(235183782,14025,569131,"2021-05-27 11:25:15"),(238932692,14196,436304,"2021-05-27 11:25:02"),(238932697,14225,359604,"2021-05-27 11:25:10"),(238932702,14646,358612,"2021-05-27 11:25:49"),(238932707,14212,60095,"2021-05-27 11:25:25"),(238932712,2230,882100,"2021-05-27 11:25:27"),(238932717,13051,304197,"2021-05-27 11:25:34"),(238932722,14683,453828,"2021-05-27 11:25:40"),(238932727,12686,336353,"2021-05-27 11:25:42"),(238932732,14371,357931,"2021-05-27 11:25:44"),(238932737,14924,342318,"2021-05-27 11:25:47"),(238932742,14339,344562,"2021-05-27 11:25:51"),(238932747,14924,342318,"2021-05-27 11:25:58")
 
 
 
Connection ID (thread ID): 54201
 
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
 
 
 
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 /db/main/tables
 
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             1031235              1031235              processes 
Max open files            32768                32768                files     
Max locked memory         65536                65536                bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       1031235              1031235              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



 Comments   
Comment by Alex [ 2021-05-27 ]

And We have corrupted indexes in tables.

Comment by Alice Sherepa [ 2021-05-27 ]

please add the output of SHOW CREATE TABLE listing;

Comment by Alex [ 2021-05-27 ] 

CREATE TABLE `listing` (
 
  `id` int(10) unsigned NOT NULL DEFAULT 0,
 
  `salesman` mediumint(8) unsigned NOT NULL DEFAULT 0,
 
  `type` int(11) NOT NULL DEFAULT 0,
 
  `l` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(),
 
  PRIMARY KEY (`id`),
 
  KEY `e_t_i` (`type`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8

Comment by Marko Mäkelä [ 2021-06-09 ]

I think that this could have been caused by MDEV-21069 and fixed in MDEV-25869. It is also possible that the database had been corrupted earlier, before MDEV-24449 was fixed.

The fixes of MDEV-24449 and MDEV-25869 will only prevent further corruption of the kind; they will not magically fix existing tables. Dropping the corrupted secondary index and creating it again should fix this corruption. Until you can upgrade to a fixed server, you should run with innodb_change_buffering=none. Do you still observe this failure after those steps?

Comment by Alex [ 2021-09-17 ]

When we disabled change buffer this problem was fixed

Comment by Marko Mäkelä [ 2022-02-04 ]

alexcool, thank you. I am going to disable the change buffer by default (MDEV-27734), but only starting with 10.5. Even with the latest fixes, as reported in MDEV-26977, it can cause some corruption.

Comment by Alex [ 2022-02-05 ]

As I understand your plan is to remove change buffer. That is kind a fine with SSD but HDD installations will suffer.

As you can see on this graph. HDD utilisation goes down significantly after turning on Change buffer. Server has 256G of ram.

Comment by Marko Mäkelä [ 2022-02-05 ]

alexcool, yes, I expect the change buffer to be more helpful on HDD, because it aims to convert random seeks before reads into hopefully more sequential writes (with innodb_flush_neighbors).

The benchmarks posted in MDEV-11634 suggest that the change buffer does not help much on SSD. Similar benchmarks on HDD should be run, to get a more complete picture.

The buffer pool and page flushing changes in 10.5 could have improved the HDD utilization. I would think that configuring a very large redo log (maybe even larger than the buffer pool) can reduce the number of page writes and thus leave some more bandwidth available for page reads. Perhaps we could implement improved logic for triggering read-ahead, to reduce latency in cases that are currently helped by the change buffer.

Generated at Thu Feb 08 09:40:28 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.