Assertion `n_null_bytes >= n_core_null_bytes || n_core < index->n_core_fields' in rec_init_offsets_comp_ordinary

origin/bb-10.6-MDEV-26192 61fcbed920c0ed1373725c4122af5a483ae7ffb2 2021-07-20T17:36:46+03:00

Per Marko the problem should be in the actual 10.6 tree too.

# 2021-07-20T15:39:11 [767223] | mysqld: /data/Server/bb-10.6-MDEV-26192/storage/innobase/rem/rem0rec.cc:342: void rec_init_offsets_comp_ordinary(const rec_t*, const dict_index_t*, rec_offs*, ulint, const dict_col_t::def_t*, rec_leaf_format) [with bool mblob = false; bool redundant_temp = true; rec_t = unsigned char; rec_offs = short unsigned int; ulint = long unsigned int]: Assertion `n_null_bytes >= n_core_null_bytes || n_core < index->n_core_fields' failed.

# 2021-07-20T15:39:11 [767223] | 210720 15:36:41 [ERROR] mysqld got signal 6

# 2021-07-20T15:39:11 [767223] | Query (0x62b000173238): OPTIMIZE TABLE `oltp2` /* E_R Thread5 QNO 8637 CON_ID 18 */

# 2021-07-20T15:39:11 [767223] | 

# 2021-07-20T15:39:11 [767223] | Connection ID (thread ID): 18

# 2021-07-20T15:39:11 [767223] | Status: NOT_KILLED

# 2021-07-20T15:39:11 [767223] #3  <signal handler called>

# 2021-07-20T15:39:11 [767223] #4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

# 2021-07-20T15:39:11 [767223] #5  0x00007f7d970cf859 in __GI_abort () at abort.c:79

# 2021-07-20T15:39:11 [767223] #6  0x00007f7d970cf729 in __assert_fail_base (fmt=0x7f7d97265588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x558cc00b9fc0 "n_null_bytes >= n_core_null_bytes || n_core < index->n_core_fields", file=0x558cc00b5fe0 "/data/Server/bb-10.6-MDEV-26192/storage/innobase/rem/rem0rec.cc", line=342, function=<optimized out>) at assert.c:92

# 2021-07-20T15:39:11 [767223] #7  0x00007f7d970e0f36 in __GI___assert_fail (assertion=0x558cc00b9fc0 "n_null_bytes >= n_core_null_bytes || n_core < index->n_core_fields", file=0x558cc00b5fe0 "/data/Server/bb-10.6-MDEV-26192/storage/innobase/rem/rem0rec.cc", line=342, function=0x558cc00bb620 "void rec_init_offsets_comp_ordinary(const rec_t*, const dict_index_t*, rec_offs*, ulint, const dict_col_t::def_t*, rec_leaf_format) [with bool mblob = false; bool redundant_temp = true; rec_t = unsigned char; rec_offs = short unsigned int; ulint = long unsigned int]") at assert.c:101

# 2021-07-20T15:39:11 [767223] #8  0x0000558cbec35b95 in rec_init_offsets_comp_ordinary<false, true> (rec=0x7f7d7b494007 "", index=0x616002b02d08, offsets=0x606000192b00, n_core=17, def_val=0x606000192aa0, format=REC_LEAF_TEMP_INSTANT) at /data/Server/bb-10.6-MDEV-26192/storage/innobase/rem/rem0rec.cc:342

# 2021-07-20T15:39:11 [767223] #9  0x0000558cbec21e5a in rec_init_offsets_temp (rec=0x7f7d7b494007 "", index=0x616002b02d08, offsets=0x606000192b00, n_core=17, def_val=0x606000192aa0, status=REC_STATUS_INSTANT) at /data/Server/bb-10.6-MDEV-26192/storage/innobase/rem/rem0rec.cc:1827

# 2021-07-20T15:39:11 [767223] #10 0x0000558cbecf0dbc in row_log_table_apply_op (thr=0x619001b2a2c0, new_trx_id_col=1, dup=0x7f7d759988f0, error=0x7f7d75998260, offsets_heap=0x631001f04800, heap=0x6310019a0800, mrec=0x7f7d7b494007 "", mrec_end=0x7f7d7b49402b "", offsets=0x606000192b00) at /data/Server/bb-10.6-MDEV-26192/storage/innobase/row/row0log.cc:2493

# 2021-07-20T15:39:11 [767223] #11 0x0000558cbecf68d5 in row_log_table_apply_ops (thr=0x619001b2a2c0, dup=0x7f7d759988f0, stage=0x60200021fe70) at /data/Server/bb-10.6-MDEV-26192/storage/innobase/row/row0log.cc:3066

# 2021-07-20T15:39:11 [767223] #12 0x0000558cbecf76a6 in row_log_table_apply (thr=0x619001b2a2c0, old_table=0x6180003ac908, table=0x7f7d7599a090, stage=0x60200021fe70, new_table=0x618000336108) at /data/Server/bb-10.6-MDEV-26192/storage/innobase/row/row0log.cc:3174

# 2021-07-20T15:39:11 [767223] #13 0x0000558cbe9f9932 in ha_innobase::inplace_alter_table (this=0x61d001a856b8, altered_table=0x7f7d7599a090, ha_alter_info=0x7f7d75999990) at /data/Server/bb-10.6-MDEV-26192/storage/innobase/handler/handler0alter.cc:8477

# 2021-07-20T15:39:11 [767223] #14 0x0000558cbdb1a254 in handler::ha_inplace_alter_table (this=0x61d001a856b8, altered_table=0x7f7d7599a090, ha_alter_info=0x7f7d75999990) at /data/Server/bb-10.6-MDEV-26192/sql/handler.h:4683

# 2021-07-20T15:39:11 [767223] #15 0x0000558cbdaf98b2 in mysql_inplace_alter_table (thd=0x62b00016c218, table_list=0x62b000173388, table=0x61900174a398, altered_table=0x7f7d7599a090, ha_alter_info=0x7f7d75999990, target_mdl_request=0x7f7d75999a90, ddl_log_state=0x7f7d759997b0, trigger_param=0x7f7d7599a4e0, alter_ctx=0x7f7d7599af60) at /data/Server/bb-10.6-MDEV-26192/sql/sql_table.cc:7376

# 2021-07-20T15:39:11 [767223] #16 0x0000558cbdb0d3b8 in mysql_alter_table (thd=0x62b00016c218, new_db=0x558cbf7c4f80 <null_clex_str>, new_name=0x558cbf7c4f80 <null_clex_str>, create_info=0x7f7d7599c380, table_list=0x62b000173388, alter_info=0x7f7d7599c250, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/Server/bb-10.6-MDEV-26192/sql/sql_table.cc:10205

# 2021-07-20T15:39:11 [767223] #17 0x0000558cbdb1568d in mysql_recreate_table (thd=0x62b00016c218, table_list=0x62b000173388, table_copy=false) at /data/Server/bb-10.6-MDEV-26192/sql/sql_table.cc:11253

# 2021-07-20T15:39:11 [767223] #18 0x0000558cbdcae968 in admin_recreate_table (thd=0x62b00016c218, table_list=0x62b000173388) at /data/Server/bb-10.6-MDEV-26192/sql/sql_admin.cc:67

# 2021-07-20T15:39:11 [767223] #19 0x0000558cbdcb61ab in mysql_admin_table (thd=0x62b00016c218, tables=0x62b000173388, check_opt=0x62b000171628, operator_name=0x558cc0858ce0 <msg_optimize>, lock_type=TL_WRITE, org_open_for_modify=true, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(class handler * const, class THD *, HA_CHECK_OPT *)) 0x558cbe06f938 <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0, is_cmd_replicated=true) at /data/Server/bb-10.6-MDEV-26192/sql/sql_admin.cc:1165

# 2021-07-20T15:39:11 [767223] #20 0x0000558cbdcb89b5 in Sql_cmd_optimize_table::execute (this=0x62b000173a80, thd=0x62b00016c218) at /data/Server/bb-10.6-MDEV-26192/sql/sql_admin.cc:1542

# 2021-07-20T15:39:11 [767223] #21 0x0000558cbd8a0196 in mysql_execute_command (thd=0x62b00016c218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-MDEV-26192/sql/sql_parse.cc:5993

# 2021-07-20T15:39:11 [767223] #22 0x0000558cbd8ac668 in mysql_parse (thd=0x62b00016c218, rawbuf=0x62b000173238 "OPTIMIZE TABLE `oltp2` /* E_R Thread5 QNO 8637 CON_ID 18 */", length=59, parser_state=0x7f7d7599eb20) at /data/Server/bb-10.6-MDEV-26192/sql/sql_parse.cc:8026

# 2021-07-20T15:39:11 [767223] #23 0x0000558cbd884907 in dispatch_command (command=COM_QUERY, thd=0x62b00016c218, packet=0x62900141e219 "", packet_length=60, blocking=true) at /data/Server/bb-10.6-MDEV-26192/sql/sql_parse.cc:1896

# 2021-07-20T15:39:11 [767223] #24 0x0000558cbd881cdf in do_command (thd=0x62b00016c218, blocking=true) at /data/Server/bb-10.6-MDEV-26192/sql/sql_parse.cc:1404

# 2021-07-20T15:39:11 [767223] #25 0x0000558cbdc7fe40 in do_handle_one_connection (connect=0x608000003038, put_in_cache=true) at /data/Server/bb-10.6-MDEV-26192/sql/sql_connect.cc:1410

# 2021-07-20T15:39:11 [767223] #26 0x0000558cbdc7f7a2 in handle_one_connection (arg=0x608000003038) at /data/Server/bb-10.6-MDEV-26192/sql/sql_connect.cc:1312

# 2021-07-20T15:39:11 [767223] #27 0x00007f7d975f8609 in start_thread (arg=<optimized out>) at pthread_create.c:477

# 2021-07-20T15:39:11 [767223] #28 0x00007f7d971cc293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

# 2021-07-20T15:39:11 [767223] Will return STATUS_SERVER_CRASHED, ...

sdp:/RQG/storage/1626804927/tmp

gdb -c dev/shm/vardir/1626804927/183/1/data/core /data/Server_bin/bb-10.6-MDEV-26192_asan/bin/mysqld

I was hitting the problem two times.

In the second case the SQL was a

ALTER TABLE `oltp2` ADD COLUMN IF NOT EXISTS ( tcol1 DATE DEFAULT NULL ), LOCK=SHARED, ADD KEY(`id`), LOCK=NONE

RQG

-----

git clone https://github.com/mleich1/rqg --branch experimental RQG

perl rqg.pl \

--gendata=conf/mariadb/oltp.zz \

--max_gd_duration=600 \

--grammar=conf/mariadb/oltp.yy \

--redefine=conf/mariadb/instant_add.yy \

--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \

--mysqld=--loose-idle_write_transaction_timeout=0 \

--mysqld=--loose-idle_transaction_timeout=0 \

--mysqld=--loose-idle_readonly_transaction_timeout=0 \

--mysqld=--connect_timeout=60 \

--mysqld=--interactive_timeout=28800 \

--mysqld=--slave_net_timeout=60 \

--mysqld=--net_read_timeout=30 \

--mysqld=--net_write_timeout=60 \

--mysqld=--loose-table_lock_wait_timeout=50 \

--mysqld=--wait_timeout=28800 \

--mysqld=--lock-wait-timeout=86400 \

--mysqld=--innodb-lock-wait-timeout=50 \

--no-mask \

--queries=10000000 \

--seed=random \

--reporters=Backtrace \

--reporters=ErrorLog \

--reporters=Deadlock1 \

--validators=None \

--mysqld=--log_output=none \

--mysqld=--log_bin_trust_function_creators=1 \

--mysqld=--loose-debug_assert_on_not_freed_memory=0 \

--engine=InnoDB \

--restart_timeout=240 \

--mysqld=--plugin-load-add=file_key_management.so \

--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \

--duration=300 \

--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \

--mysqld=--loose-innodb-sync-debug \

--mysqld=--innodb_stats_persistent=off \

--mysqld=--innodb_adaptive_hash_index=off \

--mysqld=--log-bin \

--mysqld=--sync-binlog=1 \

--mysqld=--loose-innodb_evict_tables_on_commit_debug=off \

--mysqld=--loose-max-statement-time=30 \

--threads=9 \

--mysqld=--innodb_use_native_aio=1 \

--mysqld=--innodb_page_size=64K \

--mysqld=--innodb-buffer-pool-size=24M \

--no_mask \

<local settings>

RQG error pattern

[ 'TBR-1138', 'mysqld: .{1,200}rem0rec.cc:.{1,10}: void rec_init_offsets_comp_ordinary.{1,400}: Assertion \`n_null_bytes >= n_core_null_bytes \|\| n_core < index->n_core_fields\' failed.+RESULT: The RQG run ended with status STATUS_SERVER_CRASHED' ],