[MDEV-27747] Assertion `log->blobs' failed in row_log_table_apply_update upon ALTER TABLE Created: 2022-02-04  Updated: 2022-08-02  Resolved: 2022-08-02

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.8.1
Fix Version/s: 10.6.8, 10.7.4, 10.8.3, 10.9.1

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: rr-profile

Issue Links:
Blocks
is blocked by MDEV-15250 UPSERT during ALTER-TABLE results in ... Closed

 Description   

origin/bb-10.8-MDEV-27716 81ab5d74e5f2bdbb5b7f495c74113a9bbb63376f 2022-02-04T11:02:12+02:00
This is some development tree but the same assert was also observed on
10.6 (2021-03), 10.7 development tree (2022-01).
Hence I assume that the problem is not specific to development trees.
 
# 2022-02-04T13:16:40 [19671] | [rr 23155 384553]mysqld: /data/Server/bb-10.8-MDEV-27716A/storage/innobase/row/row0log.cc:2243: 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 `log->blobs' failed.
query: "ALTER TABLE t3 ADD INDEX `idx1` ( col_varchar(9) ASC ), ADD PRIMARY KEY ( col_string(9) DESC )  /* E_R Thread1 QNO 307 CON_ID 45 */
 
# 2022-02-04T13:16:40 [19671] | [rr 23155 384573]220204 13:12:22 [rr 23155 384576][ERROR] mysqld got signal 6 ;
 
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000059a269db2859 in __GI_abort () at abort.c:79
#2  0x000059a269db2729 in __assert_fail_base (fmt=0x59a269f48588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5597c5756880 "log->blobs", 
    file=0x5597c5753ec0 "/data/Server/bb-10.8-MDEV-27716A/storage/innobase/row/row0log.cc", line=2243, function=<optimized out>) at assert.c:92
#3  0x000059a269dc3f36 in __GI___assert_fail (assertion=0x5597c5756880 "log->blobs", file=0x5597c5753ec0 "/data/Server/bb-10.8-MDEV-27716A/storage/innobase/row/row0log.cc", line=2243, 
    function=0x5597c5757060 "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  0x00005597c4508276 in row_log_table_apply_update (thr=0x619000351cc0, new_trx_id_col=1, mrec=0x5be45b40901b "", offsets=0x60400001ff10, offsets_heap=0x625002a55900, heap=0x625002a58100, dup=0x7b9c7bebf8e0, 
    old_pk=0x625002a58188) at /data/Server/bb-10.8-MDEV-27716A/storage/innobase/row/row0log.cc:2243
#5  0x00005597c450bc07 in row_log_table_apply_op (thr=0x619000351cc0, new_trx_id_col=1, dup=0x7b9c7bebf8e0, error=0x7b9c7bebf250, offsets_heap=0x625002a55900, heap=0x625002a58100, mrec=0x5be45b40901b "", 
    mrec_end=0x5be45b409758 "", offsets=0x60400001ff10) at /data/Server/bb-10.8-MDEV-27716A/storage/innobase/row/row0log.cc:2692
#6  0x00005597c450ffc8 in row_log_table_apply_ops (thr=0x619000351cc0, dup=0x7b9c7bebf8e0, stage=0x6020001b0f50) at /data/Server/bb-10.8-MDEV-27716A/storage/innobase/row/row0log.cc:3066
#7  0x00005597c4510d99 in row_log_table_apply (thr=0x619000351cc0, old_table=0x61800010c508, table=0x7b9c7bec1340, stage=0x6020001b0f50, new_table=0x61800013b108)
    at /data/Server/bb-10.8-MDEV-27716A/storage/innobase/row/row0log.cc:3174
#8  0x00005597c4212377 in alter_rebuild_apply_log (ctx=0x629000df9ff0, ha_alter_info=0x7b9c7bec0c40, altered_table=0x7b9c7bec1340) at /data/Server/bb-10.8-MDEV-27716A/storage/innobase/handler/handler0alter.cc:10753
#9  0x00005597c4214995 in ha_innobase::commit_inplace_alter_table (this=0x61d000fd8eb8, altered_table=0x7b9c7bec1340, ha_alter_info=0x7b9c7bec0c40, commit=true)
    at /data/Server/bb-10.8-MDEV-27716A/storage/innobase/handler/handler0alter.cc:10981
#10 0x00005597c38cd566 in handler::ha_commit_inplace_alter_table (this=0x61d000fd8eb8, altered_table=0x7b9c7bec1340, ha_alter_info=0x7b9c7bec0c40, commit=true) at /data/Server/bb-10.8-MDEV-27716A/sql/handler.cc:5197
#11 0x00005597c332fd9c in mysql_inplace_alter_table (thd=0x62b0001ea218, table_list=0x629000df7418, table=0x6190010b8598, altered_table=0x7b9c7bec1340, ha_alter_info=0x7b9c7bec0c40, target_mdl_request=0x7b9c7bec0d40, 
    ddl_log_state=0x7b9c7bec0a60, trigger_param=0x7b9c7bec1760, alter_ctx=0x7b9c7bec21a0, partial_alter=@0x7b9c7bec07d0: false, start_alter_id=@0x7b9c7bec0800: 0, if_exists=false)
    at /data/Server/bb-10.8-MDEV-27716A/sql/sql_table.cc:7735
#12 0x00005597c3344b59 in mysql_alter_table (thd=0x62b0001ea218, new_db=0x62b0001eecc0, new_name=0x62b0001ef0d8, create_info=0x7b9c7bec3650, table_list=0x629000df7418, alter_info=0x7b9c7bec3520, order_num=0, order=0x0, 
    ignore=false, if_exists=false) at /data/Server/bb-10.8-MDEV-27716A/sql/sql_table.cc:10691
#13 0x00005597c34d2604 in Sql_cmd_alter_table::execute (this=0x629000df7d68, thd=0x62b0001ea218) at /data/Server/bb-10.8-MDEV-27716A/sql/sql_alter.cc:547
#14 0x00005597c309ce6f in mysql_execute_command (thd=0x62b0001ea218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.8-MDEV-27716A/sql/sql_parse.cc:5988
#15 0x00005597c30a92ad in mysql_parse (thd=0x62b0001ea218, rawbuf=0x629000df7238 "ALTER TABLE t3 ADD INDEX `idx1` ( col_varchar(9) ASC ), ADD PRIMARY KEY ( col_string(9) DESC )  /* E_R Thread1 QNO 307 CON_ID 45 */", 
    length=131, parser_state=0x7b9c7bec4b20) at /data/Server/bb-10.8-MDEV-27716A/sql/sql_parse.cc:8027
#16 0x00005597c3081692 in dispatch_command (command=COM_QUERY, thd=0x62b0001ea218, 
    packet=0x629000082219 "\nALTER TABLE t3 ADD INDEX `idx1` ( col_varchar(9) ASC ), ADD PRIMARY KEY ( col_string(9) DESC )  /* E_R Thread1 QNO 307 CON_ID 45 */ ", packet_length=133, blocking=true)
    at /data/Server/bb-10.8-MDEV-27716A/sql/sql_parse.cc:1894
#17 0x00005597c307ea6a in do_command (thd=0x62b0001ea218, blocking=true) at /data/Server/bb-10.8-MDEV-27716A/sql/sql_parse.cc:1402
#18 0x00005597c34b8380 in do_handle_one_connection (connect=0x608000003bb8, put_in_cache=true) at /data/Server/bb-10.8-MDEV-27716A/sql/sql_connect.cc:1418
#19 0x00005597c34b7c0c in handle_one_connection (arg=0x608000002eb8) at /data/Server/bb-10.8-MDEV-27716A/sql/sql_connect.cc:1312
#20 0x0000115f208c6609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#21 0x000059a269eaf293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr) 
 
pluto:/data/results/1643977579/TBR-34/dev/shm/rqg/1643977579/10/1/rr
 
RQG
====
# git clone https://github.com/mleich1/rqg --branch experimental RQG
#
# GIT_SHOW: HEAD -> experimental, origin/experimental 45931a885baf847433851c7cec7acda28e28298b 2022-02-04T11:40:52+01:00
# rqg.pl  : Version 4.0.4 (2021-12)
#
# $RQG_HOME/rqg.pl \
# --grammar=conf/mariadb/table_stress_innodb_dml.yy \
# --gendata=conf/mariadb/table_stress.zz \
# --gendata_sql=conf/mariadb/table_stress.sql \
# --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 \
# --mysqld=--plugin-load-add=provider_lzo.so \
# --mysqld=--plugin-load-add=provider_bzip2.so \
# --mysqld=--plugin-load-add=provider_lzma \
# --mysqld=--plugin-load-add=provider_snappy \
# --mysqld=--plugin-load-add=provider_lz4 \
# --duration=300 \
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
# --mysqld=--loose-innodb_read_only_compressed=OFF \
# --mysqld=--innodb_stats_persistent=on \
# --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=0 \
# --mysqld=--loose-gdb \
# --mysqld=--loose-debug-gdb \
# --rr=Extended \
# --rr_options=--chaos --wait \
# --mysqld=--innodb_rollback_on_timeout=OFF \
# --vardir_type=fast \
# --mysqld=--innodb_page_size=8K \
# --mysqld=--innodb-buffer-pool-size=8M \
# --no_mask \
# <local settings>



 Comments   
Comment by Marko Mäkelä [ 2022-08-02 ]

The row_log_t::blobs was removed in MDEV-15250 and the logic simplified a lot. There is no need to track BLOB ownership anymore, because only committed rows will be written to any dict_index_t::online_log. Rollback or purge will no longer write any log.

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