Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.9.8, 10.10.6, 10.11.5, 11.1.2, 11.2.1
Description
origin/11.2 b793feb1d68c181f1073a15241b4e9833f84745b 2024-05-22T16:54:33+03:00
Scenario(explicite XA commands or replication are not involved):
1. Start the DB server, generate some initial data
2. 33 sessions run some DML mix concurrent
3. During 2. is ongoing send SIGKILL to the DB server
4. Restart Attempt
In some run 4. failed with
2024-05-23 16:15:01 0x55dc267d0900[rr 3503169 59438] InnoDB: Assertion failure in file /data/Server/11.2/storage/innobase/row/row0umod.cc line 902
|
InnoDB: Failing assertion: entry
|
|
|
(rr) bt
|
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=94404026894592) at ./nptl/pthread_kill.c:44
|
#1 __pthread_kill_internal (signo=6, threadid=94404026894592) at ./nptl/pthread_kill.c:78
|
#2 __GI___pthread_kill (threadid=94404026894592, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
|
#3 0x000055dc2681a476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
|
#4 0x000055dc268007f3 in __GI_abort () at ./stdlib/abort.c:79
|
#5 0x000055dc27bff83f in ut_dbg_assertion_failed (expr=expr@entry=0x55dc281f8a70 "entry", file=file@entry=0x55dc282c5b10 "/data/Server/11.2/storage/innobase/row/row0umod.cc", line=line@entry=902)
|
at /data/Server/11.2/storage/innobase/ut/ut0dbg.cc:60
|
#6 0x000055dc27b7e51d in row_undo_mod_del_mark_sec (node=node@entry=0x55dc29f399a0, thr=thr@entry=0x55dc29e848c0) at /data/Server/11.2/storage/innobase/row/row0umod.cc:902
|
#7 0x000055dc27b802ca in row_undo_mod (node=node@entry=0x55dc29f399a0, thr=thr@entry=0x55dc29e848c0) at /data/Server/11.2/storage/innobase/row/row0umod.cc:1211
|
#8 0x000055dc27b82354 in row_undo (node=node@entry=0x55dc29f399a0, thr=thr@entry=0x55dc29e848c0) at /data/Server/11.2/storage/innobase/row/row0undo.cc:399
|
#9 0x000055dc27b83531 in row_undo_step (thr=thr@entry=0x55dc29e848c0) at /data/Server/11.2/storage/innobase/row/row0undo.cc:440
|
#10 0x000055dc27ab035e in que_thr_step (thr=thr@entry=0x55dc29e848c0) at /data/Server/11.2/storage/innobase/que/que0que.cc:586
|
#11 0x000055dc27ab0628 in que_run_threads_low (thr=thr@entry=0x55dc29e848c0) at /data/Server/11.2/storage/innobase/que/que0que.cc:644
|
#12 0x000055dc27ab06ef in que_run_threads (thr=0x55dc29e848c0) at /data/Server/11.2/storage/innobase/que/que0que.cc:664
|
#13 0x000055dc27bd7ba9 in trx_t::rollback_low (this=this@entry=0x2fd46f34ca80, savept=savept@entry=0x0) at /data/Server/11.2/storage/innobase/trx/trx0roll.cc:124
|
#14 0x000055dc27bd4b53 in trx_rollback_for_mysql_low (trx=trx@entry=0x2fd46f34ca80) at /data/Server/11.2/storage/innobase/trx/trx0roll.cc:198
|
#15 0x000055dc27bd4fd0 in trx_rollback_for_mysql (trx=trx@entry=0x2fd46f34ca80) at /data/Server/11.2/storage/innobase/trx/trx0roll.cc:271
|
#16 0x000055dc27949607 in innobase_rollback_trx (trx=trx@entry=0x2fd46f34ca80) at /data/Server/11.2/storage/innobase/handler/ha_innodb.cc:4638
|
#17 0x000055dc27949964 in innobase_rollback_by_xid (hton=<optimized out>, xid=0x7ffc4b022130) at /data/Server/11.2/storage/innobase/handler/ha_innodb.cc:17159
|
#18 0x000055dc2760b697 in xarecover_do_commit_or_rollback (hton=0x55dc29ea6c88, arg=arg@entry=0x7ffc4b022330) at /data/Server/11.2/sql/handler.cc:2649
|
#19 0x000055dc2760b78d in xarecover_do_commit_or_rollback_handlerton (unused=unused@entry=0x0, plugin=<optimized out>, arg=arg@entry=0x7ffc4b022330) at /data/Server/11.2/sql/handler.cc:2682
|
#20 0x000055dc272ee9bf in plugin_foreach_with_mask (thd=thd@entry=0x0, func=func@entry=0x55dc2760b76f <xarecover_do_commit_or_rollback_handlerton(THD*, plugin_ref, void*)>, type=type@entry=1, state_mask=state_mask@entry=8,
|
arg=arg@entry=0x7ffc4b022330) at /data/Server/11.2/sql/sql_plugin.cc:2560
|
#21 0x000055dc2760a12a in xarecover_complete_and_count (member_arg=0x55dc29e7f930, param_arg=0x7ffc4b022330) at /data/Server/11.2/sql/handler.cc:2702
|
#22 0x000055dc27df3c3f in my_hash_iterate (hash=0x7ffc4b022410, action=0x55dc2760a0f9 <xarecover_complete_and_count(void*, void*)>, argument=0x7ffc4b022330) at /data/Server/11.2/mysys/hash.c:809
|
#23 0x000055dc27610ada in ha_recover_complete (commit_list=<optimized out>, coord=<optimized out>) at /data/Server/11.2/sql/handler.cc:2724
|
#24 0x000055dc277a8368 in Recovery_context::complete (this=this@entry=0x7ffc4b022880, log=log@entry=0x55dc28b6fa80 <mysql_bin_log>, xids=...) at /data/Server/11.2/sql/log.cc:11032
|
#25 0x000055dc277a9cd5 in MYSQL_BIN_LOG::recover (this=this@entry=0x55dc28b6fa80 <mysql_bin_log>, linfo=linfo@entry=0x7ffc4b023290, last_log_name=last_log_name@entry=0x7ffc4b022e90 "./mysql-bin.000001",
|
first_log=first_log@entry=0x7ffc4b023090, fdle=fdle@entry=0x55dc2a1cf2e8, do_xa=do_xa@entry=true) at /data/Server/11.2/sql/log.cc:11626
|
#26 0x000055dc277aa06f in MYSQL_BIN_LOG::do_binlog_recovery (this=this@entry=0x55dc28b6fa80 <mysql_bin_log>, opt_name=opt_name@entry=0x55dc29e0ad78 "mysql-bin", do_xa_recovery=do_xa_recovery@entry=true)
|
at /data/Server/11.2/sql/log.cc:11723
|
#27 0x000055dc277aded6 in MYSQL_BIN_LOG::open (this=0x55dc28b6fa80 <mysql_bin_log>, opt_name=0x55dc29e0ad78 "mysql-bin") at /data/Server/11.2/sql/log.cc:10390
|
#28 0x000055dc2718888a in init_server_components () at /data/Server/11.2/sql/mysqld.cc:5560
|
#29 0x000055dc2718cdb4 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /data/Server/11.2/sql/mysqld.cc:5936
|
#30 0x000055dc2717fd76 in main (argc=<optimized out>, argv=<optimized out>) at /data/Server/11.2/sql/main.cc:34
|
(rr)
|
|
|
cd pluto:/data/results/1716473106/CR-2134
|
_RR_TRACE_DIR=./1/rr rr replay --mark-stdio mariadbd-1 # Fate of server till SIGKILL
|
./1/fbackup # File backup made after SIGKILL and before restart
|
_RR_TRACE_DIR=./1/rr rr replay --mark-stdio # Restart attempt
|
|
|
RQG
|
===
|
# git clone https://github.com/mleich1/rqg RQG
|
#
|
# GIT_SHOW: HEAD -> master, origin/master, origin/HEAD a744f7f7753f7ecfe17ee4943673dd54723a2262 2024-05-23T14:53:07+02:00
|
# rqg.pl : Version 4.5.0 (2023-12)
|
#
|
# $RQG_HOME/rqg.pl \
|
# --gendata=conf/mariadb/table_stress.zz \
|
# --gendata_sql=conf/mariadb/table_stress.sql \
|
# --grammar=conf/mariadb/table_stress_innodb_dml.yy \
|
# --reporters=CrashRecovery \
|
# --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 \
|
# --no_mask \
|
# --queries=10000000 \
|
# --seed=random \
|
# --reporters=None \
|
# --reporters=ErrorLog \
|
# --reporters=Deadlock \
|
# --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.so \
|
# --mysqld=--plugin-load-add=provider_snappy.so \
|
# --mysqld=--plugin-load-add=provider_lz4.so \
|
# --mysqld=--loose-innodb_compression_level=1 \
|
# --duration=300 \
|
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
# --mysqld=--lock-wait-timeout=15 \
|
# --mysqld=--innodb-lock-wait-timeout=10 \
|
# --mysqld=--loose-innodb_fast_shutdown=1 \
|
# --mysqld=--sql_mode=traditional \
|
# --mysqld=--loose-innodb_read_only_compressed=OFF \
|
# --mysqld=--innodb_stats_persistent=off \
|
# --mysqld=--innodb_adaptive_hash_index=on \
|
# --mysqld=--innodb_random_read_ahead=OFF \
|
# --mysqld=--log-bin \
|
# --mysqld=--sync-binlog=1 \
|
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
|
# --threads=33 \
|
# --rr=Extended \
|
# --rr_options=--chaos --wait \
|
# --mysqld=--innodb_undo_log_truncate=OFF \
|
# --mysqld=--loose_innodb_change_buffering=all \
|
# --mysqld=--innodb_rollback_on_timeout=OFF \
|
# --mysqld=--innodb_page_size=64K \
|
# --mysqld=--innodb-buffer-pool-size=24M \
|
# <local settings>
|
Attachments
Issue Links
- duplicates
-
-
- Closed
-
- is caused by
-
-
- Closed
-
Activity
I could analyzed the issue from the RR trace.
1. The assert is hit while trying to rollback an uncommitted transaction post redo log recovery. We fail to get the LOB pages for the old record.
|
2. The LOB page in question is found to be zero filled pages.
|
3. Going back to the redo recovery stage, we see it is a multi phase recovery as the buffer pool (24M) is not enough to hold the hash table for applying the redo log changes.
|
4. The specific LOB page in question (space=17, page=7) is found to be removed form the page hash by recv_sys_t::garbage_collect() [We find being_processed < 0]
|
5. being_processed = -1 was set by recv_sys_t::apply_batch() as the page was found in space->freed_ranges.
|
6. The page is put in space->freed_ranges by recv_init_crash_recovery_spaces() before applying the redo logs. The information is read from freed_ranges in recv_spaces only for compressed row format table table or if immediate_scrub_data_uncompressed is ON. The table in question (t6) has compressed row format.
|
7. Interestingly, when garbage_collect() was freeing the page, the page was already removed from the freed_ranges within recv_spaces. It clearly indicates that there were some valid redo log data for the page that got ignored and we must have missed removing the page from freed ranges in earlier scan before doing recv_init_crash_recovery_spaces().
|
8. Checking the previous scan and all the redo logs being checked for the specific page the root cause was found. The skip adding/removing free pages if store=F i.e. when we cannot store the records for apply but need to parse through the redo logs for collecting some information. It is certainly incorrect to skip this call as it would result in incomplete information about the page in recv_spaces which in turn could get in space->freed_ranges indicating the page is free and thereby skip applying redo logs and keeping the page FREE / zero filled.
|
recv_sys_t::parse()
|
...
|
free_or_init_page:
|
if (store)
|
store_freed_or_init_rec(id, (b & 0x70) == FREE_PAGE);
|
9. Created a test and repeated the issue with some debug tweaks on the commit ID of the RR trace.
10. The issue didn't occur on latest 11.2. Turns out the "if condition" shown above is already removed and the problem is fixed in latest versions.
Introduced By:
commit 941af1fa581a799e59ddc3afcae965852aeceb00
|
Author: Thirunarayanan Balathandayuthapani <thiru@mariadb.com>
|
Date: Mon Jul 31 16:42:23 2023 +0530
|
MDEV-31803 InnoDB aborts during recovery when immediate_scrub_data_uncompressed is enabled
|
|
|
10.9.8, 10.10.6, 10.11.5, 11.1.2, 11.2.1
|
Fixed By:
commit 5b39ded713d021e7ec76f8f550b43678821eae22
|
Author: Thirunarayanan Balathandayuthapani <thiru@mariadb.com>
|
Date: Tue Jun 11 12:50:26 2024 +0530
|
MDEV-34156 InnoDB fails to apply the redo log for compressed tablespace
|
|
|
10.11.9, 11.1.6, 11.2.5, 11.4.3
|
ssh plutorr replay /data/results/1716473106/CR-2134/1/rr/mariadbd-2I see that there are descending columns both in the primary key and in the secondary index. I did not have time to analyze the root cause yet. The assertion appears to fail before there is an attempt to look up the record in the secondary index.