Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Cannot Reproduce
-
None
Description
...
|
2020-09-10 9:18:44 0 [Note] Recovering after a crash using mysql-bin
|
2020-09-10 9:18:44 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/1599750400/110/1/data/ib_buffer_pool
|
2020-09-10 9:18:45 0 [Note] InnoDB: Buffer pool(s) load completed at 200910 9:18:45
|
2020-09-10 9:18:47 0 [Note] InnoDB: To roll back: 4 transactions, 193 rows
|
2020-09-10 9:18:48 0 [Note] Starting crash recovery...
|
2020-09-10 9:18:48 0 [Note] Crash recovery finished.
|
2020-09-10 9:18:52 0 [Note] InnoDB: Rolled back recovered transaction 102402
|
mysqld: storage/innobase/row/row0uins.cc:532: dberr_t row_undo_ins(undo_node_t*, que_thr_t*): Assertion `node->table->is_temporary() || lock_table_has_locks(node->table)' failed.
|
...
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x0000405d491ac859 in __GI_abort () at abort.c:79
|
#2 0x0000405d491ac729 in __assert_fail_base (fmt=0x405d49342588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x557283fde500 "node->table->is_temporary() || lock_table_has_locks(node->table)",
|
file=0x557283fde920 "storage/innobase/row/row0uins.cc", line=532, function=<optimized out>) at assert.c:92
|
#3 0x0000405d491bdf36 in __GI___assert_fail (assertion=assertion@entry=0x557283fde500 "node->table->is_temporary() || lock_table_has_locks(node->table)",
|
file=file@entry=0x557283fde920 "storage/innobase/row/row0uins.cc", line=line@entry=532, function=function@entry=0x557283fde580 "dberr_t row_undo_ins(undo_node_t*, que_thr_t*)") at assert.c:101
|
#4 0x00005572832d80ea in row_undo_ins (node=node@entry=0x61b000051020, thr=thr@entry=0x6170000311e8) at storage/innobase/include/dict0mem.h:1795
|
#5 0x0000557282cf2b21 in row_undo (node=node@entry=0x61b000051020, thr=thr@entry=0x6170000311e8) at storage/innobase/row/row0undo.cc:433
|
#6 0x0000557282cf7602 in row_undo_step (thr=thr@entry=0x6170000311e8) at /storage/innobase/row/row0undo.cc:494
|
#7 0x0000557282b2b96b in que_thr_step (thr=thr@entry=0x6170000311e8) at storage/innobase/que/que0que.cc:945
|
#8 0x0000557282b2c8dc in que_run_threads_low (thr=thr@entry=0x6170000311e8) at storage/innobase/que/que0que.cc:1009
|
#9 0x0000557282b2d618 in que_run_threads (thr=0x6170000311e8) at storage/innobase/que/que0que.cc:1049
|
#10 0x0000557282e1a38d in trx_rollback_active (trx=trx@entry=0x3002289a20b8) at storage/innobase/trx/trx0roll.cc:628
|
#11 0x0000557282e223d6 in trx_rollback_recovered (all=all@entry=true) at storage/innobase/trx/trx0roll.cc:782
|
#12 0x0000557282e234e1 in trx_rollback_all_recovered () at storage/innobase/trx/trx0roll.cc:836
|
#13 0x00007c755c863609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#14 0x0000405d492a9103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
Workflow
|
========
|
1. Start the server, load some initial data
|
2. Several concurrent sessions run a DDL/DML mix
|
3. At some point of time (2. is ongoing) the server process gets killed with ABRT
|
4. Attempt to restart that server
|
|
MariaDB
|
=======
|
origin/bb-10.5-MDEV-23399 29e8b54c1289f212eb8e820fab584b0769c6c69e 2020-09-10T14:28:45+03:00
|
The server claims to be a 10.5.6-MariaDB-debug-log.
|
|
RQG
|
====
|
git clone https://github.com/mleich1/rqg --branch experimental RQG
|
origin/experimental 26f374c2dbcebdbe72321f3728c564f1c327bba6 2020-09-02T13:10:22+02:00
|
|
perl rqg.pl \
|
--grammar=conf/mariadb/innodb_compression_encryption.yy \
|
--gendata=conf/mariadb/innodb_compression_encryption.zz \
|
--mysqld=--plugin-load-add=file_key_management.so \
|
--mysqld=--loose-file-key-management-filename=/home/mleich/RQG/conf/mariadb/encryption_keys.txt \
|
--mysqld=--innodb-encrypt-log \
|
--mysqld=--innodb-encrypt-tables \
|
--reporters=CrashRecovery1 \
|
--redefine=conf/mariadb/redefine_innodb_undo.yy \
|
--mysqld=--innodb-immediate-scrub-data-uncompressed=1 \
|
--mysqld=--innodb_use_native_aio=1 \
|
--mysqld=--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 \
|
--mysqld=--log_bin_trust_function_creators=1 \
|
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
--engine=InnoDB \
|
--restart_timeout=120 \
|
--duration=300 \
|
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
--mysqld=--loose-innodb-sync-debug \
|
--mysqld=--innodb_stats_persistent=off \
|
--mysqld=--loose-max-statement-time=30 \
|
--threads=33 \
|
--mysqld=--innodb_page_size=4K \
|
--mysqld=--innodb-buffer-pool-size=8M \
|
--duration=300 \
|
--no_mask \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<local settings> \
|
--script_debug=_nix_ \
|
--rr=Server \
|
--rr_options=--chaos
|
|
Innodb compression and encryption are involved but its unknown if
|
they are required for the current defect.
|
The likelihood to replay the current problem is rather low.
|
|
Attachments
Issue Links
- blocks
-
MDEV-23484 Rollback unnecessarily acquires dict_operation_lock for every row
-
- Closed
-
- relates to
-
MDEV-25506 Atomic DDL: .frm file is removed and orphan InnoDB tablespace is left behind upon crash recovery
-
- Closed
-
-
MDEV-27234 InnoDB dictionary recovery wrongly uses READ UNCOMMITTED isolation level instead of READ COMMITTED
-
- Closed
-
Activity
Field | Original Value | New Value |
---|---|---|
Issue Type | Task [ 3 ] | Bug [ 1 ] |
Summary | Draft: Assertion `node->table->is_temporary() || lock_table_has_locks(node->table)' failed in row_undo_ins | Assertion `node->table->is_temporary() || lock_table_has_locks(node->table)' failed in row_undo_ins |
Assignee | Matthias Leich [ mleich ] | Marko Mäkelä [ marko ] |
Link |
This issue is caused by |
Fix Version/s | 10.2 [ 14601 ] | |
Fix Version/s | 10.3 [ 22126 ] | |
Fix Version/s | 10.4 [ 22408 ] | |
Affects Version/s | 10.2.34 [ 24505 ] | |
Affects Version/s | 10.3.25 [ 24506 ] | |
Affects Version/s | 10.4.15 [ 24507 ] | |
Affects Version/s | 10.5.6 [ 24508 ] | |
Labels | rr-profile | rr-profile-analyzed |
Summary | Assertion `node->table->is_temporary() || lock_table_has_locks(node->table)' failed in row_undo_ins | Assertion ‘node->table->is_temporary() || lock_table_has_locks(node->table)’ failed in row_undo_ins |
Status | Open [ 1 ] | Confirmed [ 10101 ] |
Priority | Major [ 3 ] | Blocker [ 1 ] |
Labels | rr-profile-analyzed | need_rr |
Description |
{noformat}
... 2020-09-10 9:18:44 0 [Note] Recovering after a crash using mysql-bin 2020-09-10 9:18:44 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/1599750400/110/1/data/ib_buffer_pool 2020-09-10 9:18:45 0 [Note] InnoDB: Buffer pool(s) load completed at 200910 9:18:45 2020-09-10 9:18:47 0 [Note] InnoDB: To roll back: 4 transactions, 193 rows 2020-09-10 9:18:48 0 [Note] Starting crash recovery... 2020-09-10 9:18:48 0 [Note] Crash recovery finished. 2020-09-10 9:18:52 0 [Note] InnoDB: Rolled back recovered transaction 102402 mysqld: storage/innobase/row/row0uins.cc:532: dberr_t row_undo_ins(undo_node_t*, que_thr_t*): Assertion `node->table->is_temporary() || lock_table_has_locks(node->table)' failed. ... (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x0000405d491ac859 in __GI_abort () at abort.c:79 #2 0x0000405d491ac729 in __assert_fail_base (fmt=0x405d49342588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x557283fde500 "node->table->is_temporary() || lock_table_has_locks(node->table)", file=0x557283fde920 "storage/innobase/row/row0uins.cc", line=532, function=<optimized out>) at assert.c:92 #3 0x0000405d491bdf36 in __GI___assert_fail (assertion=assertion@entry=0x557283fde500 "node->table->is_temporary() || lock_table_has_locks(node->table)", file=file@entry=0x557283fde920 "storage/innobase/row/row0uins.cc", line=line@entry=532, function=function@entry=0x557283fde580 "dberr_t row_undo_ins(undo_node_t*, que_thr_t*)") at assert.c:101 #4 0x00005572832d80ea in row_undo_ins (node=node@entry=0x61b000051020, thr=thr@entry=0x6170000311e8) at storage/innobase/include/dict0mem.h:1795 #5 0x0000557282cf2b21 in row_undo (node=node@entry=0x61b000051020, thr=thr@entry=0x6170000311e8) at storage/innobase/row/row0undo.cc:433 #6 0x0000557282cf7602 in row_undo_step (thr=thr@entry=0x6170000311e8) at /storage/innobase/row/row0undo.cc:494 #7 0x0000557282b2b96b in que_thr_step (thr=thr@entry=0x6170000311e8) at storage/innobase/que/que0que.cc:945 #8 0x0000557282b2c8dc in que_run_threads_low (thr=thr@entry=0x6170000311e8) at storage/innobase/que/que0que.cc:1009 #9 0x0000557282b2d618 in que_run_threads (thr=0x6170000311e8) at storage/innobase/que/que0que.cc:1049 #10 0x0000557282e1a38d in trx_rollback_active (trx=trx@entry=0x3002289a20b8) at storage/innobase/trx/trx0roll.cc:628 #11 0x0000557282e223d6 in trx_rollback_recovered (all=all@entry=true) at storage/innobase/trx/trx0roll.cc:782 #12 0x0000557282e234e1 in trx_rollback_all_recovered () at storage/innobase/trx/trx0roll.cc:836 #13 0x00007c755c863609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #14 0x0000405d492a9103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 (rr) Workflow ======== 1. Start the server, load some initial data 2. Several concurrent sessions run a DDL/DML mix 3. At some point of time (2. is ongoing) the server process gets killed with ABRT 4. Attempt to restart that server MariaDB ======= origin/bb-10.5- The server claims to be a 10.5.6-MariaDB-debug-log. RQG ==== git clone https://github.com/mleich1/rqg --branch experimental RQG origin/experimental 26f374c2dbcebdbe72321f3728c564f1c327bba6 2020-09-02T13:10:22+02:00 perl rqg.pl \ --grammar=conf/mariadb/innodb_compression_encryption.yy \ --gendata=conf/mariadb/innodb_compression_encryption.zz \ --mysqld=--plugin-load-add=file_key_management.so \ --mysqld=--loose-file-key-management-filename=/home/mleich/RQG/conf/mariadb/encryption_keys.txt \ --mysqld=--innodb-encrypt-log \ --mysqld=--innodb-encrypt-tables \ --reporters=CrashRecovery1 \ --redefine=conf/mariadb/redefine_innodb_undo.yy \ --mysqld=--innodb-immediate-scrub-data-uncompressed=1 \ --mysqld=--innodb_use_native_aio=1 \ --mysqld=--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 \ --mysqld=--log_bin_trust_function_creators=1 \ --mysqld=--loose-debug_assert_on_not_freed_memory=0 \ --engine=InnoDB \ --restart_timeout=120 \ --duration=300 \ --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \ --mysqld=--loose-innodb-sync-debug \ --mysqld=--innodb_stats_persistent=off \ --mysqld=--loose-max-statement-time=30 \ --threads=33 \ --mysqld=--innodb_page_size=4K \ --mysqld=--innodb-buffer-pool-size=8M \ --duration=300 \ --no_mask \ --workdir=<local settings> \ --vardir=<local settings> \ --mtr-build-thread=<local settings> \ --basedir1=<local settings> \ --script_debug=_nix_ \ --rr=Server \ --rr_options=--chaos Innodb compression and encryption are involved but its unknown if the are required for the current defect. The likelihood to replay the current problem is rather low. {noformat} |
{noformat}
... 2020-09-10 9:18:44 0 [Note] Recovering after a crash using mysql-bin 2020-09-10 9:18:44 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/vardir/1599750400/110/1/data/ib_buffer_pool 2020-09-10 9:18:45 0 [Note] InnoDB: Buffer pool(s) load completed at 200910 9:18:45 2020-09-10 9:18:47 0 [Note] InnoDB: To roll back: 4 transactions, 193 rows 2020-09-10 9:18:48 0 [Note] Starting crash recovery... 2020-09-10 9:18:48 0 [Note] Crash recovery finished. 2020-09-10 9:18:52 0 [Note] InnoDB: Rolled back recovered transaction 102402 mysqld: storage/innobase/row/row0uins.cc:532: dberr_t row_undo_ins(undo_node_t*, que_thr_t*): Assertion `node->table->is_temporary() || lock_table_has_locks(node->table)' failed. ... (rr) bt #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x0000405d491ac859 in __GI_abort () at abort.c:79 #2 0x0000405d491ac729 in __assert_fail_base (fmt=0x405d49342588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x557283fde500 "node->table->is_temporary() || lock_table_has_locks(node->table)", file=0x557283fde920 "storage/innobase/row/row0uins.cc", line=532, function=<optimized out>) at assert.c:92 #3 0x0000405d491bdf36 in __GI___assert_fail (assertion=assertion@entry=0x557283fde500 "node->table->is_temporary() || lock_table_has_locks(node->table)", file=file@entry=0x557283fde920 "storage/innobase/row/row0uins.cc", line=line@entry=532, function=function@entry=0x557283fde580 "dberr_t row_undo_ins(undo_node_t*, que_thr_t*)") at assert.c:101 #4 0x00005572832d80ea in row_undo_ins (node=node@entry=0x61b000051020, thr=thr@entry=0x6170000311e8) at storage/innobase/include/dict0mem.h:1795 #5 0x0000557282cf2b21 in row_undo (node=node@entry=0x61b000051020, thr=thr@entry=0x6170000311e8) at storage/innobase/row/row0undo.cc:433 #6 0x0000557282cf7602 in row_undo_step (thr=thr@entry=0x6170000311e8) at /storage/innobase/row/row0undo.cc:494 #7 0x0000557282b2b96b in que_thr_step (thr=thr@entry=0x6170000311e8) at storage/innobase/que/que0que.cc:945 #8 0x0000557282b2c8dc in que_run_threads_low (thr=thr@entry=0x6170000311e8) at storage/innobase/que/que0que.cc:1009 #9 0x0000557282b2d618 in que_run_threads (thr=0x6170000311e8) at storage/innobase/que/que0que.cc:1049 #10 0x0000557282e1a38d in trx_rollback_active (trx=trx@entry=0x3002289a20b8) at storage/innobase/trx/trx0roll.cc:628 #11 0x0000557282e223d6 in trx_rollback_recovered (all=all@entry=true) at storage/innobase/trx/trx0roll.cc:782 #12 0x0000557282e234e1 in trx_rollback_all_recovered () at storage/innobase/trx/trx0roll.cc:836 #13 0x00007c755c863609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #14 0x0000405d492a9103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 (rr) Workflow ======== 1. Start the server, load some initial data 2. Several concurrent sessions run a DDL/DML mix 3. At some point of time (2. is ongoing) the server process gets killed with ABRT 4. Attempt to restart that server MariaDB ======= origin/bb-10.5- The server claims to be a 10.5.6-MariaDB-debug-log. RQG ==== git clone https://github.com/mleich1/rqg --branch experimental RQG origin/experimental 26f374c2dbcebdbe72321f3728c564f1c327bba6 2020-09-02T13:10:22+02:00 perl rqg.pl \ --grammar=conf/mariadb/innodb_compression_encryption.yy \ --gendata=conf/mariadb/innodb_compression_encryption.zz \ --mysqld=--plugin-load-add=file_key_management.so \ --mysqld=--loose-file-key-management-filename=/home/mleich/RQG/conf/mariadb/encryption_keys.txt \ --mysqld=--innodb-encrypt-log \ --mysqld=--innodb-encrypt-tables \ --reporters=CrashRecovery1 \ --redefine=conf/mariadb/redefine_innodb_undo.yy \ --mysqld=--innodb-immediate-scrub-data-uncompressed=1 \ --mysqld=--innodb_use_native_aio=1 \ --mysqld=--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 \ --mysqld=--log_bin_trust_function_creators=1 \ --mysqld=--loose-debug_assert_on_not_freed_memory=0 \ --engine=InnoDB \ --restart_timeout=120 \ --duration=300 \ --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \ --mysqld=--loose-innodb-sync-debug \ --mysqld=--innodb_stats_persistent=off \ --mysqld=--loose-max-statement-time=30 \ --threads=33 \ --mysqld=--innodb_page_size=4K \ --mysqld=--innodb-buffer-pool-size=8M \ --duration=300 \ --no_mask \ --workdir=<local settings> \ --vardir=<local settings> \ --mtr-build-thread=<local settings> \ --basedir1=<local settings> \ --script_debug=_nix_ \ --rr=Server \ --rr_options=--chaos Innodb compression and encryption are involved but its unknown if they are required for the current defect. The likelihood to replay the current problem is rather low. {noformat} |
Link |
This issue blocks |
Link |
This issue is caused by |
Fix Version/s | 10.6 [ 24028 ] | |
Fix Version/s | 10.2 [ 14601 ] | |
Fix Version/s | 10.3 [ 22126 ] | |
Fix Version/s | 10.4 [ 22408 ] | |
Fix Version/s | 10.5 [ 23123 ] | |
Affects Version/s | 10.2.34 [ 24505 ] | |
Affects Version/s | 10.3.25 [ 24506 ] | |
Affects Version/s | 10.4.15 [ 24507 ] | |
Affects Version/s | 10.5.6 [ 24508 ] | |
Priority | Blocker [ 1 ] | Major [ 3 ] |
Workflow | MariaDB v3 [ 113443 ] | MariaDB v4 [ 144296 ] |
Link |
This issue relates to |
Link |
This issue relates to |
Assignee | Marko Mäkelä [ marko ] | Thirunarayanan Balathandayuthapani [ thiru ] |
Assignee | Thirunarayanan Balathandayuthapani [ thiru ] | Marko Mäkelä [ marko ] |
Fix Version/s | N/A [ 14700 ] | |
Fix Version/s | 10.6 [ 24028 ] | |
Resolution | Cannot Reproduce [ 5 ] | |
Status | Confirmed [ 10101 ] | Closed [ 6 ] |
I performed an initial analysis of the trace. The problem appears to be that the name of the table does not match the tablespace until the very last call of fil_space_for_table_exists_in_mem(). That is why early calls of fil_ibd_open() returned NULL or !table->is_readable() held (due to !table->space) in trx_resurrect_table_locks(). However, the final call to fil_table_accessible() in row_undo_ins_parse_undo_rec() would hold, and upon rolling back the changes, we would notice that no table lock was resurrected.
It seems to me that
MDEV-23484will require a follow-up fix to make it compatible with the rollback of RENAME operations (which was implemented inMDEV-14717).Because trx_resurrect_table_locks() is evicting the unreadable table, and because the table will be loaded with the correct name in dict_table_open_on_id() by row_undo_ins_parse_undo_rec(), it seems that the SYS_TABLES.NAME must have been corrected by a rollback of a dictionary transaction.
Possibly the fix should be that trx_resurrect_table_locks() should resurrect table locks even if !table->space.
It is unclear yet whether 10.2 is affected by this.
MDEV-12266changed some related code in 10.3.