Assertion `!memcmp(rec_trx_id, old_pk_trx_id->data, 6 + 7)' failed in row_log_table_apply_update

origin/10.8 b3c254339be29d3be24c16fa0c150ff8ebd0bfda 2022-12-07T09:43:13+02:00

and also bb-10.11-MDEV-29694

Scenario

1. Start the server and generate some unimportant data

2. Thread 1 creates a table

     CREATE TABLE t1 ( col_int INTEGER , col_varchar VARCHAR(500) ) ENGINE = InnoDB ROW_FORMAT = Dynamic ;

      sleeps 1s, runs than

      ALTER TABLE t1 ADD PRIMARY KEY ( col_varchar ) ;

      and exits.

      Threads 2 runs in a loop a random picked SQL of

      UPDATE t1 SET col_int  = { $my_int= $prng->int(513, 4096) } ; COMMIT |

      UPDATE t1 SET col_int  = { $my_int= $prng->int(513, 4096) } ; COMMIT |

      UPDATE t1 SET col_int  = { $my_int= $prng->int(513, 4096) } ; COMMIT |

      INSERT INTO t1 (col_int) VALUES ( { $my_int= $prng->int(513, 4096) } ); COMMIT ;

Sooner or later one of the test runs doing what is described above hits

# 2022-12-08T18:43:44 [4136740] | [rr 4137876 40173]mysqld: /data/Server/10.8H/storage/innobase/row/row0log.cc:1975: dberr_t row_log_table_apply_update(que_thr_t*, ulint, const mrec_t*, const rec_offs*, mem_heap_t*, mem_heap_t*, row_merge_dup_t*, const dtuple_t*): Assertion `!memcmp(rec_trx_id, old_pk_trx_id->data, 6 + 7)' failed.

(rr) bt

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

#1  0x00007f16fd11e859 in __GI_abort () at abort.c:79

#2  0x00007f16fd11e729 in __assert_fail_base (fmt=0x7f16fd2b4588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55579c7f94c0 "!memcmp(rec_trx_id, old_pk_trx_id->data, 6 + 7)", 

    file=0x55579c7f6860 "/data/Server/10.8H/storage/innobase/row/row0log.cc", line=1975, function=<optimized out>) at assert.c:92

#3  0x00007f16fd12ff36 in __GI___assert_fail (assertion=0x55579c7f94c0 "!memcmp(rec_trx_id, old_pk_trx_id->data, 6 + 7)", file=0x55579c7f6860 "/data/Server/10.8H/storage/innobase/row/row0log.cc", line=1975, 

    function=0x55579c7f91c0 "dberr_t row_log_table_apply_update(que_thr_t*, ulint, const mrec_t*, const rec_offs*, mem_heap_t*, mem_heap_t*, row_merge_dup_t*, const dtuple_t*)") at assert.c:101

#4  0x000055579b61f76b in row_log_table_apply_update (thr=0x6190004552c0, new_trx_id_col=1, mrec=0x763a41de7081 "", offsets=0x6030001933c0, offsets_heap=0x621000297d00, heap=0x621000296900, dup=0x763a41dde940, old_pk=0x621000296988)

    at /data/Server/10.8H/storage/innobase/row/row0log.cc:1975

#5  0x000055579b622d22 in row_log_table_apply_op (thr=0x6190004552c0, new_trx_id_col=1, dup=0x763a41dde940, error=0x763a41dde2b0, offsets_heap=0x621000297d00, heap=0x621000296900, mrec=0x763a41de7081 "", mrec_end=0x763a41de7098 "", offsets=0x6030001933c0)

    at /data/Server/10.8H/storage/innobase/row/row0log.cc:2393

#6  0x000055579b626ff6 in row_log_table_apply_ops (thr=0x6190004552c0, dup=0x763a41dde940, stage=0x60200001e030) at /data/Server/10.8H/storage/innobase/row/row0log.cc:2763

#7  0x000055579b627dc7 in row_log_table_apply (thr=0x6190004552c0, old_table=0x618000090908, table=0x763a41de0160, stage=0x60200001e030, new_table=0x618000091508) at /data/Server/10.8H/storage/innobase/row/row0log.cc:2871

#8  0x000055579b30f562 in ha_innobase::inplace_alter_table (this=0x61d0007ec2b8, altered_table=0x763a41de0160, ha_alter_info=0x763a41ddfa60) at /data/Server/10.8H/storage/innobase/handler/handler0alter.cc:8682

#9  0x000055579a47fc34 in handler::ha_inplace_alter_table (this=0x61d0007ec2b8, altered_table=0x763a41de0160, ha_alter_info=0x763a41ddfa60) at /data/Server/10.8H/sql/handler.h:4601

#10 0x000055579a45ca1c in mysql_inplace_alter_table (thd=0x62b0001dc218, table_list=0x629000dd93b0, table=0x619000442598, altered_table=0x763a41de0160, ha_alter_info=0x763a41ddfa60, target_mdl_request=0x763a41ddfb60, ddl_log_state=0x763a41ddf880, 

    trigger_param=0x763a41de05a0, alter_ctx=0x763a41de1000, partial_alter=@0x763a41ddf5f0: false, start_alter_id=@0x763a41ddf620: 0, if_exists=false) at /data/Server/10.8H/sql/sql_table.cc:7682

#11 0x000055579a47262c in mysql_alter_table (thd=0x62b0001dc218, new_db=0x62b0001e0cf0, new_name=0x62b0001e1110, create_info=0x763a41de24a0, table_list=0x629000dd93b0, alter_info=0x763a41de2370, order_num=0, order=0x0, ignore=false, if_exists=false)

    at /data/Server/10.8H/sql/sql_table.cc:10777

#12 0x000055579a5fdae8 in Sql_cmd_alter_table::execute (this=0x629000dd9bd8, thd=0x62b0001dc218) at /data/Server/10.8H/sql/sql_alter.cc:557

#13 0x000055579a1cc432 in mysql_execute_command (thd=0x62b0001dc218, is_called_from_prepared_stmt=false) at /data/Server/10.8H/sql/sql_parse.cc:5991

#14 0x000055579a1d8496 in mysql_parse (thd=0x62b0001dc218, rawbuf=0x629000dd9238 "ALTER TABLE t1 ADD PRIMARY KEY ( col_varchar ) /* E_R Thread1 QNO 5 CON_ID 18 */", length=80, parser_state=0x763a41de39b0) at /data/Server/10.8H/sql/sql_parse.cc:8016

#15 0x000055579a1b0f3b in dispatch_command (command=COM_QUERY, thd=0x62b0001dc218, packet=0x629000dcf219 " ALTER TABLE t1 ADD PRIMARY KEY ( col_varchar ) /* E_R Thread1 QNO 5 CON_ID 18 */ ", packet_length=82, blocking=true)

    at /data/Server/10.8H/sql/sql_parse.cc:1894

#16 0x000055579a1ae4a8 in do_command (thd=0x62b0001dc218, blocking=true) at /data/Server/10.8H/sql/sql_parse.cc:1407

#17 0x000055579a5e3d93 in do_handle_one_connection (connect=0x608000003db8, put_in_cache=true) at /data/Server/10.8H/sql/sql_connect.cc:1415

#18 0x000055579a5e371b in handle_one_connection (arg=0x608000003db8) at /data/Server/10.8H/sql/sql_connect.cc:1317

#19 0x0000677e02a84609 in start_thread (arg=<optimized out>) at pthread_create.c:477

#20 0x00007f16fd21b293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(rr)

pluto:/data/results/1670524974/TBR-1503$ _RR_TRACE_DIR=./1/rr/ rr replay --mark-stdio

RQG

===

# GIT_SHOW: HEAD -> experimental c0cd00de14dd52daa87b155e44a5e4a6f9e67e4d 2022-09-22T16:32:22+02:00

# rqg.pl  : Version 4.0.6 (2022-09)

#

# $RQG_HOME/rqg.pl \

# --duration=300 \

# --queries=10000000 \

# --no_mask \

# --seed=random \

# --max_gd_duration=1200 \

# --rpl_mode=none \

# --engine=InnoDB \

# --gendata=conf/mariadb/table_stress.zz \

# --gendata_sql=conf/mariadb/table_stress.sql \

# --mysqld=--loose-innodb_read_only_compressed=OFF \

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

# --mysqld=--log_bin_trust_function_creators=1 \

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

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

# --mysqld=--log-output=none \

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

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

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

# --mysqld=--loose-plugin-load-add=provider_lz4.so \

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

# --mysqld=--interactive_timeout=28800 \

# --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \

# --mysqld=--net_read_timeout=30 \

# --mysqld=--wait_timeout=28800 \

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

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

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

# --mysqld=--innodb-buffer-pool-size=5M \

# --mysqld=--connect_timeout=60 \

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

# --mysqld=--innodb_page_size=4K \

# --mysqld=--slave_net_timeout=60 \

# --mysqld=--log-bin \

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

# --mysqld=--net_write_timeout=60 \

# --reporters=Backtrace,Deadlock1 \

# --validators=None \

# --threads=2 \

# --grammar=TBR-1503.yy \

# <local settings>