|
prt == Protocol of my MTR replay test when running against 10.4 compiled with debug
|
MDEV-20066.tgz == Archive with MTR based replay test case
|
|
How to replay the problem:
|
|
0. Use a Linux
|
1. cd <source>/mysql-test
|
2. tar xvzf MDEV-20066.tgz
|
This unpacks a
|
mysqltest_background.sh
|
main/ml_MDEV-20066.test
|
3. cd <tree_with_binaries compiled with debug>/mysql-test
|
4. ./mysql-test-run.pl --mem ml_MDEV-20066
|
|
Please do not add my replay test case to the regression tests because
|
it consumes too much resources.
|
|
A perfect regression test should use debug_sync or similar.
|
|
|
|
I can repeat this. For me, the error is reported on UNIQUE INDEX uidx(col_text(9)), and there exists PRIMARY KEY(col1) as well. The fields in the clustered index are (col1,DB_TRX_ID,DB_ROLL_PTR,col2,dropped,…dropped,col_text,col_text_copy) (with 11 instantly dropped columns). Originally there were 5 fields in the clustered index: (col1,DB_TRX_ID,DB_ROLL_PTR,col2,dropped_col_text), where dropped_col_text is a dropped column that was originally called col_text (not the same as the instantly added col_text near the end of the latest field list).
The non-delete-marked record, on top of which we are about to insert, is (col_text(9),col1)=(NULL,7). On the rightmost leaf page of the clustered index, we have a non-delete-marked record (col1,DB_TRX_ID,DB_ROLL_PTR,col2,dropped_col_text)=(7,0x481,update,6,concat(repeat('7',768),blob_pointer,NULL)). This record was updated by the current transaction, because we have thr->graph->trx->id=0x481. Two undo log records were written by the transaction. The statement is updating the PRIMARY KEY, hence it is writing two undo log records per modified row. It is on its very first updated row:
UPDATE t3 SET col1 = 7 LIMIT 2 ;
|
I will try to determine the original value of col1 from the undo log page, so that I can analyze this further. Side note: this is somewhat similar with MDEV-20038, in that something fails in an update on a unique secondary index.
|
|
I found the undo log page:
(gdb) p *thr.graph.trx.rsegs.m_redo.undo
|
$22 = {id = 0, state = 1, trx_id = 1153, xid = {formatID = -1,
|
gtrid_length = 0, bqual_length = 0, data = '\000' <repeats 127 times>},
|
dict_operation = 0, table_id = 257, rseg = 0x55955516c610,
|
hdr_page_no = 369, hdr_offset = 656, last_page_no = 369, size = 1,
|
top_page_no = 369, top_offset = 882, top_undo_no = 1,
|
guess_block = 0x7f3754e097e8, withdraw_clock = 0, undo_list = {prev = 0x0,
|
next = 0x0}}
|
(gdb) p *thr.graph.trx.rsegs.m_redo.rseg.space.id
|
Cannot access memory at address 0x0
|
(gdb) find_page_in_pool buf_pool_ptr 0 369
|
$23 = (buf_block_t *) 0x7f3754e097e8
|
(gdb) dump binary memory /dev/shm/u.bin $23.frame $23.frame+srv_page_size
|
We seem to have a singleton doubly-linked list of undo log records at byte offset 644, ending at offset 656, with the record TRX_UNDO_INSERT_REC for inserting the value 7, by this transaction (‽). But, the undo log should have started with a record to delete-mark the record that had the old value of col1. Also, TRX_UNDO_PAGE_START is pointing to a different linked list of undo log records, at offsets 842,882, ending at 1716. So, let me ignore that record and investigate the other list instead.
In the 2-element list, also mentioning our thr->graph->trx->id and carrying the trx->undo_no of 0 and 1, as expected, we have TRX_UNDO_DEL_MARK_REC for delete-marking (DB_TRX_ID,DB_ROLL_PTR,col1)=(0,1<<56,4) followed by TRX_UNDO_UPD_DEL_REC for updating a delete-marked record (DB_TRX_ID,DB_ROLL_PTR,col1,…)=(0x486,0x040000013807f5,7,…). So, apparently transaction 0x486 had delete-marked that record before our transaction 0x481 is reinserting it. For some reason, transaction 0x486 apparently failed to delete-mark the record in the secondary index before committing.
In the secondary index page, we do have a delete-marked record (NULL,4) followed by non-delete-marked (NULL,6),(NULL,7), and finally a delete-marked (repeat('7',9),7). The PAGE_MAX_TRX_ID is 0x486, so the page was apparently touched by the previously committed record. Maybe the offending record (NULL,7) was not left by it, but some even earlier transaction?
In the preceding clustered index page, we have the delete-marked record (col1,DB_TRX_ID,DB_ROLL_PTR,col2,deleted_col_text,…)=(4,0x481,0x7f00000171034a,6,concat(repeat('7',768),blob_pointer),…). All the remaining fields that are stored are similar BLOBs. This record was what our crashing transaction delete-marked for updating the PRIMARY KEY(col1) from 4 to 7. This record is followed by a non-delete-marked (col1,DB_TRX_ID,DB_ROLL_PTR,col2,…)=(6,0,1<<55,6,…) which in turn is followed by the first record on the rightmost leaf page of the clustered index (with col1=7, which was analyzed in my previous comment.
I will try to gather more information from further runs by adding diagnostic output. I believe that the corruption must have been introduced earlier. Furthermore, I believe that innodb_force_recovery=2 (disabling the purge of history) could improve the chances of repeating or nailing down this bug. I can repeat the bug with that setting.
|
|
I can also repeat with ROW_FORMAT=DYNAMIC, in 10 seconds with innodb_force_recovery=2. I repeated in 74 seconds after removing col2 from the table. After I reduced fill_amount to 50, it repeated in 68 seconds (86 seconds with innodb_force_recovery=2). I reduced fill_amount further to 10, which should prevent the use of any BLOBs, and with innodb_force_recovery=2 repeated it again in 10 seconds.
There is some redundancy in MDEV-20066.tgz because col1=8 never occurs, and col1 IS NULL cannot hold, because the column is implicitly NOT NULL because of being part of the PRIMARY KEY.
After I replaced TEXT with VARCHAR(3), reduced the strings to '777', and declared UNIQUE INDEX uidx3(col_text) on the full column, the test passed. With the VARCHAR(3) but with UNIQUE INDEX uidx3(col_text(1)) the test passes as well. With UNIQUE INDEX uidx3(col_text(1)) and TEXT containing NULL or '777', the test crashed again, in 10 seconds. If I shorten the '777' to '7' or '77', the test passes.
Because InnoDB treats TEXT and VARCHAR pretty much in the same way, I suspect that this bug depends on something happening in the SQL layer.
I will try to reduce the test further.
|
|
The test does crash even when the TEXT type is replaced with VARCHAR(3) containing '777' or NULL (and using a full-column UNIQUE INDEX uidx3(col_text), but the crash frequency often appears to be insufficient for the 140-second run time of the test.
With CHAR(1) and '7', I was unable to repeat the crash, but it might be explained by the too low frequency. CHAR(3) and '777' repeated the bug on the second try, using innodb_page_size=4k.
I will next try if I can repeat the bug with an integer column. After that, I will try NOT NULL and non-UNIQUE index. I think that the test may rely on UNIQUE indexes accepting ‘duplicate’ NULL values.
|
|
I am able to repeat the bug with INT (values NULL and 77), in 38 seconds.
Also INT NOT NULL DEFAULT 0 and non-UNIQUE repeated it on the second try, in 140+10 seconds.
Finally, TINYINT UNSIGNED NOT NULL DEFAULT 0 failed to fail in 140*3 seconds, but I also did not see a failure for CHAR(1) or VARCHAR(1).
|
|
ml_MDEV-20066.test is my current simplified test, replacing the one in MDEV-20066.tgz. Strangely, the dummy connection with
DELETE FROM t3 WHERE col1 = 8; COMMIT;
|
seems to be necessary, even though it should never find any matching rows. In a crash with it, both the clustered index and the secondary index comprise one 4KiB page, with only 3 records each.
./mtr --mysqld=--innodb-page-size=4k --mysqld=--innodb-force-recovery=2 main.ml_MDEV-20066
|
The secondary index contains the following records (col_text,col1):
delete-marked(0,4), (0,6), (0,7), delete-marked(77,7).
The clustered index contains the following records (col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,drop2,drop3,drop4,drop5,col_text,col_text_copy):
(metadata record by DB_TRX_ID=0x173), delete-marked(4,0x175,0xa40110,0,0,77), (6,0x9a,0x9d02da,0,0,77), (7, 0x175, 0xa40138,0,0,0,0,0,77).
The current transaction is 0x175, with undo_no=2, executing UPDATE t3 SET col1 = 7 LIMIT 2, so it looks like it delete-marked the record col1=4 and should have inserted the corresponding record col1=7.
But why does the number of index fields differ between the delete-marked record col1=4 and the inserted record col1=7? And why was the record col1=7 updated, not inserted? The transaction is occupying undo log page 164:
(gdb) p *thr.graph.trx.rsegs.m_redo.undo
|
$11 = {id = 0, state = 1, trx_id = 373, xid = {formatID = -1,
|
gtrid_length = 0, bqual_length = 0, data = '\000' <repeats 127 times>},
|
dict_operation = 0, table_id = 0, rseg = 0x56117ece66f0, hdr_page_no = 164,
|
hdr_offset = 86, last_page_no = 164, size = 1, top_page_no = 164,
|
top_offset = 312, top_undo_no = 1, guess_block = 0x7faa12a37558,
|
withdraw_clock = 0, undo_list = {prev = 0x0, next = 0x0}}
|
That page contains the following two records by our transaction 0x175:
- TRX_UNDO_DEL_MARK_REC updating col1=4 that had been delete-marked by DB_TRX_ID=0x90
- TRX_UNDO_UPD_DEL_REC updating col1=7 that had been delete-marked by DB_TRX_ID=0x17d
Note: like in the previously analyzed case, the record col1=7 was previously delete-marked by a already committed transaction that had started earlier than our current transaction.
Based on the transaction IDs, columns must have been instantly added and dropped since the record col1=4 was originally delete-marked. The transaction that delete-marked the record col1=7 was started after the most recent instant ALTER TABLE was committed.
The bug could simply be that when we are inserting a record by updating a committed delete-marked record, we should make sure that the number of fields will match those of the record that we are inserting. This hypothesis should be verified rather easily by adding diagnostics to row_ins_clust_index_entry_by_modify().
|
|
I think that the following test could be close to the failing scenario, but unfortunately it does not fail:
--source include/have_innodb.inc
|
CREATE TABLE t1(a INT PRIMARY KEY, b INT NOT NULL) ENGINE=InnoDB;
|
INSERT INTO t1 (a,b) VALUES (4,0),(6,0),(7,0);
|
ALTER TABLE t1 ADD INDEX (b);
|
ALTER TABLE t1 DROP COLUMN b, ADD COLUMN (c INT NOT NULL DEFAULT 0, d INT NOT NULL DEFAULT 0);
|
UPDATE t1 SET c=77;
|
DELETE FROM t1 WHERE a=7;
|
ALTER TABLE t1 DROP COLUMN d, ADD COLUMN e INT NOT NULL DEFAULT 0;
|
UPDATE t1 SET a=7 WHERE a=4;
|
DROP TABLE t1;
|
Another variant:
--source include/have_innodb.inc
|
CREATE TABLE t1(a INT PRIMARY KEY, b INT NOT NULL) ENGINE=InnoDB;
|
INSERT INTO t1 (a,b) VALUES (4,0),(6,0),(7,0);
|
ALTER TABLE t1 DROP COLUMN b, ADD COLUMN (c INT NOT NULL DEFAULT 0, d INT NOT NULL DEFAULT 0);
|
ALTER TABLE t1 ADD INDEX (d);
|
UPDATE t1 SET d=77 WHERE a=4;
|
DELETE FROM t1 WHERE a=7;
|
INSERT INTO t1 (a,d) VALUES (7,77);
|
DELETE FROM t1 WHERE a=7;
|
ALTER TABLE t1 DROP COLUMN c, ADD COLUMN e INT NOT NULL DEFAULT 0;
|
UPDATE t1 SET a=7 WHERE a=4;
|
DROP TABLE t1;
|
These tests cause a similar content of the secondary index page as the nondeterministic ml_MDEV-20066.test, but no matter what I do, the clustered index page would contain the value 77 in the same index field position.
I think that the actual bug must occur on the clustered index record, or in the conversion of that record into a table row or from table row to secondary index record. The clustered index field for the indexed column should always be at the same position.
I tweaked the ml_MDEV-20066.test further so that it will crash in 1 second or pass in 4 seconds. With that modification, I was able to run enough repetitions of it so that the connection with the following (redundant) statement is not needed after all:
DELETE FROM t3 WHERE col1 = 8 ; COMMIT ;
|
With this connection eliminated, I got a different error and yet simpler table contents:
|
10.4 57a4323f67d7ab720a94438cb2f3998b643d726f
|
2019-08-26 14:39:01 13 [ERROR] InnoDB: Record in index `uidx3` of table `test`.`t3` was not found on update: TUPLE (info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} at: COMPACT RECORD(info_bits=0, 2 fields): {[4] (0x00000000),[4] (0x80000007)}
|
mysqld: /mariadb/10.4/storage/innobase/row/row0upd.cc:2429: dberr_t row_upd_sec_index_entry(upd_node_t *, que_thr_t *): Assertion `btr_validate_index(index, 0)' failed.
|
The clustered index contents is:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata),(4,0x105,update,0,77),delete-marked(7,0x105,update,0,77)
The secondary index contents is a single non-delete-marked record (col_text,col1)=(0,7), with PAGE_MAX_TRX_ID=0x106, which was apparently committed. We have trx_sys.m_max_trx_id=0x10a and the only active transactions are our 0x105 and a 0x103 that was blocked by a lock wait before it got to modify anything, for
INSERT INTO t3 (col1, col_text ) VALUES ( 6, 77 );
|
The current transaction is 0x105, and the statement is UPDATE t3 SET col1 = 4 LIMIT 2. Again, the transaction had written 2 undo log records, apparently for delete-marking the record col1=7, and then inserting the record with the new PRIMARY KEY(col1) value col1=4. Why did we not delete-mark the secondary index record (4,0)? Perhaps we failed to resume from a lock wait properly?
Next, I will try to eliminate the records col1=6 from the test case, because they were not needed for this crash.
|
|
Without statements referring col1=6 the test still crashes in row_upd_sec_index_entry(). This time, it managed to add 2 columns, but both indexes only contain 1 user record:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text,col_text_copy)=(metadata),delete-marked(7,0xcf,update,0,77,missing).
The secondary index contains a single record again, and it is not delete-marked:
(col_text,col1)=(0,7), PAGE_MAX_TRX_ID=0xcb (committed).
This time we crashed in the current transaction (0xcf) already on the very first undo log record, of the following:
DELETE FROM t3 WHERE col1 = 7;
|
I will retry after removing the statement
UPDATE t3 SET col_text_copy = col_text ;
|
because it clearly did not have any effect in this case.
|
|
If I remove all UPDATE statements from the test, then I will hit MDEV-20090/MDEV-20117 in the purge thread. If I work around that with innodb_force_recovery=2, then the test will pass. So, UPDATE are necessary.
With the UPDATE statements present, if I run with innodb_force_recovery=2, then the test will pass.
I can repeat the failure with 4 connections and the purge thread running:
connection 1:
ALTER TABLE t3 ADD COLUMN IF NOT EXISTS col_text_copy INT UNSIGNED NOT NULL DEFAULT 0 FIRST , ALGORITHM = NOCOPY , LOCK = EXCLUSIVE ;
|
ALTER TABLE t3 DROP COLUMN IF EXISTS col_text , ALGORITHM = NOCOPY , LOCK = EXCLUSIVE ;
|
ALTER TABLE t3 CHANGE COLUMN IF EXISTS col_text_copy col_text INT UNSIGNED NOT NULL DEFAULT 0, ADD INDEX IF NOT EXISTS `uidx3` ( col_text ) , ALGORITHM = NOCOPY , LOCK = EXCLUSIVE ;
|
connection 2:
INSERT INTO t3 (col1, col_text ) VALUES ( 7, 77 ); COMMIT;
|
connection 3:
DELETE FROM t3 WHERE col1 = 7;
|
connection 4:
UPDATE t3 SET col1 = 7; UPDATE t3 SET col1 = 4;
|
If I remove the DELETE, the test will pass. If I atomize the last one to
BEGIN; UPDATE t3 SET col1 = 4; UPDATE t3 SET col1 = 7; COMMIT;
|
then I will hit MDEV-20090/MDEV-20117 again, but not this bug.
The only remaining opportunity for simplification is the ALTER TABLE connection.
|
|
The simplest I got was an ALTER TABLE connection that runs only once, with two statements:
ALTER TABLE t3 DROP COLUMN col_text, ADD COLUMN col_text_copy INT UNSIGNED NOT NULL DEFAULT 0 FIRST , ALGORITHM = NOCOPY , LOCK = EXCLUSIVE ;
|
ALTER TABLE t3 CHANGE COLUMN col_text_copy col_text INT UNSIGNED NOT NULL DEFAULT 0, ADD INDEX uidx3 ( col_text ) , ALGORITHM = NOCOPY , LOCK = EXCLUSIVE ;
|
It appears necessary to run the INSERT statement several times. With the above ALTER, I got an ‘almost minimal’ crash that looks close to what I got earlier:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata with purged history),delete-marked(4,0x46,update,0,77),delete-marked(7,0x30,update,77)
(col_text,col1)=(0,7)
On rerun, I got something different:
|
10.4 efb8485d85b19a2a729310adc6779ca649198f29
|
Version: '10.4.8-MariaDB-debug-log' socket: '/dev/shm/10.4/mysql-test/var/tmp/23/mysqld.1.sock' port: 16460 Source distribution
|
2019-08-26 16:28:19 0x7efeead01700 InnoDB: Assertion failure in file /mariadb/10.4/storage/innobase/lock/lock0lock.cc line 4958
|
InnoDB: Failing assertion: !other_lock || wsrep_thd_is_BF(lock->trx->mysql_thd, FALSE) || wsrep_thd_is_BF(other_lock->trx->mysql_thd, FALSE)
|
…
|
#6 0x00005563e2cb0d4e in lock_rec_queue_validate (locked_lock_trx_sys=false,
|
block=0x7efeeb012128, rec=0x7efeeb51407d "\200", index=0x7efea012f218,
|
offsets=0x7efeeacf7cb0)
|
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:4956
|
#7 0x00005563e2cb2db3 in lock_clust_rec_read_check_and_lock (flags=0,
|
block=0x7efeeb012128, rec=0x7efeeb51407d "\200", index=0x7efea012f218,
|
offsets=0x7efeeacf7cb0, mode=LOCK_X, gap_mode=1024, thr=0x7efe8c02fb18)
|
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5849
|
#8 0x00005563e2e0dbed in sel_set_rec_lock (pcur=0x7efe8c02f5e0,
|
rec=0x7efeeb51407d "\200", index=0x7efea012f218, offsets=0x7efeeacf7cb0,
|
mode=3, type=1024, thr=0x7efe8c02fb18, mtr=0x7efeeacf86e8)
|
at /mariadb/10.4/storage/innobase/row/row0sel.cc:1262
|
#9 0x00005563e2e0956b in row_search_mvcc (buf=0x7efe9401ad68 "\377",
|
mode=PAGE_CUR_GE, prebuilt=0x7efe8c02f408, match_mode=1, direction=0)
|
at /mariadb/10.4/storage/innobase/row/row0sel.cc:5051
|
#10 0x00005563e2beb65c in ha_innobase::index_read (this=0x7efe8c01b260, buf=0x7efe9401ad68 "\377", key_ptr=0x7efe940678f0 "\a", key_len=4, find_flag=HA_READ_KEY_EXACT) at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:9305
|
#11 0x00005563e29577ae in handler::index_read_map (this=0x7efe8c01b260, buf=0x7efe9401ad68 "\377", key=0x7efe940678f0 "\a", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /mariadb/10.4/sql/handler.h:3595
|
#12 0x00005563e2943630 in handler::ha_index_read_map (this=0x7efe8c01b260, buf=0x7efe9401ad68 "\377", key=0x7efe940678f0 "\a", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /mariadb/10.4/sql/handler.cc:2891
|
#13 0x00005563e294d438 in handler::read_range_first (this=0x7efe8c01b260, start_key=0x7efe8c01b350, end_key=0x7efe8c01b370, eq_range_arg=true, sorted=true) at /mariadb/10.4/sql/handler.cc:5836
|
#14 0x00005563e27809b4 in handler::multi_range_read_next (this=0x7efe8c01b260, range_info=0x7efeeacf90a8) at /mariadb/10.4/sql/multi_range_read.cc:413
|
#15 0x00005563e2780b99 in Mrr_simple_index_reader::get_next (this=0x7efe8c01b800, range_info=0x7efeeacf90a8) at /mariadb/10.4/sql/multi_range_read.cc:450
|
#16 0x00005563e2783d4d in DsMrr_impl::dsmrr_next (this=0x7efe8c01b6c0, range_info=0x7efeeacf90a8) at /mariadb/10.4/sql/multi_range_read.cc:1520
|
#17 0x00005563e2bff14f in ha_innobase::multi_range_read_next (this=0x7efe8c01b260, range_info=0x7efeeacf90a8) at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:20114
|
#18 0x00005563e2b1bde0 in QUICK_RANGE_SELECT::get_next (this=0x7efe94054600) at /mariadb/10.4/sql/opt_range.cc:12142
|
#19 0x00005563e2b35aa0 in rr_quick (info=0x7efeeacf9558) at /mariadb/10.4/sql/records.cc:361
|
#20 0x00005563e249c55b in READ_RECORD::read_record (this=0x7efeeacf9558) at /mariadb/10.4/sql/records.h:69
|
#21 0x00005563e2b58de4 in mysql_delete (thd=0x7efe94000cf8, table_list=0x7efe94011558, conds=0x7efe94011dc0, order_list=0x7efe940056a8, limit=18446744073709551615, options=0, result=0x0) at /mariadb/10.4/sql/sql_delete.cc:802
|
#22 0x00005563e256de63 in mysql_execute_command (thd=0x7efe94000cf8) at /mariadb/10.4/sql/sql_parse.cc:4727
|
#23 0x00005563e2560850 in mysql_parse (thd=0x7efe94000cf8, rawbuf=0x7efe94011470 "DELETE FROM t3 WHERE col1 = 7", length=29, parser_state=0x7efeeacfe918, is_com_multi=false, is_next_command=false) at /mariadb/10.4/sql/sql_parse.cc:7908
|
In this case, the ALTER TABLE must have been run on an empty table, so the table is in the canonical format:
(col1,DB_TRX_ID,DB_ROLL_PTR,col_text)=(4,0,1<<55,77),(7,0x2ac,update,77)
(col_text,col1)=(77,4),(77,7)
Could an error in locking lead to the corruption occurring?
The other_lock is associated with the transaction 0x2ac, which is in the process of releasing locks during commit:
#8 0x00005563e2c10cf9 in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (
|
this=0x5563e3cc8800 <lock_sys+64>, n_spins=30, n_delay=4,
|
name=0x5563e34a5c24 "/mariadb/10.4/storage/innobase/lock/lock0lock.cc",
|
line=6268) at /mariadb/10.4/storage/innobase/include/ib0mutex.h:595
|
#9 0x00005563e2cb44c7 in lock_trx_release_locks (trx=0x7efef000a5e0)
|
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:6268
|
#10 0x00005563e2ea7ce9 in trx_commit_in_memory (trx=0x7efef000a5e0,
|
mtr=0x7efee81ced60) at /mariadb/10.4/storage/innobase/trx/trx0trx.cc:1374
|
#11 0x00005563e2ea718d in trx_commit_low (trx=0x7efef000a5e0,
|
mtr=0x7efee81ced60) at /mariadb/10.4/storage/innobase/trx/trx0trx.cc:1588
|
#12 0x00005563e2ea8ba8 in trx_commit (trx=0x7efef000a5e0)
|
at /mariadb/10.4/storage/innobase/trx/trx0trx.cc:1612
|
#13 0x00005563e2ea9baa in trx_commit_for_mysql (trx=0x7efef000a5e0)
|
at /mariadb/10.4/storage/innobase/trx/trx0trx.cc:1758
|
#14 0x00005563e2bdc978 in innobase_commit_low (trx=0x7efef000a5e0)
|
at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:4397
|
#15 0x00005563e2c06194 in innobase_commit_ordered_2 (trx=0x7efef000a5e0,
|
thd=0x7efe90000cf8)
|
at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:4519
|
#16 0x00005563e2bfbf0b in innobase_commit (hton=0x5563e4a5fe58,
|
thd=0x7efe90000cf8, commit_trx=false)
|
at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:4635
|
#17 0x00005563e293e9d1 in commit_one_phase_2 (thd=0x7efe90000cf8, all=false,
|
trans=0x7efe900042a8, is_real_trans=true)
|
at /mariadb/10.4/sql/handler.cc:1774
|
#18 0x00005563e293f1b2 in ha_commit_one_phase (thd=0x7efe90000cf8, all=false)
|
at /mariadb/10.4/sql/handler.cc:1754
|
#19 0x00005563e293c9c3 in ha_commit_trans (thd=0x7efe90000cf8, all=false)
|
at /mariadb/10.4/sql/handler.cc:1563
|
#20 0x00005563e2747d66 in trans_commit_stmt (thd=0x7efe90000cf8)
|
at /mariadb/10.4/sql/transaction.cc:436
|
#21 0x00005563e25762bf in mysql_execute_command (thd=0x7efe90000cf8) at /mariadb/10.4/sql/sql_parse.cc:6155
|
#22 0x00005563e2560850 in mysql_parse (thd=0x7efe90000cf8, rawbuf=0x7efe90011470 "INSERT INTO t3 (col1, col_text ) VALUES ( 7, 77 )", length=49, parser_state=0x7efee81d5918, is_com_multi=false, is_next_command=false) at /mariadb/10.4/sql/sql_parse.cc:7908
|
Here, we still have other_lock->trx->state=TRX_STATE_ACTIVE.
Other active transactions are 0x2b1 (the current transaction in the crashing thread, with undo_no=0, so no changes yet) and 0x2b0, likewise no changes yet:
#8 0x00005563e2c10cf9 in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (
|
this=0x5563e3cc8800 <lock_sys+64>, n_spins=30, n_delay=4,
|
name=0x5563e34a5c24 "/mariadb/10.4/storage/innobase/lock/lock0lock.cc",
|
line=1942) at /mariadb/10.4/storage/innobase/include/ib0mutex.h:595
|
#9 0x00005563e2cb1aa3 in lock_rec_lock (impl=false, mode=1027,
|
block=0x7efeeb012128, heap_no=3, index=0x7efea012f218, thr=0x7efe980251d8)
|
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:1942
|
#10 0x00005563e2cb2d99 in lock_clust_rec_read_check_and_lock (flags=0,
|
block=0x7efeeb012128, rec=0x7efeeb514097 "\200", index=0x7efea012f218,
|
offsets=0x7efeeacad0d0, mode=LOCK_X, gap_mode=1024, thr=0x7efe980251d8)
|
at /mariadb/10.4/storage/innobase/lock/lock0lock.cc:5846
|
#11 0x00005563e2e0dbed in sel_set_rec_lock (pcur=0x7efe98024ca0,
|
rec=0x7efeeb514097 "\200", index=0x7efea012f218, offsets=0x7efeeacad0d0,
|
mode=3, type=1024, thr=0x7efe980251d8, mtr=0x7efeeacadb08)
|
at /mariadb/10.4/storage/innobase/row/row0sel.cc:1262
|
#12 0x00005563e2e0956b in row_search_mvcc (buf=0x7efe98021bd8 "\377",
|
mode=PAGE_CUR_GE, prebuilt=0x7efe98024ac8, match_mode=1, direction=0)
|
at /mariadb/10.4/storage/innobase/row/row0sel.cc:5051
|
#13 0x00005563e2beb65c in ha_innobase::index_read (this=0x7efe98023f20,
|
buf=0x7efe98021bd8 "\377", key_ptr=0x7efe98021df0 "\004", key_len=4,
|
find_flag=HA_READ_KEY_EXACT)
|
at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:9305
|
#14 0x00005563e2bec64b in ha_innobase::rnd_pos (this=0x7efe98023f20,
|
buf=0x7efe98021bd8 "\377", pos=0x7efe98021df0 "\004")
|
at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:9807
|
#15 0x00005563e294320f in handler::ha_rnd_pos (this=0x7efe98023f20,
|
buf=0x7efe98021bd8 "\377", pos=0x7efe98021df0 "\004")
|
at /mariadb/10.4/sql/handler.cc:2866
|
#16 0x00005563e2b353de in rr_from_tempfile (info=0x7efeeacae9d8)
|
at /mariadb/10.4/sql/records.cc:493
|
#17 0x00005563e249c55b in READ_RECORD::read_record (this=0x7efeeacae9d8)
|
at /mariadb/10.4/sql/records.h:69
|
#18 0x00005563e26aa407 in mysql_update (thd=0x7efe98000cf8,
|
table_list=0x7efe98011548, fields=..., values=..., conds=0x0,
|
order_num=0, order=0x0, limit=18446744073709551615, ignore=false,
|
found_return=0x7efeeacafef8, updated_return=0x7efeeacafef0)
|
at /mariadb/10.4/sql/sql_update.cc:954
|
#19 0x00005563e256bfa7 in mysql_execute_command (thd=0x7efe98000cf8)
|
at /mariadb/10.4/sql/sql_parse.cc:4369
|
#20 0x00005563e2560850 in mysql_parse (thd=0x7efe98000cf8,
|
rawbuf=0x7efe98011470 "UPDATE t3 SET col1 = 7", length=22,
|
parser_state=0x7efeeacb3918, is_com_multi=false, is_next_command=false)
|
at /mariadb/10.4/sql/sql_parse.cc:7908
|
|
|
other_lock_MDEV-20066.test occasionally (roughly once in 10 runs of the optimized debug build) repeats the other_lock assertion for me when running with
./mtr --parallel=auto main.other_lock_MDEV-20066{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,}
|
It simplifies the ALTER TABLE to one statement and prevents the instant ALTER TABLE related bug from occurring:
ALTER TABLE t3 DROP COLUMN col_text, ADD COLUMN col_text INT UNSIGNED NOT NULL DEFAULT 0, ADD INDEX IF NOT EXISTS uidx3 ( col_text ), FORCE , ALGORITHM = INPLACE , LOCK = EXCLUSIVE ;
|
Furthermore, I can remove the separate ‘thread’ and amend the CREATE TABLE statement, and still be able to repeat the other_lock assertion failure:
CREATE TABLE t3 (col1 INT PRIMARY KEY, col_text INT UNSIGNED NOT NULL DEFAULT 0, INDEX uidx3(col_text)) ENGINE=InnoDB;
|
|
|
mm_MDEV-20066.test is my current reduced test for reproducing the btr_validate_index() assertion failure in row_upd_sec_index_entry() with rather poor probability. Similar to other_lock_MDEV-20066.test, it depends on the mysqltest_background.sh from MDEV-20066.tgz.
|
|
I updated MDEV-15326 with the other_lock assertion failure, which I can also repeat on mysql-5.7.27 and 10.2, but not 10.1. I think that that failure should be fixed first, because malfunctioning locks could theoretically cause this kind of data corruption.
|
|
I ported the in-progress 10.3 fixes for MDEV-15326 to 10.4, and I can still reproduce this issue with mm_MDEV-20066.test:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata record with purged history),delete-marked(7,0x14f,update,0,77)
(col_text,col1)=(0,7), PAGE_MAX_TRX_ID=0x150
The current transaction 0x14f DELETE FROM t3 WHERE col1=7 crashes after successfully delete-marking the clustered index record, because the secondary index record is not (77,7) but (0,7). trx->undo_no=1, as expected.
Other active transactions in the system are 0x151 INSERT INTO t3 (col1, col_text) VALUES (7, 77) and 0x153 UPDATE t3 SET col1=4, both stuck in lock wait with trx->undo_no=0, as expected.
I think that this bug must have been caused by MDEV-15562 (instant DROP COLUMN).
|
|
mmr_MDEV-20066.test is a ./mtr --repeat friendly and slightly cleaned up version of mm_MDEV-20066.test.
|
|
Another crash with mmr_MDEV-20066.test, again on DELETE transaction 0x40d7:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata record with purged history),delete-marked(4,0x40d5,update,0),delete-marked(7,0x40d7,update,0,77)
(col_text,col1)=delete-marked(0,4),(0,7), PAGE_MAX_TRX_ID=0x40d5
Again, we are missing the record (77,7) and finding (0,7) instead.
Other active transactions are 0x40d9 (UPDATE t3 SET col1 = 4) and 0x40d6 (INSERT), both waiting for lock, with no changes done.
The test is always explicitly inserting col_text=77, never updating it. The only way how col_text=0 can occur is when the table is nonempty to being with and the following statement is executed:
ALTER TABLE t3 DROP COLUMN col_text, ADD COLUMN col_text INT UNSIGNED NOT NULL DEFAULT 0, ALGORITHM=INSTANT;
|
I will try to instrument the secondary index operations, so that I will see which statements are inserting the values.
|
|
instrument_secondary_index.patch implements crude logging for secondary index operations (not for modifying the delete-mark flag). I did not want stack traces, because they would most likely destroy the reproducibility. It did seem to reduce the reproducibility somewhat, but I finally got a failure that looks like the one in my immediately preceding comment:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata record with purged history),delete-marked(4,0xae0e,update,77),delete-marked(7,0xae11,update,0,77)
(col_text,col1)=delete-marked(0,4),(0,7), PAGE_MAX_TRX_ID=0xae0e
Again, the crashing transaction is 0xae11 DELETE, with trx->undo_no=1, excepting to find (77,7) but finding (0,7) instead.
Other active transactions are 0xae14 (UPDATE t3 SET col1 = 4) and 0xae12 (INSERT), both waiting for lock, with no changes done.
Except for transaction IDs, this looks equivalent to the previous crash. Here is the log output:
2019-08-29 13:20:27 163 [Note] InnoDB: uip COMPACT RECORD(info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} by 0xade6,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 13:20:27 163 [Note] InnoDB: uip COMPACT RECORD(info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} by 0xadef,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 13:20:27 163 [Note] InnoDB: uip COMPACT RECORD(info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} by 0xadf8,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 13:20:27 163 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} by 0xae01,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 13:20:27 163 [Note] InnoDB: uip COMPACT RECORD(info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} by 0xae05,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 13:20:27 165 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[4] (0x00000000),[4] (0x80000007)} by 0xae0e,UPDATE t3 SET col1 = 7
|
2019-08-29 13:20:27 164 [ERROR] [FATAL] InnoDB: Record in index `uidx3` of table `test`.`t3` was not found on update: TUPLE (info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} at: COMPACT RECORD(info_bits=0, 2 fields): {[4] (0x00000000),[4] (0x80000007)}
|
190829 13:20:27 [ERROR] mysqld got signal 6 ;
|
By design, there is no output for the ALTER TABLE statements. But, because the table was initially created with no secondary index, the ALTER TABLE statements are executed only once, and because the output is only being issued for secondary indexes, we know that both ALTER TABLE statements had completed early on.
Based on this knowledge, we can simplify the test (and improve reproducibility) further by removing the ALTER TABLE connection and performing those statements at initialization:
CREATE TABLE t3 (col1 INT PRIMARY KEY, col_text INT UNSIGNED NOT NULL DEFAULT 0) ENGINE=InnoDB;
|
INSERT INTO t3 VALUES (7,77);
|
ALTER TABLE t3 DROP COLUMN col_text, ADD COLUMN col_text INT UNSIGNED NOT NULL DEFAULT 0, ALGORITHM=INSTANT;
|
ALTER TABLE t3 ADD INDEX uidx3 ( col_text ), ALGORITHM = NOCOPY, LOCK = EXCLUSIVE ;
|
With this modification, it will fail too.
Armed with this improved reproducibility, I tried to replace the UPDATE with DELETE, but the test would refuse to fail again.
Once, I got a different failure:
2019-08-29 14:11:30 2 [ERROR] InnoDB: tried to purge non-delete-marked record in index `uidx3` of table `test`.`t3`: tuple: TUPLE (info_bits=0, 2 fields): {[4] (0x00000000),[4] (0x80000007)}, record: COMPACT RECORD(info_bits=0, 2 fields): {[4] (0x00000000),[4] (0x80000007)}
|
mysqld: /mariadb/10.4/storage/innobase/row/row0purge.cc:599: bool row_purge_remove_sec_if_poss_leaf(purge_node_t *, dict_index_t *, const dtuple_t *): Assertion `0' failed.
|
Given that no record with col_text=0 should ever be inserted into the secondary index for the INSERT statement, which always passes col_text=77, I think that I can add an assertion to catch this corruption at the moment when it occurs.
|
|
For the purge crash, the value col_text=77 appears at the very end of the log output, immediately preceding the failure:
2019-08-29 14:11:30 80 [Note] InnoDB: uip COMPACT RECORD(info_bits=0, 2 fields): {[4] (0x00000000),[4] (0x80000004)} by 0xd737,UPDATE t3 SET col1 = 4
|
2019-08-29 14:11:30 81 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} by 0xd739,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 14:11:30 80 [Note] InnoDB: uip COMPACT RECORD(info_bits=0, 2 fields): {[4] (0x00000000),[4] (0x80000007)} by 0xd74a,UPDATE t3 SET col1 = 7
|
2019-08-29 14:11:30 81 [Note] InnoDB: uip COMPACT RECORD(info_bits=0, 2 fields): {[4] M(0x0000004D),[4] (0x80000007)} by 0xd74c,INSERT INTO t3 VALUES (7,77)
|
All preceding entries were with the value col_text=0. The indexes contain the following:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata record with purged history),delete-marked(4,0xd74a,0x15000001632cce,0),delete-marked(7,0xd750,0x190000019e201a,0,77)
(col_text,col1)=delete-marked(0,4),(0,7),(77,7), PAGE_MAX_TRX_ID=0xd74c
The transaction 0xd750 (DELETE) is active, waiting for page latch in row_upd_sec_index_entry().
Other transactions are 0xd752 (INSERT) and 0xd74f (UPDATE t3 SET col1 = 4), both waiting for record lock, no changes performed yet.
Here, the secondary index looks corrupted, with two non-delete-marked entries for col1=7: (0,7) and (77,7).
The (77,7) is about to be delete-marked by the DELETE transaction, which is waiting for the page latch. But it should not have coexisted with the (0,7)!
I dereferenced the DB_ROLL_PTR=0x190000019e201a for the clustered index record (7,77) that the DELETE is marking. As expected, it refers to a log with only one TRX_UNDO_DEL_MARK_REC record. The previous version is (7,0xd74c,0x17000001bd1d78,77), matching the 0xd74c for the INSERT in the diagnostic output. Because the high-order bit of DB_ROLL_PTR is not set, we can see that that INSERT was actually delete-unmarking a delete-marked record.
The (0,7) was inserted by the UPDATE of a record that carried col1=4, visible in the above log snippet.
I dereferenced the DB_ROLL_PTR=0x15000001632cce for the clustered index record (4,0) that the UPDATE t3 SET col1=7 delete-marked. It points to the first record of a log with two entries:
- TRX_UNDO_DEL_MARK_REC for (4,0xd737,0x09000001ba2345) (this is the first entry in the log snippet above, inserted by UPDATE t3 SET col1=4)
- TRX_UNDO_UPD_DEL_REC for (7,0xd747,0x13000001442290,col_text=77) (col_text was correctly identified by field number 4, the instantly added column)
I dereferenced the DB_ROLL_PTR=0x13000001442290 to find out what the transaction 0xd747 executed. It refers to a log with only one record: TRX_UNDO_DEL_MARK_REC for (7,0xd739,0x0a000001701d25,col_text=77). So, it must have been a DELETE statement.
There was no diagnostic message for transaction 0xd747 touching the secondary index, but that could be because I did not instrument delete-mark activity. I must add more instrumentation to get a better view.
|
|
Another crash during DELETE, with delete-mark operations logged, and with TINYINT UNSIGNED and ROW_FORMAT=REDUNDANT:
2019-08-29 17:03:47 93 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[8] (0x0000000000000020),[7]test/t3(0x746573742F7433)} by 0x10e59,CREATE TABLE t3 (col1 TINYINT UNSIGNED PRIMARY KEY, col_text TINYINT UNSIGNED NOT NULL DEFAULT 0) ENGINE=InnoDB ROW_FORMAT=REDUNDANT
|
2019-08-29 17:03:48 95 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x10e90,UPDATE t3 SET col1 = 4
|
2019-08-29 17:03:48 95 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x10e90,UPDATE t3 SET col1 = 4
|
2019-08-29 17:03:48 94 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x10e91,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 17:03:48 95 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x10e94,UPDATE t3 SET col1 = 7
|
2019-08-29 17:03:48 96 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x10e96,DELETE FROM t3 WHERE col1=7
|
2019-08-29 17:03:48 94 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x10e97,INSERT INTO t3 VALUES (7,77)
|
2019-08-29 17:03:48 96 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x10e9e,DELETE FROM t3 WHERE col1=7
|
2019-08-29 17:03:48 95 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x10e9c,UPDATE t3 SET col1 = 7
|
2019-08-29 17:03:48 95 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x10e9c,UPDATE t3 SET col1 = 7
|
2019-08-29 17:03:48 96 [ERROR] [FATAL] InnoDB: Record in index `uidx3` of table `test`.`t3` was not found on update: TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} at: RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)}
|
The DELETE transaction is 0x10ea1, and it modified the clustered index record already. The indexes contain the following:
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata record with purged history),delete-marked(7,0x10ea1,0x3900000156037d,0,77)
(col_text,col1)=(0,7), PAGE_MAX_TRX_ID=0x10e9e
The secondary index is expected to contain (77,7), not (0,7).
The DB_ROLL_PTR points to a single-record undo log of our transaction (just as expected), with TRX_UNDO_DEL_MARK_REC of (7,0,1<<55,col_text=77). Unfortunately the history of a previous INSERT had been purged.
In the secondary index page, the PAGE_FREE list contains the purged delete-marked records (0,4),(0,7).
In the clustered index page, the PAGE_FREE list contains the purged delete-marked records (4,0x10e9c,0x360000016a0c89,0),(7,0x10e90,0x2e0000015905,77,77).
I did not add diagnostic output to btr_cur_optimistic_delete(), because a thr or trx parameter is not available there. Earlier, I wrote that the failure is not reproducible when purge is disabled by innodb_force_recovery=2.
I think that this must be somehow related to purge, and I must instrument it next.
|
|
Another day, another crash, this time with some more diagnostics:
2019-08-30 8:58:21 9 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[8] (0x0000000000000014),[7]test/t3(0x746573742F7433)} by 0x22,CREATE TABLE t3 (col1 TINYINT UNSIGNED PRIMARY KEY, col_text TINYINT UNSIGNED NOT NULL DEFAULT 0) ENGINE=InnoDB ROW_FORMAT=REDUNDANT
|
2019-08-30 8:58:22 12 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x63,UPDATE t3 SET col1 = 4
|
2019-08-30 8:58:22 12 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x63,UPDATE t3 SET col1 = 4
|
2019-08-30 8:58:22 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x64,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 8:58:22 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}
|
2019-08-30 8:58:22 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}:1
|
2019-08-30 8:58:22 12 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x66,UPDATE t3 SET col1 = 7
|
2019-08-30 8:58:22 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x69,DELETE FROM t3 WHERE col1=7
|
2019-08-30 8:58:22 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}
|
2019-08-30 8:58:22 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}:1
|
2019-08-30 8:58:22 12 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x6d,UPDATE t3 SET col1 = 7
|
2019-08-30 8:58:22 12 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x6d,UPDATE t3 SET col1 = 7
|
2019-08-30 8:58:22 4 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}
|
2019-08-30 8:58:22 4 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}:1
|
2019-08-30 8:58:22 4 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] m(0x00000000006D),[7]D I (0x44000001490110),[1] (0x00),DEFAULT}
|
2019-08-30 8:58:22 11 [ERROR] [FATAL] InnoDB: Record in index `uidx3` of table `test`.`t3` was not found on update: TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} at: RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)}
|
(col1,DB_TRX_ID,DB_ROLL_PTR,dropped_col_text,col_text)=(metadata record with purged history),delete-marked(7,0x6f,0x460000014a0110,0,77)
(col_text,col1)=(0,7), PAGE_MAX_TRX_ID=0x6d
Again, instead of finding a delete-marked record (77,7), we find the non-delete-marked (0,7) in the secondary index.
The history of the record (77,7) is as follows:
- inserted by INSERT INTO t3 VALUES (7,77), transaction 0x64
- delete-marked by DELETE FROM t3 WHERE col1=7, transaction 0x69
- purged
- assertion failure on DELETE FROM t3 WHERE col1=7, transaction 0x6f
(other transactions 0x71,0x72 are waiting for locks, did not modify anything)
The history of the record (0,7) is as follows:
- delete-marked by UPDATE t3 SET col1=4, transaction 0x63
- purged
- inserted by UPDATE t3 SET col1=7, transaction 0x6d updating (0,4) to (0,7)
Let us reconstruct the complete contents of the secondary index (col_text,col1) at each step of the log:
- initial state: (0,7) after ADD INDEX (not logged)
- del-mark(0,7) after UPDATE t3 SET col1 = 4, transaction 0x63
- (0,4),del-mark(0,7) after UPDATE t3 SET col1 = 4, transaction 0x63
- (0,4),del-mark(0,7),(77,7) after INSERT INTO t3 VALUES (7,77), transaction 0x64
- (0,4),(77,7) after purge
- del-mark(0,4),(77,7) after UPDATE t3 SET col1 = 7, transaction 0x66
- del-mark(0,4),del-mark(77,7) after DELETE FROM t3 WHERE col1=7, transaction 0x69
- del-mark(0,4) after purge
- del-mark(0,4) after UPDATE t3 SET col1 = 7, transaction 0x6d
- del-mark(0,4),(0,7) after UPDATE t3 SET col1 = 7, transaction 0x6d
- (0,7) after purge
- (0,7) instead of (77,7) on the DELETE FROM t3 WHERE col1=7, transaction 0x6f
The last UPDATE is attempting to delete-mark an already delete-marked record (0,4). The corruption seems to have been caused earlier, by UPDATE t3 SET col1 = 7, transaction 0x66, which did not attempt to insert the record (0,7) as expected. Actually, that transaction should have been rolled back, because the record (7,77) already existed in the clustered index, so the attempt to update (4,0) to (7,0) should have violated the uniqueness of the PRIMARY KEY(col1).
I must add more diagnostics to cover transaction rollback. The bug appears to be in the UPDATE or its rollback.
|
|
The diagnostics for del-mark both in the previous logs and the following log was misleading, because it is not showing the new value of the flag, and it is being displayed even when there is no change.
I analyzed another crash, with an explicit trace of persistent transaction commit (undo_no>0) or rollback (undo_no=0).
Again, we crash on DELETE (transaction 0x57), while other transactions 0x59,0x5a are blocked before making any changes.
And again, the table contents is the same, except for transaction identifiers and undo log pointers.
According to the available information that I gathered from the new crash, the clustered index should have contained the record (7,0) instead of (7,77), after the UPDATE t3 SET col1 = 7, transaction 0x53.
Similarly for the earlier case, the record (0,4) was not delete-marked by the UPDATE (transaction 0x66); it was a null change performed by a rollback that was made due to duplicate primary key. Also in that case, it looks like the clustered index should have contained (7,0) instead of (7,77).
I reran with more diagnostics (also including operations on the clustered index), to get a similar crash again, at DELETE, transaction 0xac. In the undo log record for that transaction, the DB_TRX_ID had been zeroed out by row_purge_reset_trx_id(). I might disable that, so that we can try to cross-reference the undo log records with the diagnostic output.
|
|
TL;DR: Here is a deterministic test case that does not repeat any crash, but shows error in CHECK TABLE even with innodb_force_recovery=2 (purge disabled):
--source include/have_innodb.inc
|
CREATE TABLE t1(a INT PRIMARY KEY, b INT NOT NULL) ENGINE=InnoDB;
|
INSERT INTO t1 VALUES (7,77);
|
|
ALTER TABLE t1 DROP COLUMN b, ADD COLUMN c INT NOT NULL DEFAULT 0;
|
ALTER TABLE t1 ADD INDEX (c);
|
|
BEGIN;
|
DELETE FROM t1;
|
INSERT INTO t1 VALUES (4,0),(7,77);
|
COMMIT;
|
BEGIN;
|
DELETE FROM t1 WHERE a=7;
|
UPDATE t1 SET a=7;
|
COMMIT;
|
DELETE FROM t1;
|
CHECK TABLE t1;
|
DROP TABLE t1;
|
How did I arrive at that?
After disabling row_purge_reset_trx_id(), I can follow the history from the undo log page for failures of mmr_MDEV-20066.test with btr-instr.patch.
With this crash, the DELETE is transaction 0x64. The record (7,77) was previously updated by the second and last undo log record of transaction 0x5f, which recorded TRX_UNDO_DEL_MARK_REC for (4,0) and TRX_UNDO_UPD_DEL_REC for (7,77) that had been delete-marked by the only undo log record of transaction 0x60, and previously inserted by transaction 0x5e, which is where the history starts by TRX_UNDO_INSERT_REC.
The ADD INDEX (transaction 0x2b) was committed long before 0x5e started. So, the clustered index record with col1=7 must have carried the value col_text=77 from this point on, and a previous entry must have been purged before 0x5e started. The log confirms this: there was a DELETE and purge right before the INSERT.
According to the following, the index did contain a record (col1,col_text)=(4,0) since this point:
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 4 fields): {[1] (0x04),[6] E(0x000000000045),[7] I /(0x9700000149012F),[1] (0x00)} by 0x45,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x45,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x45,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x45,2
|
The DB_ROLL_PTR=0x9700000149012F points to the second and last record of a transaction that logged TRX_UNDO_DEL_MARK_REC for col1=7 that had been modified by transaction 0x43, and TRX_UNDO_INSERT_REC for the (4,0). There is a chain of undo log records, pointing to transactions 0x43, 0x40, 0x3d, 0x3b, 0x39, 0x37, 0x35, 0x33, 0x31, 0x2f, 0x24, which was the initial INSERT of the record col1=7 before the ALTER TABLE (0x28 and 0x2b). After the first ALTER, the record should be interpreted as (col1,dropped_col_text,col_text)=(7,77,DEFAULT=0), that is, (7,0).
So, the record value (4,0) after the long chain of UPDATE seems to be legitimate. The original record (7,0) with dropped_col_text=77 was purged already between transaction 0x2f and 0x31:
2019-08-30 11:03:49 9 [Note] InnoDB: insert TUPLE (info_bits=0, 5 fields): {[8] (0x000000000000001A),[4] (0x00000000),[6] +(0x00000000002B),[7] < (0x880000013C029F),[8]col_text(0x636F6C5F74657874)} by 0x2b,ALTER TABLE t3 ADD INDEX uidx3 ( col_text ), ALGORITHM = NOCOPY, LOCK = EXCLUSIVE
|
2019-08-30 11:03:49 9 [Note] InnoDB: commit 0x2b,2
|
2019-08-30 11:03:49 9 [Note] InnoDB: commit 0x2d,1
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 4 fields): {[1] (0x04),[6] /(0x00000000002F),[7] = (0x8A0000013D02D2),[1] (0x00)} by 0x2f,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x2f,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x2f,UPDATE t3 SET col1 = 4
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x2f,2
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x07)}:1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] /(0x00000000002F),[7] = (0x0A0000013D02B3),[1]M(0x4D),DEFAULT}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] /(0x00000000002F),[7] = (0x0A0000013D02B3),[1]M(0x4D),DEFAULT}
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 4 fields): {[1] (0x07),[6] 1(0x000000000031),[7] > O(0x8B0000013E024F),[1] (0x00)} by 0x31,UPDATE t3 SET col1 = 7
|
Here is the end of the log:
2019-08-30 11:03:50 10 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] Q(0x000000000051),[7] O (0x1E0000014F0110),[1] (0x00),DEFAULT} to RECORD(info_bits=0, 5 fields): {[1] (0x04),[6] (0x000000000000),[7] (0x80000000000000),[1] (0x00),DEFAULT} by 0x51,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x51,0
|
2019-08-30 11:03:50 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x55,DELETE FROM t3 WHERE col1=7
|
2019-08-30 11:03:50 11 [Note] InnoDB: commit 0x55,1
|
2019-08-30 11:03:50 12 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] U(0x000000000055),[7] P (0x20000001500110),[1] (0x00),[1]M(0x4D)} to RECORD(info_bits=0, 5 fields): {[1] (0x07),[6] T(0x000000000054),[7] Q (0x1F000001510110),[1] (0x00),[1]M(0x4D)} by 0x54,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: uip RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)} to RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x54,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: commit 0x54,1
|
2019-08-30 11:03:50 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x59,DELETE FROM t3 WHERE col1=7
|
2019-08-30 11:03:50 11 [Note] InnoDB: commit 0x59,1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}:1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] Y(0x000000000059),[7]! R (0x21000001520110),[1] (0x00),[1]M(0x4D)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] Y(0x000000000059),[7]! R (0x21000001520110),[1] (0x00),[1]M(0x4D)}
|
2019-08-30 11:03:50 12 [Note] InnoDB: insert TUPLE (info_bits=0, 5 fields): {[1] (0x07),[6] ^(0x00000000005E),[7] S (0xA5000001530110),[1] (0x00),[1]M(0x4D)} by 0x5e,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x5e,INSERT INTO t3 VALUES (7,77)
|
2019-08-30 11:03:50 12 [Note] InnoDB: commit 0x5e,1
|
2019-08-30 11:03:50 11 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} by 0x60,DELETE FROM t3 WHERE col1=7
|
2019-08-30 11:03:50 11 [Note] InnoDB: commit 0x60,1
|
2019-08-30 11:03:50 4 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}
|
2019-08-30 11:03:50 4 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1]M(0x4D),[1] (0x07)}:1
|
2019-08-30 11:03:50 10 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] `(0x000000000060),[7]' T (0x27000001540110),[1] (0x00),[1]M(0x4D)} to RECORD(info_bits=0, 5 fields): {[1] (0x07),[6] _(0x00000000005F),[7]& U /(0x2600000155012F),[1] (0x00),[1]M(0x4D)} by 0x5f,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: del-mark RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x04)} by 0x5f,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: insert TUPLE (info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)} by 0x5f,UPDATE t3 SET col1 = 7
|
2019-08-30 11:03:50 10 [Note] InnoDB: commit 0x5f,2
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purging RECORD(info_bits=32, 2 fields): {[1] (0x00),[1] (0x04)}:1
|
2019-08-30 11:03:50 2 [Note] InnoDB: delete RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] _(0x00000000005F),[7]& U (0x26000001550110),[1] (0x00),DEFAULT}
|
2019-08-30 11:03:50 2 [Note] InnoDB: purged RECORD(info_bits=32, 5 fields): {[1] (0x04),[6] _(0x00000000005F),[7]& U (0x26000001550110),[1] (0x00),DEFAULT}
|
2019-08-30 11:03:50 11 [ERROR] [FATAL] InnoDB: Record in index `uidx3` of table `test`.`t3` was not found on update: TUPLE (info_bits=0, 2 fields): {[1]M(0x4D),[1] (0x07)} at: RECORD(info_bits=0, 2 fields): {[1] (0x00),[1] (0x07)}
|
Let me reconstruct the clustered index contents from the start of transaction 0x5e:
- (4,0),(7,77) at the start of transaction 0x51 (rolled back)
- (4,0),delete-marked(7,77) after DELETE, transaction 0x55 (committed)
- (4,0),(7,77) after INSERT, transaction 0x54 (committed)
- (4,0),delete-marked(7,77) after DELETE, transaction 0x59 (committed)
- (4,0) after purge (in both indexes)
- (4,0),(7,77) after INSERT, transaction 0x5e (committed)
- (4,0),delete-marked(7,77) after DELETE, transaction 0x60 (committed)
- unchanged after (77,7) was purged from secondary index
- delete-marked(4,0),(7,77) after UPDATE, transaction 0x5f
- (7,77) after purge (in both indexes)
- crash on DELETE because the record should have been (7,0)
The logging for clustered index operations is not complete, but the evidence for the corruption is there, wrongly using update-in-place and inserting (7,77) instead of (7,0) when updating (4,0):
2019-08-30 11:03:50 10 [Note] InnoDB: uip RECORD(info_bits=32, 5 fields): {[1] (0x07),[6] `(0x000000000060),[7]' T (0x27000001540110),[1] (0x00),[1]M(0x4D)} to RECORD(info_bits=0, 5 fields): {[1] (0x07),[6] _(0x00000000005F),[7]& U /(0x2600000155012F),[1] (0x00),[1]M(0x4D)} by 0x5f,UPDATE t3 SET col1 = 7
|
|
|
The corruption is repeatable on 10.3, which does not support instant DROP COLUMN:
--source include/have_innodb.inc
|
CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
|
INSERT INTO t1 VALUES (7);
|
|
ALTER TABLE t1 ADD COLUMN c INT NOT NULL DEFAULT 0;
|
ALTER TABLE t1 ADD INDEX (c);
|
|
BEGIN;
|
DELETE FROM t1;
|
INSERT INTO t1 VALUES (4,0),(7,77);
|
COMMIT;
|
BEGIN;
|
DELETE FROM t1 WHERE a=7;
|
UPDATE t1 SET a=7;
|
COMMIT;
|
SELECT * FROM t1 FORCE INDEX(PRIMARY);
|
SELECT * FROM t1 FORCE INDEX(c);
|
DELETE FROM t1;
|
CHECK TABLE t1;
|
DROP TABLE t1;
|
The problem is that row_upd_build_difference_binary() fails to account for index->n_fields > entry->n_fields. Hence, the UPDATE of (4,0) to (7,0) will write the wrong value (7,77) to the clustered index and the correct value (0,7) to the secondary index.
|
|
Note that until MDEV-19783 is fixed, it may be risky to use instant ADD COLUMN.
|
MDEV-20066.tgz
prt