[MDEV-25702] InnoDB: Failing assertion: rec_offs_nth_extern(offsets, n) for background thread while optimizing table with FULLTEXT index Created: 2021-05-17  Updated: 2021-12-22  Resolved: 2021-09-13

Status: Closed
Project: MariaDB Server
Component/s: Full-text Search, Storage Engine - InnoDB
Affects Version/s: 10.5.9
Fix Version/s: 10.2.41, 10.3.32, 10.4.22, 10.5.13, 10.6.5

Type: Bug Priority: Critical
Reporter: Valerii Kravchuk Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-23670 Crash during OPTIMIZE TABLE mysql.inn... Closed

 Description   

The following assertion failure (and many similar crashes) noted while mysqlcheck -o is executed against InnoDB tables with FULLTEXT indexes:

2021-05-15 04:16:48 0x7feffbcff700 InnoDB: Assertion failure in file /home/jenkins/workspace/MariaDBE-Custom-RPM/label/rhel-8/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX_ON_ES_BACKUP_DEBUGSOURCE/storage/innobase/btr/btr0cur.cc line 6897
InnoDB: Failing assertion: rec_offs_nth_extern(offsets, n)
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.
210515 4:16:48 [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.9-6-MariaDB-enterprise-log
key_buffer_size=2147483648
read_buffer_size=131072
max_used_connections=1
max_threads=252
thread_count=5
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2651902 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
/usr/sbin/mariadbd(my_print_stacktrace+0x2e)[0x56066b2de2ae]
/usr/sbin/mariadbd(handle_fatal_signal+0x485)[0x56066ad63ef5]
sigaction.c:0(__restore_rt)[0x7ff1aa287b30]
:0(__GI_raise)[0x7ff1a7e1984f]
:0(__GI_abort)[0x7ff1a7e03c45]
/usr/sbin/mariadbd(+0x62d86c)[0x56066aa4f86c]
/usr/sbin/mariadbd(+0x630626)[0x56066aa52626]
/usr/sbin/mariadbd(+0xd73d55)[0x56066b195d55]
/usr/sbin/mariadbd(+0xd626d4)[0x56066b1846d4]
/usr/sbin/mariadbd(+0xd64978)[0x56066b186978]
/usr/sbin/mariadbd(+0xcb4e7b)[0x56066b0d6e7b]
/usr/sbin/mariadbd(+0xcb501b)[0x56066b0d701b]
/usr/sbin/mariadbd(+0xcb699c)[0x56066b0d899c]
/usr/sbin/mariadbd(_ZN5tpool4task7executeEv+0x2b)[0x56066b270d7b]
/usr/sbin/mariadbd(_ZN5tpool19thread_pool_generic11worker_mainEPNS_11worker_dataE+0x4f)[0x56066b26f98f]
??:0(std::error_code::default_error_condition() const)[0x7ff1a85e9ba3]
pthread_create.c:0(start_thread)[0x7ff1aa27d15a]
:0(__GI___clone)[0x7ff1a7edef73]
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. 

In the core dump we see this thread with assertion failure:

Thread 1 (Thread 0x7feffbcff700 (LWP 821507)):
#0 0x00007ff1a7e1984f in raise () from /lib64/libc.so.6
#1 0x00007ff1a7e03d0e in abort () from /lib64/libc.so.6
#2 0x000056066aa4f86c in ut_dbg_assertion_failed (expr=expr@entry=0x56066b54b6c0 "rec_offs_nth_extern(offsets, n)",
file=file@entry=0x56066b54b618 "/home/jenkins/workspace/MariaDBE-Custom-RPM/label/rhel-8/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX_ON_ES_BACKUP_DEBUGSOURCE/storage/innobase/btr/btr0cur.cc",
line=line@entry=6897) at /usr/src/debug/MariaDB-/src_0/storage/innobase/ut/ut0dbg.cc:60
#3 0x000056066aa52626 in btr_rec_get_field_ref_offs (offsets=<optimized out>, n=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/btr/btr0cur.cc:6897
#4 btr_rec_get_field_ref_offs (offsets=<optimized out>, n=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/btr/btr0cur.cc:6889
#5 0x000056066b195d55 in btr_store_big_rec_extern_fields (pcur=pcur@entry=0x7feffbcfe170, offsets=offsets@entry=0x7ff0000463f8, big_rec_vec=big_rec_vec@entry=0x7ff0001b52c0,
btr_mtr=btr_mtr@entry=0x7ff00000e588, op=op@entry=BTR_STORE_INSERT_BULK) at /usr/src/debug/MariaDB-/src_0/storage/innobase/btr/btr0cur.cc:7311
#6 0x000056066b1846d4 in PageBulk::storeExt (this=this@entry=0x7ff00000e578, big_rec=big_rec@entry=0x7ff0001b52c0, offsets=offsets@entry=0x7ff0000463f8)
at /usr/src/debug/MariaDB-/src_0/storage/innobase/btr/btr0bulk.cc:815
#7 0x000056066b186978 in BtrBulk::insert (this=0x7fefbc117148, tuple=0x7ff000044630, level=level@entry=0) at /usr/src/debug/MariaDB-/src_0/storage/innobase/btr/btr0bulk.cc:1136
#8 0x000056066b0d6e7b in BtrBulk::insert (tuple=<optimized out>, this=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/include/btr0bulk.h:301
#9 row_merge_write_fts_node (ins_ctx=0x7feffbcfe780, ins_ctx=0x7feffbcfe780, word=0x7feffbcfe760, word=0x7feffbcfe760, node=0x7ff0000ce210)
at /usr/src/debug/MariaDB-/src_0/storage/innobase/row/row0ftsort.cc:1161
#10 row_merge_write_fts_word (ins_ctx=0x7feffbcfe780, word=0x7feffbcfe760) at /usr/src/debug/MariaDB-/src_0/storage/innobase/row/row0ftsort.cc:1189
#11 0x000056066b0d701b in row_fts_insert_tuple (ins_ctx=0x7feffbcfe780, word=0x7feffbcfe760, positions=0x7ff000044508, in_doc_id=0x7feffbcfe758, dtuple=0x7ff000013720)
at /usr/src/debug/MariaDB-/src_0/storage/innobase/row/row0ftsort.cc:1282
#12 0x000056066b0d899c in row_fts_merge_insert (index=<optimized out>, table=<optimized out>, psort_info=<optimized out>, id=<optimized out>)
at /usr/src/debug/MariaDB-/src_0/storage/innobase/row/row0ftsort.cc:1740
#13 0x000056066b270d7b in tpool::task::execute (this=0x7fefbc1976a0) at /usr/src/debug/MariaDB-/src_0/tpool/task.cc:52
#14 tpool::task::execute (this=0x7fefbc1976a0) at /usr/src/debug/MariaDB-/src_0/tpool/task.cc:42
#15 0x000056066b26f98f in tpool::thread_pool_generic::worker_main (this=0x56066c9a40f0, thread_var=0x56066c9b3d90) at /usr/src/debug/MariaDB-/src_0/tpool/tpool_generic.cc:546
#16 0x00007ff1a85e9ba3 in execute_native_thread_routine () from /lib64/libstdc++.so.6
#17 0x00007ff1aa27d15a in start_thread () from /lib64/libpthread.so.0
#18 0x00007ff1a7edef73 in clone () from /lib64/libc.so.6 



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2021-05-21 ]

Can we get following from frame 9 ?

p *tuple->fields@tuple->n_fields
p ins_ctx->aux_index_id
p/x *(char*)tuple->fields[0].data@tuple->fields[0].len

Comment by Valerii Kravchuk [ 2021-05-21 ]

Here it is:

(gdb) frame 9
#9 row_merge_write_fts_node (ins_ctx=0x7feffbcfe780, ins_ctx=0x7feffbcfe780, word=0x7feffbcfe760, word=0x7feffbcfe760, node=0x7ff0000ce210)
at /usr/src/debug/MariaDB-/src_0/storage/innobase/row/row0ftsort.cc:1161
1161 ret = ins_ctx->btr_bulk->insert(tuple);
(gdb) p *tuple->fields@tuple->n_fields
value has been optimized out
(gdb) p ins_ctx->aux_index_id
There is no member named aux_index_id.
(gdb) p/x *(char*)tuple->fields[0].data@tuple->fields[0].len
value has been optimized out 

Comment by Thirunarayanan Balathandayuthapani [ 2021-05-25 ]

Previous comments didn't bring anything at all. Sorry for that. Please can you check the following:

set $offsets=(rec_offs*)0x7ff0000463f8
p/x $offsets@*$offsets
 
set $string= (fts_string_t*) 0x7feffbcfe760
p *$string
p/x *$string.f_str@$string.f_len

Comment by Valerii Kravchuk [ 2021-06-07 ]

(gdb) frame 9
#9 row_merge_write_fts_node (ins_ctx=0x7feffbcfe780, ins_ctx=0x7feffbcfe780, word=0x7feffbcfe760, word=0x7feffbcfe760, node=0x7ff0000ce210)
at /usr/src/debug/MariaDB-/src_0/storage/innobase/row/row0ftsort.cc:1161
1161 ret = ins_ctx->btr_bulk->insert(tuple);
(gdb) set $offsets=(rec_offs*)0x7ff0000463f8
(gdb) p/x $offsets@*$offsets
Only values in memory can be extended with '@'.
(gdb) set $string= (fts_string_t*) 0x7feffbcfe760
(gdb) p *$string
$1 = {f_str = 0x7ff0000c6730 "std", f_len = 3, f_n_char = 0}
(gdb) p/x *$string.f_str@$string.f_len
$2 = {0x73, 0x74, 0x64} 

Comment by Thirunarayanan Balathandayuthapani [ 2021-06-07 ]

Looks like string std is present in many documents. Most probably, ilist could exceed the blob size.
It could make sense to add std as innodb fts stopword.

set $offsets=(rec_offs*)0x7ff0000463f8
p/x *$offsets@*$offsets

Sorry, I messed up again. Slack mistook asterisk as bold and ignored the first asterisk.

Comment by Valerii Kravchuk [ 2021-06-07 ]

(gdb) frame 9
#9 row_merge_write_fts_node (ins_ctx=0x7feffbcfe780, ins_ctx=0x7feffbcfe780, word=0x7feffbcfe760, word=0x7feffbcfe760, node=0x7ff0000ce210)
at /usr/src/debug/MariaDB-/src_0/storage/innobase/row/row0ftsort.cc:1161
1161 ret = ins_ctx->btr_bulk->insert(tuple);
(gdb) set $offsets=(rec_offs*)0x7ff0000463f8
(gdb) p/x *$offsets@*$offsets
$1 = {0xa, 0x7, 0x8008, 0x3, 0xb, 0x11, 0x18, 0x20, 0x24, 0xe4}

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