Details
-
Task
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
Description
The original description of this task read as follows:
as a solution for bulk-inserting huge amount of data into innodb, we consider an utility that creates exported innodb tablespaces.
Normally one needs to create a table in InnoDB or XtraDB and then "export" it. But we could try to create an exported tablespace with a table not by actually exporting it but directly from the data, say, from XML or CSV.
In the end, we decided to optimize the INSERT code path inside InnoDB. There are many different InnoDB ROW_FORMAT, and we do not have instant import until MDEV-11658 gets some thought. Besides, if we make INSERT faster, also some normal workloads will benefit.
We implement an idea that was suggested by monty in October 2017: When InnoDB is inserting into an empty table or partition, we can write a single undo log record TRX_UNDO_EMPTY to cover the operation. ROLLBACK would clear the table when undoing this record.
For this to work, the insert into an empty table or partition must be covered by an exclusive table lock that will be held until the transaction has been committed or rolled back, or until a partial rollback that affects the INSERT operation (so that the table is empty again).
Concurrent non-locking reads must be adjusted: If the read view was created before the INSERT into an empty table was committed, then we must continue to imagine that the table is empty, and not try to read any records. If the read view was created after the COMMIT of the INSERT, then all records must be visible normally.
This special handling only applies to the very first INSERT statement of a transaction for the empty table or partition. If a subsequent statement in the transaction is modifying the initially empty table again, we must enable row-level undo logging, so that we will be able to roll back to the start of the statement in case of an error (such as duplicate key).
INSERT IGNORE will continue to use row-level logging and locking, because implementing it would require the ability to roll back the latest row, while our table-level logging only allows the entire statement to be rolled back.
Future work:
MDEV-24621will make such INSERT even faster, by sorting the records for each index separately and by building indexes one page at a time.MDEV-24622will enable this feature on replicas (slaves).MDEV-24623will enable this feature on Galera cluster.
Attachments
Issue Links
- blocks
-
MDEV-23484 Rollback unnecessarily acquires dict_operation_lock for every row
-
- Closed
-
-
-
- Closed
-
- causes
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
- duplicates
-
-
- Closed
-
- includes
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Open
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Open
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Confirmed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
- mentioned in
-
Page Loading...
(19 causes, 1 duplicates, 1 includes, 23 relates to, 1 mentioned in)
Activity
I don't know. One very important part of this feature — it's a difference between "repair by sort" and "repair with keycache" in MyISAM. Basically, one can insert values into b-tree one by one (repair with keycache) or one can generate sort the values and the whole b-tree at once, page after page. The second approach is much faster. But I don't know if InnoDB can do that.
Well, for secondary keys this can be implemented "logically" by adding secondary keys only after all data is inserted into the table. This bulk-loading tool would have to have full DDL for the table in order to create it in the first place, so it should be possible to pretty easily parse that and add secondary keys only after the import.
I'm not sure about the clustered index... does InnoDB have any optimization for LOAD DATA to defer index creation or handle it in batches?
There are multiple things that can be done to speed up bulk insert:
- Skip record locking and undo logging. (MySQL 5.6 WL#5526 and WL#6625 do this in ALGORITHM=INPLACE.)
- Skip redo logging, and build the indexes page by page. (MySQL 5.7 WL#7277 does this in ALGORITHM=INPLACE during the index build phase. But it still does redo logging when applying the online log.)
- (MySQL 8.0 disables undo logging but not redo logging: Bug#17479594 AVOID INTERMEDIATE COMMIT WHILE DOING ALTER TABLE ALGORITHM=COPY)
In MariaDB 10.2, we already have the above building blocks in place. We should only tie it to the SQL statements:
- CREATE TABLE…SELECT and ALTER TABLE…ALGORITHM=COPY: Only generate undo log for creating the table, so that recovery will drop it if we do not commit. Remove intermediate commits during the operation (currently we commit the CREATE TABLE part before the INSERT…SELECT part).
- Implement a new statement that combines CREATE TABLE with LOAD DATA INFILE.
In all the above cases, we would build the table page by page. If the table is located in the system tablespace, we must write redo log about the page allocations. Else, we can disable all redo logging. At the end of the operation (just before commit), we must flush all pages before enabling redo logging for the table.
Crash recovery can only observe an incomplete CREATE TABLE operation that it would address by DROP TABLE. Dropping a table requires valid page allocation information except if a separate *.ibd file was created for the table.'
Because InnoDB does not allow multiple concurrent transactions on its data dictionary tables, we probably should mark the incomplete tables in SYS_TABLES somehow, so that incomplete tables can be dropped on startup. This should also fix the problem of orphan tables left behind by ALTER TABLE.
Undo log only looks promising , but what i miss is the multi row insert part generated by a regular dump , we should be able to mark the table in such state so that multiple statement can be proceed in the same state CREATE TEMPORARY TABLE test ENGINE=innodb NOLOG; ALTER TABLE test ALGORITHM=COPY ENGINE=innodb;
stephane@skysql.com seems to be suggesting a change to dump-generating tools to change the syntax to indicate that a dump is being loaded.
I guess that if the table is very long, we would indeed need some ‘begin bulk load’ and ‘end bulk load’ delimiters. The exact syntax of those delimiters should be chosen carefully. My preference would be to not use ALTER TABLE for that, and especiallty not ALGORITHM=COPY, because I think that we would want to avoid unnecessary copying. The data file that is being loaded will be perfectly valid, provided that the operation is completed.
What if we had new syntax would combine the CREATE TABLE and the data, inline?
CREATE TABLE t (a INT, b VARCHAR(255)) ENGINE=InnoDB LOAD DATA INLINE DELIMITER 'EOF';
|
1 'foo'
|
2 'bar'
|
EOF
|
One more possibility would be to implement the ALTER TABLE…DISABLE KEYS and ALTER TABLE…ENABLE KEYS for InnoDB, in a new way: DISABLE KEYS would basically mark the table ‘drop me on the next startup’, and ENABLE KEYS would mark the bulk insert completed. This might mean that old mysqldump output could be loaded faster. Until now, InnoDB has ignored those statements, so it could be a nasty surprise to users. Also, when undo logging is disabled, any attempt to insert a duplicate key to any index will result in the table being corrupted. Normally InnoDB would handle duplicates by rolling back the last inserted or updated row in every index.
The advantage of having an ALTER TABLE to a specific in memory format would be that it can be used by any DBA to get something similar to what is HEAP for MyISAM but that can overflow on disk.
What I wrote on 2017-01-17 still holds, except for one thing: All of this can be achieved with the existing SQL syntax. This should also allow efficient processing of mysqldump even with --skip-extended-insert, provided that the INSERT are delimited by BEGIN and COMMIT.
Like monty pointed out to me last week, an insert into an empty table or partition can be treated as a special case. The recovery would perform the equivalent of TRUNCATE; creating an empty table or partition.
All undo logging and redo logging
of the individual operations can be suppressed, and every index can be built using the bulk-loading mechanism. The only logging that would be needed is a special TRUNCATE_ON_ROLLBACK record in the undo log.
If the table or partition resides in the InnoDB system tablespace instead of an .ibd file, then we must write redo log for all page allocation operations, so that the pages can be freed when executing the TRUNCATE_ON_ROLLBACK.
When it comes to the logic that would enable a bulk-load path for ‘first insert into an empty table or partition’, there are some locking and concurrency considerations.
- The transaction may full well access and modify other tables or partitions, and may consist of multiple statements. The special insert is not necessarily the first operation of the transaction.
- As soon as we enable the bulk-load code path, we must acquire an exclusive lock on the table or partition, to prevent concurrent accesses from seeing garbage.
- During the bulk-load operation, non-locking reads from other transactions must be specially handled to return the empty set.
- If a read access (or UPDATE or DELETE operation) is detected from the transaction that triggered the bulk-load code path, we must finish the bulk-load and return to normal operation for the table.
- On transaction rollback (truncate) or commit, we will return to normal operation for the table.
It could be useful to implement an intermediate step: enhance the MDEV-11415 ALTER TABLE…ALGORITHM=COPY so that it uses the same code path as /the table-rebuilding ALTER TABLE…ALGORITHM=INPLACE, that is, construct the indexes page by page, instead of constructing them record by record. This would have two main benefits:
- No redo logging (to work with hot backup, we may have to log full pages when they are flushed)
- No change buffering; entries for each index are merge sorted
Once this is done, a further step would be to implement the TRUNCATE undo logging and the table locking that are needed for implementing the bulk-loading code path for transactions that INSERT into an empty table or partition.
Related note: For a multi-row insert into a non-empty table, the following could be done to improve data locality:
- Sort the records in PRIMARY KEY order.
- Write undo log records for rolling back the inserts.
- Insert the records into the PRIMARY KEY index. (This could be interleaved with the write of undo log records.)
- For each secondary index: Sort the records in the key order, then insert them to the index.
This would still allow a ROLLBACK (to the start of the multi-row insert, or further to the past). Compared to the current single-row insert interface, we would access each secondary index in key order, instead of using a random order.
MDEV-12288 increased the cost of INSERT by making the purge of history take care of resetting DB_TRX_ID after the commit of the INSERT transaction is visible in the oldest active read view.
For speeding up those cases where the table or partition is not empty to begin with, perhaps we should introduce a special, exclusive, table lock mode that would allow data to be inserted with DB_TRX_ID=0, so that purge will have no work to do? The table lock would need to prevent any concurrent access, including MVCC reads. Both the implicit record locking and MVCC reads are based on DB_TRX_ID pointing to an active transaction, and that would be broken.
For INSERT IGNORE, we must be able to roll back the last inserted row. Only for an INSERT without IGNORE, we can pre-sort the data for all indexes.
For speeding up INSERT IGNORE into an empty table or partition, we can still do the following:
- Exclusively lock the table or partition(s). Mark them somehow, so that purge and MVCC reads will stay away until commit.
- Write an undo log record for truncating the table on rollback.
- Process rows one by one at ha_innobase::write_row(). We may use a single mini-transaction for updating all indexes. Insert all records with DB_TRX_ID=0.
- If a UNIQUE or FOREIGN KEY constraint is violated in any index, roll back the insert in all preceding indexes, without referring to undo log (which we did not write).
- Mark the transaction as committed.
For MVCC reads, will we need something like dict_table_t::load_trx_id. Any MVCC read older than that ID must see an empty table. Anything newer must access the table data and use the normal MVCC rules. This ID should survive table eviction. We can reset the field once the purge view (and the oldest active read view) has advanced past that transaction ID.
I think that we must seriously consider ignoring
SET unique_checks=0; |
in InnoDB altogether. As far as I understand, the motivation was to allow faster load of data dumps by allowing the user of change buffer even for unique secondary indexes. If InnoDB uses the opportunity, it may corrupt the data. With this task, the load into an empty table or partition would never use the change buffer, and we would detect duplicates while pre-sorting the records for each index.
This would involve removing the following code:
if (!thr_get_trx(thr)->check_unique_secondary) { |
search_mode |= BTR_IGNORE_SEC_UNIQUE;
|
}
|
as well as all references to check_unique_secondary, BTR_IGNORE_SEC_UNIQUE, and the second parameter of ibuf_should_try().
Some notes from discussion with thiru:
- We must ensure that dict_table_t::stat_n_rows is 0 if and only if the table is empty and history fully purged (no records, not even delete-marked ones).
- At the start of an insert, possibly in ha_innobase::write_row(), we would determine whether the new logic can be enabled, by checking m_prebuilt->table->stat_n_rows == 0.
- We might introduce data member in ha_innobase to allow ha_innobase::write_row() to determine whether the bulk insert code path is enabled.
- When the bulk insert code path becomes enabled, we will exclusively lock the dict_table_t until the end of the transaction. This will not block concurrent MVCC (which must see the table as empty), but will block other writers.
- If FOREIGN KEY constraints exist, those must be enforced also in the bulk insert code path. (This only involves checking that the rows exist in parent tables.)
- Any other operation for the table in the same transaction than a plain INSERT will enable full row-level undo logging for the table until the end of the transaction. Such operations include UPDATE, DELETE, SAVEPOINT but not necessarily SELECT.
It seems to me that we cannot support the bulk insert for REPLACE or INSERT IGNORE. The reason is that without row-level undo logging and sequential row-by-row processing, we will be unable to resolve a uniqueness violation in a compatible way. It is possible to optimize these operations (like I outlined for INSERT IGNORE in a previous comment), but I would not do it as part of this task.
origin/bb-10.5-MDEV-515 36606accdd2ffd38a0c13d6e6bf3833961a6100d 2020-11-20
shows some serious progress compared to the previous version of bb-10.5-MDEV-515.
Issues observed:
1. The restart after intentional crash asserts
mysqld: /Server/bb-10.5-MDEV-515A/storage/innobase/row/row0uins.cc:87: dberr_t row_undo_ins_remove_clust_rec(undo_node_t*): Assertion `lock_table_has_locks(index->table)' failed.
sdp:/RQG/storage/1605894262/TBR-774/dev/shm/vardir/1605894262/27/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio
2. mysqld: /Server/bb-10.5-MDEV-515A/storage/innobase/buf/buf0buf.cc:3442: buf_block_t* buf_page_get_low(page_id_t, ulint, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*, bool): Assertion `mode == 16 || mode == 12 || fix_block->page.status != buf_page_t::FREED' failed. This looks like the fixed MDEV-22710.
sdp:/RQG/storage/1605894262/TBR-776/dev/shm/vardir/1605894262/91/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio
origin/bb-10.6-MDEV-515 a1489a081eb9874f21998e9b178ffc1d42791b99 2020-12-13T20:06:25+05:30
|
|
|
mysqld: storage/innobase/btr/btr0cur.cc:7253: dberr_t btr_store_big_rec_extern_fields(btr_pcur_t*, rec_offs*, const big_rec_t*, mtr_t*, blob_op): Assertion `rec_offs_any_extern(offsets)' failed.
|
...
|
Query: INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1771, 1771, 1771 - 1, REPEAT(SUBSTR(CAST( 1771 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1771 AS CHAR),1,1), @fill_amount) )
|
Status: KILL_TIMEOUT
|
sdp:/RQG/storage/1607953109/TBR-791/dev/shm/vardir/1607953109/255/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
|
|
mysqld: storage/innobase/include/ut0byte.h:71: void* ut_align_down(void*, size_t): Assertion `ptr' failed.
|
...
|
Query: UPDATE t1 SET col1 = NULL ORDER BY col1 DESC LIMIT 2
|
Status: KILL_TIMEOUT
|
sdp:/RQG/storage/1607953109/TBR-792/dev/shm/vardir/1607953109/105/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
|
|
Also hit
|
InnoDB: Failing assertion: prebuilt->trx->isolation_level == TRX_ISO_READ_UNCOMMITTED
|
Query: DELETE ...
|
Status: KILL_TIMEOUT
|
|
|
mysqld: storage/innobase/lock/lock0lock.cc:1601: void lock_rec_add_to_queue(unsigned int, const buf_block_t*, ulint, dict_index_t*, trx_t*, bool): Assertion `!other_lock' failed.
|
Some INSERT but this time without Status: KILL_TIMEOUT
|
origin/bb-10.6-MDEV-515 df0176ba475211f8ea961af9e265eefe33b12437 2020-12-14T23:26:47+05:30
|
The three bad effects from above were not observed again.
|
|
|
InnoDB: Assertion failure in file /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc line 4577
|
InnoDB: Failing assertion: rec
|
....
|
Query (0x62b000134238): SHOW ENGINE INNODB STATUS
|
Status: NOT_KILLED
|
sdp:/RQG/storage/1607970069/TBR-795/dev/shm/vardir/1607970069/43/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0
|
|
The current design is roughly as follows:
- If at the low level we notice that we are inserting into an empty table or partition, we will acquire an exclusive lock on the table and set table->bulk_trx_id.store(trx->id, std::memory_order_relaxed). A record TRX_UNDO_EMPTY will be written, and records will be written with DB_TRX_ID=0.
- Concurrent MVCC will check table->bulk_trx_id.load(std::memory_order_relaxed). If that field is 0 or the current read view was created after that transaction was committed, then all rows with DB_TRX_ID=0 will be visible. Else, the entire table will be treated as empty.
- The purge of TRX_UNDO_EMPTY or the rollback of TRX_UNDO_EMPTY will invoke table->bulk_trx_id.store(0, std::memory_order_relaxed).
- Inserts will for now use the normal DML code, inserting row by row in each index. Making use of BtrBulk (using merge sort and building indexes one page at a time) will be a separate task.
Patch is in bb-10.6-MDEV-515. Requested matthias to test it again. I addressed almost all of marko's review comments.
mysqld: /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0log.cc:354: void row_log_online_op(dict_index_t*, const dtuple_t*, trx_id_t): Assertion `dict_index_is_online_ddl(index)' failed.
|
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x000033fe633d9859 in __GI_abort () at abort.c:79
|
#2 0x000033fe633d9729 in __assert_fail_base (fmt=0x33fe6356f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x561aff667c00 "dict_index_is_online_ddl(index)",
|
file=0x561aff667420 "/Server/bb-10.6-MDEV-515B/storage/innobase/row/row0log.cc", line=354, function=<optimized out>) at assert.c:92
|
#3 0x000033fe633eaf36 in __GI___assert_fail (assertion=0x561aff667c00 "dict_index_is_online_ddl(index)", file=0x561aff667420 "/Server/bb-10.6-MDEV-515B/storage/innobase/row/row0log.cc", line=354,
|
function=0x561aff667aa0 "void row_log_online_op(dict_index_t*, const dtuple_t*, trx_id_t)") at assert.c:101
|
#4 0x0000561afdf77d7b in row_log_online_op (index=0x616003b75220, tuple=0x0, trx_id=0) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0log.cc:354
|
#5 0x0000561afe27f5b2 in dict_table_t::empty_table (this=0x618000261120, thr=0x61700016c8e8) at /Server/bb-10.6-MDEV-515B/storage/innobase/dict/dict0mem.cc:1422
|
#6 0x0000561afe3ddfd4 in row_undo_ins (node=0x61b000099320, thr=0x61700016c8e8) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0uins.cc:605
|
#7 0x0000561afdff32d1 in row_undo (node=0x61b000099320, thr=0x61700016c8e8) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0undo.cc:433
|
#8 0x0000561afdff37b3 in row_undo_step (thr=0x61700016c8e8) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0undo.cc:489
|
#9 0x0000561afde848ef in que_thr_step (thr=0x61700016c8e8) at /Server/bb-10.6-MDEV-515B/storage/innobase/que/que0que.cc:934
|
#10 0x0000561afde84ce2 in que_run_threads_low (thr=0x61700016c8e8) at /Server/bb-10.6-MDEV-515B/storage/innobase/que/que0que.cc:997
|
#11 0x0000561afde84ff3 in que_run_threads (thr=0x61700016c8e8) at /Server/bb-10.6-MDEV-515B/storage/innobase/que/que0que.cc:1030
|
#12 0x0000561afe09b27c in trx_t::rollback_low (this=0x640000046260, savept=0x0) at /Server/bb-10.6-MDEV-515B/storage/innobase/trx/trx0roll.cc:119
|
#13 0x0000561afe093f81 in trx_rollback_for_mysql_low (trx=0x640000046260) at /Server/bb-10.6-MDEV-515B/storage/innobase/trx/trx0roll.cc:186
|
#14 0x0000561afe0949b2 in trx_rollback_for_mysql (trx=0x640000046260) at /Server/bb-10.6-MDEV-515B/storage/innobase/trx/trx0roll.cc:216
|
#15 0x0000561afdbbb827 in innobase_rollback (hton=0x615000002b18, thd=0x62b00028b218, rollback_trx=true) at /Server/bb-10.6-MDEV-515B/storage/innobase/handler/ha_innodb.cc:4106
|
#16 0x0000561afd0a5bb3 in ha_rollback_trans (thd=0x62b00028b218, all=true) at /Server/bb-10.6-MDEV-515B/sql/handler.cc:2053
|
#17 0x0000561afcd10f42 in trans_rollback (thd=0x62b00028b218) at /Server/bb-10.6-MDEV-515B/sql/transaction.cc:372
|
#18 0x0000561afc8aa066 in mysql_execute_command (thd=0x62b00028b218) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:5531
|
#19 0x0000561afc8b9d55 in mysql_parse (thd=0x62b00028b218, rawbuf=0x62b000292238 "ROLLBACK /* E_R Thread33 QNO 347 CON_ID 51 */", length=46, parser_state=0x6ffe27c0) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:7881
|
#20 0x0000561afc890b2f in dispatch_command (command=COM_QUERY, thd=0x62b00028b218, packet=0x6290009ce219 " ROLLBACK /* E_R Thread33 QNO 347 CON_ID 51 */ ", packet_length=48) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:1816
|
#21 0x0000561afc88d9f5 in do_command (thd=0x62b00028b218) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:1348
|
#22 0x0000561afccce56f in do_handle_one_connection (connect=0x6080000881b8, put_in_cache=true) at /Server/bb-10.6-MDEV-515B/sql/sql_connect.cc:1410
|
#23 0x0000561afcccded8 in handle_one_connection (arg=0x6080000881b8) at /Server/bb-10.6-MDEV-515B/sql/sql_connect.cc:1312
|
#24 0x0000561afd9d0cbd in pfs_spawn_thread (arg=0x61500000fd18) at /Server/bb-10.6-MDEV-515B/storage/perfschema/pfs.cc:2201
|
#25 0x000059854cd00609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#26 0x000033fe634d6293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
|
pluto:/data/Results/1608652062/TBR-802/dev/shm/vardir/1608652062/137/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
|
|
Up till today I have not seen the same problem on actual 10.6.
|
|
origin/bb-10.6-MDEV-515 1ba84ee78118016067931aaa7553ef0533417b6e 2020-12-23T19:31:20+05:30
|
The crash from the previous comment was not seen again but
|
[rr 2687321 207698]mysqld: /Server/bb-10.6-MDEV-515B/storage/innobase/lock/lock0lock.cc:4823: dberr_t lock_rec_insert_check_and_lock(ulint, const rec_t*, buf_block_t*, dict_index_t*, que_thr_t*, mtr_t*, bool*): Assertion `lock_table_has(trx, index->table, LOCK_IX)' failed.
|
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x000016235c185859 in __GI_abort () at abort.c:79
|
#2 0x000016235c185729 in __assert_fail_base (fmt=0x16235c31b588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x559e3cfaa340 "lock_table_has(trx, index->table, LOCK_IX)",
|
file=0x559e3cfa3ce0 "/Server/bb-10.6-MDEV-515B/storage/innobase/lock/lock0lock.cc", line=4823, function=<optimized out>) at assert.c:92
|
#3 0x000016235c196f36 in __GI___assert_fail (assertion=0x559e3cfaa340 "lock_table_has(trx, index->table, LOCK_IX)", file=0x559e3cfa3ce0 "/Server/bb-10.6-MDEV-515B/storage/innobase/lock/lock0lock.cc", line=4823,
|
function=0x559e3cfaa120 "dberr_t lock_rec_insert_check_and_lock(ulint, const rec_t*, buf_block_t*, dict_index_t*, que_thr_t*, mtr_t*, bool*)") at assert.c:101
|
#4 0x0000559e3b7af6d2 in lock_rec_insert_check_and_lock (flags=0, rec=0x559e3f935063 "infimum", block=0x559e3f1324a0, index=0x6160032dd320, thr=0x621000291408, mtr=0x7fd21ccc4e30, inherit=0x7fd21ccc41c0)
|
at /Server/bb-10.6-MDEV-515B/storage/innobase/lock/lock0lock.cc:4823
|
#5 0x0000559e3bb94574 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7fd21ccc4a10, entry=0x617000272ca0, thr=0x621000291408, mtr=0x7fd21ccc4e30, inherit=0x7fd21ccc41c0) at /Server/bb-10.6-MDEV-515B/storage/innobase/btr/btr0cur.cc:3256
|
#6 0x0000559e3bb95fa8 in btr_cur_optimistic_insert (flags=0, cursor=0x7fd21ccc4a10, offsets=0x7fd21ccc4990, heap=0x7fd21ccc4970, entry=0x617000272ca0, rec=0x7fd21ccc49b0, big_rec=0x7fd21ccc4950, n_ext=1, thr=0x621000291408, mtr=0x7fd21ccc4e30)
|
at /Server/bb-10.6-MDEV-515B/storage/innobase/btr/btr0cur.cc:3509
|
#7 0x0000559e3b950516 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x6160032dd320, n_uniq=1, entry=0x617000272ca0, n_ext=0, thr=0x621000291408) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0ins.cc:2750
|
#8 0x0000559e3b952ec3 in row_ins_clust_index_entry (index=0x6160032dd320, entry=0x617000272ca0, thr=0x621000291408, n_ext=0) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0ins.cc:3222
|
#9 0x0000559e3b9538af in row_ins_index_entry (index=0x6160032dd320, entry=0x617000272ca0, thr=0x621000291408) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0ins.cc:3347
|
#10 0x0000559e3b954a20 in row_ins_index_entry_step (node=0x621000290ec0, thr=0x621000291408) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0ins.cc:3516
|
#11 0x0000559e3b95544a in row_ins (node=0x621000290ec0, thr=0x621000291408) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0ins.cc:3640
|
#12 0x0000559e3b9563e7 in row_ins_step (thr=0x621000291408) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0ins.cc:3775
|
#13 0x0000559e3b99eea0 in row_insert_for_mysql (mysql_rec=0x61a0002616b8 "\310\001", prebuilt=0x6210002905a0, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0mysql.cc:1426
|
#14 0x0000559e3b618a8e in ha_innobase::write_row (this=0x61d0008656b8, record=0x61a0002616b8 "\310\001") at /Server/bb-10.6-MDEV-515B/storage/innobase/handler/ha_innodb.cc:7366
|
#15 0x0000559e3ab1e9bf in handler::ha_write_row (this=0x61d0008656b8, buf=0x61a0002616b8 "\310\001") at /Server/bb-10.6-MDEV-515B/sql/handler.cc:7144
|
#16 0x0000559e3a22c5f7 in write_record (thd=0x62b000046218, table=0x6190004e2598, info=0x7fd21ccc6890, sink=0x0) at /Server/bb-10.6-MDEV-515B/sql/sql_insert.cc:2104
|
#17 0x0000559e3a224163 in mysql_insert (thd=0x62b000046218, table_list=0x62b0000624c0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
|
at /Server/bb-10.6-MDEV-515B/sql/sql_insert.cc:1099
|
#18 0x0000559e3a2eba06 in mysql_execute_command (thd=0x62b000046218) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:4439
|
#19 0x0000559e3a303d55 in mysql_parse (thd=0x62b000046218,
|
rawbuf=0x62b000062238 "INSERT INTO t3 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 - 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread2 QNO 171 CO"..., length=210,
|
parser_state=0x7fd21ccc77c0) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:7881
|
#20 0x0000559e3a2dab2f in dispatch_command (command=COM_QUERY, thd=0x62b000046218,
|
packet=0x629000028219 " INSERT INTO t3 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 - 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread2 QNO 171 C"...,
|
packet_length=212) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:1816
|
#21 0x0000559e3a2d79f5 in do_command (thd=0x62b000046218) at /Server/bb-10.6-MDEV-515B/sql/sql_parse.cc:1348
|
#22 0x0000559e3a71856f in do_handle_one_connection (connect=0x6080000032b8, put_in_cache=true) at /Server/bb-10.6-MDEV-515B/sql/sql_connect.cc:1410
|
#23 0x0000559e3a717ed8 in handle_one_connection (arg=0x6080000032b8) at /Server/bb-10.6-MDEV-515B/sql/sql_connect.cc:1312
|
#24 0x0000559e3b41acbd in pfs_spawn_thread (arg=0x61500000b718) at /Server/bb-10.6-MDEV-515B/storage/perfschema/pfs.cc:2201
|
#25 0x00003a1f32993609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#26 0x000016235c282293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
|
pluto:~/RQG5/storage/1608735138/TBR-575/dev/shm/vardir/1608735138/182/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
|
|
This problem was seen
|
- first time 2020-05-25 on bb-10.5-svoj-MDEV-22593
|
- never on some 10.<n>
|
- again 2020-12-14T10:21:10 bb-10.6-MDEV-515
|
- again 2020-11-20T09:44:22 bb-10.5-MDEV-515
|
- here (2020-12-23) bb-10.6-MDEV-515
|
Therefore I assume its a MDEV-515 issue.
|
There seems to be some heavy new problem. > 90% of all tests fail with
|
|
|
mysqld: /Server/bb-10.6-MDEV-515/storage/innobase/row/row0mysql.cc:1445: dberr_t row_insert_for_mysql(const byte*, row_prebuilt_t*, ins_mode_t): Assertion `node->state == 3 || node->state == 2' failed.
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x000055acb5f49859 in __GI_abort () at abort.c:79
|
#2 0x000055acb5f49729 in __assert_fail_base (fmt=0x55acb60df588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55acb3e67da0 "node->state == 3 || node->state == 2", file=0x55acb3e65fe0 "/Server/bb-10.6-MDEV-515/storage/innobase/row/row0mysql.cc",
|
line=1445, function=<optimized out>) at assert.c:92
|
#3 0x000055acb5f5af36 in __GI___assert_fail (assertion=0x55acb3e67da0 "node->state == 3 || node->state == 2", file=0x55acb3e65fe0 "/Server/bb-10.6-MDEV-515/storage/innobase/row/row0mysql.cc", line=1445,
|
function=0x55acb3e67b40 "dberr_t row_insert_for_mysql(const byte*, row_prebuilt_t*, ins_mode_t)") at assert.c:101
|
#4 0x000055acb276aaaf in row_insert_for_mysql (mysql_rec=0x619000451ac8 "\360\002", prebuilt=0x6210001d11a0, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.6-MDEV-515/storage/innobase/row/row0mysql.cc:1445
|
#5 0x000055acb23e47b0 in ha_innobase::write_row (this=0x61d0007a76b8, record=0x619000451ac8 "\360\002") at /Server/bb-10.6-MDEV-515/storage/innobase/handler/ha_innodb.cc:7366
|
#6 0x000055acb18ea9af in handler::ha_write_row (this=0x61d0007a76b8, buf=0x619000451ac8 "\360\002") at /Server/bb-10.6-MDEV-515/sql/handler.cc:7144
|
#7 0x000055acb0ff85e7 in write_record (thd=0x62b00013b218, table=0x619000451598, info=0x12590f255890, sink=0x0) at /Server/bb-10.6-MDEV-515/sql/sql_insert.cc:2104
|
#8 0x000055acb0ff0153 in mysql_insert (thd=0x62b00013b218, table_list=0x62b000142420, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /Server/bb-10.6-MDEV-515/sql/sql_insert.cc:1099
|
#9 0x000055acb10b79f6 in mysql_execute_command (thd=0x62b00013b218) at /Server/bb-10.6-MDEV-515/sql/sql_parse.cc:4439
|
#10 0x000055acb10cfd45 in mysql_parse (thd=0x62b00013b218, rawbuf=0x62b000142238 "INSERT INTO t1 (col1,col2,col3,col4) VALUES ( 2, 2, 2, REPEAT(CAST(2 - 1 AS CHAR(1)),@fill_amount)) /* E_R Thread9 QNO 6 CON_ID 24 */", length=133,
|
parser_state=0x12590f2567c0) at /Server/bb-10.6-MDEV-515/sql/sql_parse.cc:7881
|
#11 0x000055acb10a6b1f in dispatch_command (command=COM_QUERY, thd=0x62b00013b218, packet=0x6290006fe219 "INSERT INTO t1 (col1,col2,col3,col4) VALUES ( 2, 2, 2, REPEAT(CAST(2 - 1 AS CHAR(1)),@fill_amount)) /* E_R Thread9 QNO 6 CON_ID 24 */ ",
|
packet_length=134) at /Server/bb-10.6-MDEV-515/sql/sql_parse.cc:1816
|
#12 0x000055acb10a39e5 in do_command (thd=0x62b00013b218) at /Server/bb-10.6-MDEV-515/sql/sql_parse.cc:1348
|
#13 0x000055acb14e455f in do_handle_one_connection (connect=0x608000003438, put_in_cache=true) at /Server/bb-10.6-MDEV-515/sql/sql_connect.cc:1410
|
#14 0x000055acb14e3ec8 in handle_one_connection (arg=0x608000003438) at /Server/bb-10.6-MDEV-515/sql/sql_connect.cc:1312
|
#15 0x000055acb21e69df in pfs_spawn_thread (arg=0x61500000c118) at /Server/bb-10.6-MDEV-515/storage/perfschema/pfs.cc:2201
|
#16 0x000055acb5f0a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#17 0x000055acb6046293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
|
sdp:/RQG2/storage/1609752931/TBR-800/dev/shm/vardir/1609752931/10/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
The assert from above did not show up again. But now I got rare
|
# 2021-01-04 05:19:19 0x1cab5a88a300 InnoDB: Assertion failure in file /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc line 4596
|
# InnoDB: Failing assertion: rec
|
for a SHOW ENGINE INNODB STATUS
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x00007f4dc7b2b859 in __GI_abort () at abort.c:79
|
#2 0x00005645761d4cf3 in ut_dbg_assertion_failed (expr=0x56457764b400 "rec", file=0x56457764ece0 "/Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc", line=4596) at /Server/bb-10.6-MDEV-515A/storage/innobase/ut/ut0dbg.cc:60
|
#3 0x0000564575e59421 in lock_rec_validate_page (block=0x66e83e73ea60, latched=false) at /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc:4596
|
#4 0x0000564575e5a08f in lock_rec_block_validate (page_id=...) at /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc:4698
|
#5 0x0000564575e5a9e5 in lock_validate () at /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc:4762
|
#6 0x0000564575e56aea in lock_print_info_all_transactions (file=0x615000002d80) at /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc:4294
|
#7 0x000056457611d607 in srv_printf_innodb_monitor (file=0x615000002d80, nowait=0, trx_start_pos=0x1cab5a887840, trx_end=0x1cab5a887860) at /Server/bb-10.6-MDEV-515A/storage/innobase/srv/srv0srv.cc:856
|
#8 0x0000564575cf2e75 in innodb_show_status (hton=0x615000002b18, thd=0x62b000038218, stat_print=0x5645751c35a0 <stat_print(THD*, char const*, size_t, char const*, size_t, char const*, size_t)>)
|
at /Server/bb-10.6-MDEV-515A/storage/innobase/handler/ha_innodb.cc:15597
|
#9 0x0000564575cf350b in innobase_show_status (hton=0x615000002b18, thd=0x62b000038218, stat_print=0x5645751c35a0 <stat_print(THD*, char const*, size_t, char const*, size_t, char const*, size_t)>, stat_type=HA_ENGINE_STATUS)
|
at /Server/bb-10.6-MDEV-515A/storage/innobase/handler/ha_innodb.cc:15679
|
#10 0x00005645751c3bf1 in ha_show_status (thd=0x62b000038218, db_type=0x615000002b18, stat=HA_ENGINE_STATUS) at /Server/bb-10.6-MDEV-515A/sql/handler.cc:6523
|
#11 0x0000564574994c75 in mysql_execute_command (thd=0x62b000038218) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:4042
|
#12 0x00005645749afd45 in mysql_parse (thd=0x62b000038218, rawbuf=0x62b000069238 "SHOW ENGINE INNODB STATUS", length=25, parser_state=0x1cab5a8887c0) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:7881
|
#13 0x0000564574986b1f in dispatch_command (command=COM_QUERY, thd=0x62b000038218, packet=0x6290019a5219 "", packet_length=25) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:1816
|
#14 0x00005645749839e5 in do_command (thd=0x62b000038218) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:1348
|
#15 0x0000564574dc455f in do_handle_one_connection (connect=0x6080000036b8, put_in_cache=true) at /Server/bb-10.6-MDEV-515A/sql/sql_connect.cc:1410
|
#16 0x0000564574dc3ec8 in handle_one_connection (arg=0x608000003338) at /Server/bb-10.6-MDEV-515A/sql/sql_connect.cc:1312
|
#17 0x0000564575ac69df in pfs_spawn_thread (arg=0x61500000b218) at /Server/bb-10.6-MDEV-515A/storage/perfschema/pfs.cc:2201
|
#18 0x000039e70c1da609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#19 0x00007f4dc7c28293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
|
sdp:/RQG2/storage/1609761915/TBR-810/dev/shm/vardir/1609761915/31/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0
|
|
|
====================
|
Crash during CrashRecovery
|
# 2021-01-04T06:23:24 [3643335] | [rr 3970450 5721]2021-01-04 6:23:15 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=31844648,32232638
|
# 2021-01-04T06:23:24 [3643335] | [rr 3970450 9283]mysqld: /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc:3598: void lock_table_ix_resurrect(dict_table_t*, trx_t*): Assertion `!lock_table_other_has_incompatible( trx, 256U, table, LOCK_IX)' failed.
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x0000654b35335859 in __GI_abort () at abort.c:79
|
#2 0x0000654b35335729 in __assert_fail_base (fmt=0x654b354cb588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5595007c9da0 "!lock_table_other_has_incompatible( trx, 256U, table, LOCK_IX)",
|
file=0x5595007c5ce0 "/Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc", line=3598, function=<optimized out>) at assert.c:92
|
#3 0x0000654b35346f36 in __GI___assert_fail (assertion=0x5595007c9da0 "!lock_table_other_has_incompatible( trx, 256U, table, LOCK_IX)", file=0x5595007c5ce0 "/Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc", line=3598,
|
function=0x5595007c9d40 "void lock_table_ix_resurrect(dict_table_t*, trx_t*)") at assert.c:101
|
#4 0x00005594fefc9ed7 in lock_table_ix_resurrect (table=0x618000001d20, trx=0x6bc608beca50) at /Server/bb-10.6-MDEV-515A/storage/innobase/lock/lock0lock.cc:3598
|
#5 0x00005594ff31f9a6 in trx_resurrect_table_locks (trx=0x6bc608beca50, undo=0x612000006658) at /Server/bb-10.6-MDEV-515A/storage/innobase/trx/trx0trx.cc:636
|
#6 0x00005594ff3208dd in trx_resurrect (undo=0x612000006658, rseg=0x613000008558, start_time=1609770195, start_time_micro=3511233041922, rows_to_undo=0x7ffe5ef10db0, is_old_insert=false) at /Server/bb-10.6-MDEV-515A/storage/innobase/trx/trx0trx.cc:718
|
#7 0x00005594ff321004 in trx_lists_init_at_db_start () at /Server/bb-10.6-MDEV-515A/storage/innobase/trx/trx0trx.cc:779
|
#8 0x00005594ff2ab2d0 in srv_start (create_new_db=false) at /Server/bb-10.6-MDEV-515A/storage/innobase/srv/srv0start.cc:1458
|
#9 0x00005594fee266ed in innodb_init (p=0x615000002b18) at /Server/bb-10.6-MDEV-515A/storage/innobase/handler/ha_innodb.cc:3697
|
#10 0x00005594fe30bba5 in ha_initialize_handlerton (plugin=0x621000030810) at /Server/bb-10.6-MDEV-515A/sql/handler.cc:645
|
#11 0x00005594fdb452d8 in plugin_initialize (tmp_root=0x7ffe5ef146e0, plugin=0x621000030810, argc=0x559501fab200 <remaining_argc>, argv=0x615000000ff8, options_only=false) at /Server/bb-10.6-MDEV-515A/sql/sql_plugin.cc:1459
|
#12 0x00005594fdb47266 in plugin_init (argc=0x559501fab200 <remaining_argc>, argv=0x615000000ff8, flags=0) at /Server/bb-10.6-MDEV-515A/sql/sql_plugin.cc:1751
|
#13 0x00005594fd80066b in init_server_components () at /Server/bb-10.6-MDEV-515A/sql/mysqld.cc:4950
|
#14 0x00005594fd80265e in mysqld_main (argc=44, argv=0x615000000ff8) at /Server/bb-10.6-MDEV-515A/sql/mysqld.cc:5539
|
#15 0x00005594fd7ec14d in main (argc=43, argv=0x7ffe5ef16e18) at /Server/bb-10.6-MDEV-515A/sql/main.cc:25
|
(rr)
|
|
|
sdp:/RQG2/storage/1609761915/TBR-812/dev/shm/vardir/1609761915/60/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio # Fate of server during CrashRecovery
|
Unfortunately the rr trace of the server till SIGKILL is rotten (looks like problem in rr).
|
|
|
==============================
|
Workflow:
|
1. Start server, create initial data
|
2. DDL/DML load on server
|
3. During 2. is ongoing SIGKILL server process
|
4. Restart attempt with success
|
5. Run SELECTs on the tables
|
ERROR: SELECT * FROM `test`.`t5` FORCE INDEX (`uidx3`) WHERE `col_int` >= -9223372036854775808 OR `col_int` IS NULL OR `col_int` IS NOT NULL harvested 2013: Lost connection to MySQL server during query.
|
ASAN failure
|
|
|
# 2021-01-04T05:00:44 [2769017] | [rr 2843794 178443][rr 2843794 178447]==2843794==ERROR: AddressSanitizer: negative-size-param: (size=-6)
|
# 2021-01-04T05:00:44 [2769017] | [rr 2843794 178450][rr 2843794 187666] #0 0x3be60ff80fcd (/lib/x86_64-linux-gnu/libasan.so.5+0x67fcd)
|
# 2021-01-04T05:00:44 [2769017] | [rr 2843794 187811] #1 0x55711bd43a71 in row_mysql_pad_col(unsigned long, unsigned char*, unsigned long) /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0mysql.cc:353
|
# 2021-01-04T05:00:44 [2769017] | [rr 2843794 187942] #2 0x55711bdc9639 in row_sel_field_store_in_mysql_format_func(unsigned char*, mysql_row_templ_t const*, dict_index_t const*, unsigned long, unsigned char const*, unsigned long) /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:2732
|
# 2021-01-04T05:00:44 [2769017] | [rr 2843794 187947] #3 0x55711bdcba6e in row_sel_store_mysql_field /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:2962
|
# 2021-01-04T05:00:44 [2769017] | [rr 2843794 187949] #4 0x55711bdd1488 in row_search_idx_cond_check /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:3943
|
# 2021-01-04T05:00:44 [2769017] | [rr 2843794 187959] #5 0x55711bdda338 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:5266
|
...
|
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x00003be610b81859 in __GI_abort () at abort.c:79
|
#2 0x00003be6100446a2 in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
|
#3 0x00003be61004f24c in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
|
#4 0x00003be6100308ec in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
|
#5 0x00003be61002fdc2 in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
|
#6 0x00003be60ff8100c in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
|
#7 0x000055711bd43a72 in row_mysql_pad_col (mbminlen=1, pad=0x61a0002796cb "", len=18446744073709551610) at /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0mysql.cc:353
|
#8 0x000055711bdc963a in row_sel_field_store_in_mysql_format_func (dest=0x61a0002796c1 "1111111111", templ=0x618000077128, index=0x616001705320, field_no=1, data=0x2d2b715e2083 "1111111111\200", len=10)
|
at /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:2732
|
#9 0x000055711bdcba6f in row_sel_store_mysql_field (mysql_rec=0x61a0002796b8 "\377\001", prebuilt=0x62100091f1a0, rec=0x2d2b715e207f "\200", index=0x616001705320, offsets=0x44d51005dee0, field_no=1, templ=0x618000077128)
|
at /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:2962
|
#10 0x000055711bdd1489 in row_search_idx_cond_check (mysql_rec=0x61a0002796b8 "\377\001", prebuilt=0x62100091f1a0, rec=0x2d2b715e207f "\200", offsets=0x44d51005dee0) at /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:3943
|
#11 0x000055711bdda339 in row_search_mvcc (buf=0x61a0002796b8 "\377\001", mode=PAGE_CUR_GE, prebuilt=0x62100091f1a0, match_mode=0, direction=0) at /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0sel.cc:5266
|
#12 0x000055711b9cc052 in ha_innobase::index_read (this=0x61d0004fbab8, buf=0x61a0002796b8 "\377\001", key_ptr=0x621000921a00 "\001", key_len=5, find_flag=HA_READ_KEY_OR_NEXT) at /Server/bb-10.6-MDEV-515A/storage/innobase/handler/ha_innodb.cc:8562
|
#13 0x000055711aed6ddf in handler::index_read_map (this=0x61d0004fbab8, buf=0x61a0002796b8 "\377\001", key=0x621000921a00 "\001", keypart_map=1, find_flag=HA_READ_KEY_OR_NEXT) at /Server/bb-10.6-MDEV-515A/sql/handler.h:3797
|
#14 0x000055711aea6ddc in handler::ha_index_read_map (this=0x61d0004fbab8, buf=0x61a0002796b8 "\377\001", key=0x621000921a00 "\001", keypart_map=1, find_flag=HA_READ_KEY_OR_NEXT) at /Server/bb-10.6-MDEV-515A/sql/handler.cc:3123
|
#15 0x000055711aec1bde in handler::read_range_first (this=0x61d0004fbab8, start_key=0x61d0004fbbb8, end_key=0x0, eq_range_arg=false, sorted=true) at /Server/bb-10.6-MDEV-515A/sql/handler.cc:6190
|
#16 0x000055711ab9b371 in handler::multi_range_read_next (this=0x61d0004fbab8, range_info=0x44d51005ecc0) at /Server/bb-10.6-MDEV-515A/sql/multi_range_read.cc:516
|
#17 0x000055711ab9b7c2 in Mrr_simple_index_reader::get_next (this=0x61d0004fc0e0, range_info=0x44d51005ecc0) at /Server/bb-10.6-MDEV-515A/sql/multi_range_read.cc:553
|
#18 0x000055711aba5451 in DsMrr_impl::dsmrr_next (this=0x61d0004fbf90, range_info=0x44d51005ecc0) at /Server/bb-10.6-MDEV-515A/sql/multi_range_read.cc:1653
|
#19 0x000055711b9fcb24 in ha_innobase::multi_range_read_next (this=0x61d0004fbab8, range_info=0x44d51005ecc0) at /Server/bb-10.6-MDEV-515A/storage/innobase/handler/ha_innodb.cc:19408
|
#20 0x000055711b2c9c9d in QUICK_RANGE_SELECT::get_next (this=0x613000306480) at /Server/bb-10.6-MDEV-515A/sql/opt_range.cc:12251
|
#21 0x000055711b2fefd7 in rr_quick (info=0x62b0000c9180) at /Server/bb-10.6-MDEV-515A/sql/records.cc:403
|
#22 0x000055711a4d3de8 in READ_RECORD::read_record (this=0x62b0000c9180) at /Server/bb-10.6-MDEV-515A/sql/records.h:81
|
#23 0x000055711a7e4317 in join_init_read_record (tab=0x62b0000c90b8) at /Server/bb-10.6-MDEV-515A/sql/sql_select.cc:21573
|
#24 0x000055711a7dd36e in sub_select (join=0x62b0000c65e0, join_tab=0x62b0000c90b8, end_of_records=false) at /Server/bb-10.6-MDEV-515A/sql/sql_select.cc:20595
|
#25 0x000055711a7db73c in do_select (join=0x62b0000c65e0, procedure=0x0) at /Server/bb-10.6-MDEV-515A/sql/sql_select.cc:20145
|
#26 0x000055711a768491 in JOIN::exec_inner (this=0x62b0000c65e0) at /Server/bb-10.6-MDEV-515A/sql/sql_select.cc:4472
|
#27 0x000055711a765a7c in JOIN::exec (this=0x62b0000c65e0) at /Server/bb-10.6-MDEV-515A/sql/sql_select.cc:4252
|
#28 0x000055711a7699f6 in mysql_select (thd=0x62b0000bd218, tables=0x62b0000c4a98, fields=..., conds=0x62b0000c58f8, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x62b0000c65b0, unit=0x62b0000c13e0,
|
select_lex=0x62b0000c43b8) at /Server/bb-10.6-MDEV-515A/sql/sql_select.cc:4668
|
#29 0x000055711a73b5da in handle_select (thd=0x62b0000bd218, lex=0x62b0000c1318, result=0x62b0000c65b0, setup_tables_done_option=0) at /Server/bb-10.6-MDEV-515A/sql/sql_select.cc:417
|
#30 0x000055711a6a4b43 in execute_sqlcom_select (thd=0x62b0000bd218, all_tables=0x62b0000c4a98) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:6116
|
#31 0x000055711a693b05 in mysql_execute_command (thd=0x62b0000bd218) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:3820
|
#32 0x000055711a6afd45 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "SELECT * FROM `test`.`t5` FORCE INDEX (`uidx3`) WHERE `col_int` >= -9223372036854775808 OR `col_int` IS NULL OR `col_int` IS NOT NULL", length=133,
|
parser_state=0x44d5100607c0) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:7881
|
#33 0x000055711a686b1f in dispatch_command (command=COM_QUERY, thd=0x62b0000bd218, packet=0x6290000eb219 "", packet_length=133) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:1816
|
#34 0x000055711a6839e5 in do_command (thd=0x62b0000bd218) at /Server/bb-10.6-MDEV-515A/sql/sql_parse.cc:1348
|
#35 0x000055711aac455f in do_handle_one_connection (connect=0x6080000057b8, put_in_cache=true) at /Server/bb-10.6-MDEV-515A/sql/sql_connect.cc:1410
|
#36 0x000055711aac3ec8 in handle_one_connection (arg=0x6080000057b8) at /Server/bb-10.6-MDEV-515A/sql/sql_connect.cc:1312
|
#37 0x000055711b7c69df in pfs_spawn_thread (arg=0x61500000c618) at /Server/bb-10.6-MDEV-515A/storage/perfschema/pfs.cc:2201
|
#38 0x0000245d41411609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#39 0x00003be610c7e293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
|
sdp:/RQG2/storage/1609761915/TBR-811/dev/shm/vardir/1609761915/29/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio # Fate of server process after restart.
|
Unfortunately the rr trace of the server till SIGKILL is rotten (looks like problem in rr).
|
|
|
=================
|
sdp:/RQG3/storage/1609781811/000268.log shows a
|
mysqld: /Server/bb-10.6-MDEV-515A/storage/innobase/row/row0log.cc:3164: dberr_t row_log_table_apply(que_thr_t*, dict_table_t*, TABLE*, ut_stage_alter_t*, dict_table_t*): Assertion `error != DB_SUCCESS || clust_index->online_log->head.total == clust_index->online_log->tail.total' failed.
|
some ALTER TABLE gets hit by KILL_TIMEOUT
|
ERROR: The query ' CHECK TABLE t7 EXTENDED /* E_R Thread1 QNO 434 CON_ID 47 */ ' passed but has a result set line
|
# 2021-01-04T10:56:49 [3387484] ERROR: ->test.t7 check Warning InnoDB: Index 'MarVão_uidx3' contains 0 entries, should be 1.<-.
|
|
|
sdp:/RQG3/storage/1609781811/TBR-36/dev/shm/vardir/1609781811/149/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
The detection of this problem is rr event
|
[rr 3376457 388994]2021-01-04 10:56:49 47 [ERROR] InnoDB: Flagged corruption of `MarVão_uidx3` in table `test`.`t7` in CHECK TABLE; Wrong count
|
Please note that RQG reacts on that observation with killing the server process.
|
RQG testing on origin/bb-10.6-MDEV-515 855e3646893bad9c8cdbacc38563725579fd2b0d 2021-01-07T17:18:33+05:30
|
|
|
mysqld: /Server/bb-10.6-MDEV-515B/storage/innobase/row/row0row.cc:319: dtuple_t* row_build_index_entry_low(const dtuple_t*, const row_ext_t*, const dict_index_t*, mem_heap_t*, ulint): Assertion `f.col->ord_part' failed.
|
for an UPDATE being victim of Status: KILL_CONNECTION
|
sdp:/RQG3/storage/1610020807/TBR-814/dev/shm/vardir/1610020807/98/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
|
|
-------------
|
|
|
There was not a restart with crash recovery before the following issue
|
# 2021-01-07T04:49:33 [2655148] ERROR: The query ' CHECK TABLE t4 /* E_R Thread23 QNO 323 CON_ID 191 */ ' passed but has a result set line
|
# 2021-01-07T04:49:33 [2655148] ERROR: ->test.t4 check Warning InnoDB: Index 'FTS_DOC_ID_INDEX' contains 0 entries, should be 1.<-.
|
# 2021-01-07T04:49:33 [2655148] ERROR: Will set status STATUS_DATABASE_CORRUPTION.
|
RQG reacts with killing the server.
|
sdp:/RQG3/storage/1610020807/TBR-36/dev/shm/vardir/1610020807/50/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
|
origin/bb-10.6-MDEV-515 cb9dfe91928cdf852a8588155adcf22adf54e71f 2021-01-08T17:00:55+05:30
|
performed well during RQG testing (~6500 tests).
|
I think that we must protect the dict_table_t::bulk_trx_id as follows:
/** Last transaction that inserted into an empty table. |
Updated while holding exclusive table lock and an exclusive
|
latch on the clustered index root page (which must also be
|
an empty leaf page), and an ahi_latch (if btr_search_enabled). */
|
Atomic_relaxed<trx_id_t> bulk_trx_id;
|
I think that we must test this also with innodb_adaptive_hash_index=ON.
We have some early checks (shortcuts) for this field, but I think that we must re-check dict_table_t::bulk_trx_id while holding a leaf page latch in the clustered index. Only in that way, a race condition with row_ins_clust_index_entry_low() (which assigns the bulk_trx_id) can be avoided.
I observed ASAN-reported memory leaks in the tests innodb.ddl_purge and main.innodb_mysql_sync.
Everything else now looks OK to me, except the missing checks for index->table->bulk_trx_id. I now believe that this check must be applied to reads of any index pages, not only clustered index pages, because we can perform covering-index reads in secondary indexes without visiting the clustered index at all.
I believe that there currently is a hard-to-reproduce race condition where an INSERT is initiated between the early check and the time that a MVCC read reads an index page. That is, an MVCC read could wrongly return records, even though it is supposed to see an empty table.
It should suffice to check when first latching a leaf page, but we might also check after fetching any index page (also internal pages). By design, it is unnecessary to check the flag when moving to the right sibling leaf page.
It turned out that the check for bulk_trx_id in row_search_mvcc() was executed while holding an index leaf page latch, and no race condition is possible. Some checks were missing in other places (in particular, adaptive hash index lookups).
During my performance test, it turned out that a TRX_UNDO_EMPTY record is being inserted for every single record that is being written to the table by the INSERT statement. This will make ROLLBACK extremely slow, because the indexes will be rebuilt several times. This part of the code needs to be adjusted.
Furthermore, the logic related to trx->mod_tables must be checked, because until now, we did not write information about temporary tables there. Yet, it seems that the bulk insert logic will be enabled for temporary tables as well. I will investigate these deeper and try to fix them tomorrow.
I think that we must rewrite some of the trx->mod_tables logic and properly support partial rollback (clear the "bulk-insert-ness" mode). I am working on that; some tests still fail. While testing on a non-debug build, I also noticed that the bulk insert was being disabled on TEMPORARY TABLE. There is no good reason for that. I used the following benchmark:
--source include/have_innodb.inc
|
--source include/have_sequence.inc
|
--source include/not_debug.inc
|
|
|
SET @freq=@@GLOBAL.innodb_purge_rseg_truncate_frequency; |
SET GLOBAL innodb_purge_rseg_truncate_frequency=1; |
|
|
CREATE TABLE t (a INT PRIMARY KEY, b CHAR(255) CHARACTER SET utf8) |
ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
|
|
|
let $n=1000000;
|
|
|
--source include/wait_all_purged.inc
|
SET profiling_history_size=100; |
SET profiling = 1; |
SELECT variable_value INTO @old_lsn FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
BEGIN; |
eval INSERT INTO t(a) SELECT * FROM seq_1_to_$n; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
ROLLBACK; |
SET @old_lsn=@lsn; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
SELECT * FROM t; |
|
|
eval INSERT INTO t(a) SELECT * FROM seq_1_to_$n; |
--source include/wait_all_purged.inc
|
SET @old_lsn=@lsn; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
TRUNCATE TABLE t; |
--source include/wait_all_purged.inc
|
SET @old_lsn=@lsn; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
BEGIN; |
eval INSERT INTO t SET a=$n; |
--error ER_DUP_ENTRY
|
eval INSERT INTO t(a) SELECT * FROM seq_1_to_$n; |
SELECT * FROM t; |
ROLLBACK; |
SELECT * FROM t; |
SET @old_lsn=@lsn; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
SHOW PROFILES;
|
SET profiling = 0; |
DROP TABLE t; |
SET GLOBAL innodb_purge_rseg_truncate_frequency=@freq; |
If I change the CREATE TABLE to CREATE TEMPORARY TABLE, no log will be written and purge should not take any time (it already is very fast, thanks to this change).
The very last INSERT will trigger a statement rollback due to a duplicate key error (the very last row will clash with the value that was inserted by the first statement). For both temporary and persistent tables, that operation will take more than twice the time of a similar successful insert (on my system on RAM disk, about 22 seconds, compared to 7.7 seconds for an INSERT to an empty table). For a persistent table, the last INSERT will write more than twice the amount of redo log too. The overhead comes from writing and rolling back 1,000,000 undo log records. With MDEV-24621, the bulk insert should become even faster and write less log.
A ROLLBACK of an INSERT is slower than an INSERT also in plain 10.6 before this change. Here are the results for the first transaction:
| statement | 10.6 time | opt time | 10.6 log/bytes | opt log/bytes |
|---|---|---|---|---|
| INSERT | 9.3 | 7.7s | 840,093,108 | 823,538,089 |
| ROLLBACK | 12.2s | 0.003s | 54,040,170 | 71,371 |
Note: The table is intentionally bloated by the 767-byte column. In ROW_FORMAT=REDUNDANT, space will be reserved also for NULL values.
A benchmark that inserts 1,000,000 rows into a smaller table will better highlight the difference due to undo logging:
CREATE TABLE t (a INT PRIMARY KEY) ENGINE=InnoDB; |
| logging+locking | INSERT+ROLLBACK time | log/bytes |
|---|---|---|
| row | 13.47s | 78,784,783 |
| table | 3.75s | 26,909,929 |
Another benchmark (triggering a statement rollback on the very last row):
CREATE TABLE t (a INT PRIMARY KEY) ENGINE=InnoDB; |
--error ER_DUP_ENTRY
|
INSERT INTO t SELECT seq&1048575 FROM seq_0_to_1048576; |
BEGIN; |
INSERT INTO t SET a=0; |
--error ER_DUP_ENTRY
|
INSERT INTO t SELECT seq&1048575 FROM seq_1_to_1048576; |
ROLLBACK; |
DROP TABLE t; |
| logging+locking | INSERT+ROLLBACK time | log/bytes |
|---|---|---|
| row | 13.78s | 58,100,452 |
| table | 3.84s | 28,217,909 |
The full benchmark script for that is below:
--source include/have_innodb.inc
|
--source include/have_sequence.inc
|
--source include/not_debug.inc
|
|
|
CREATE TABLE t (a INT PRIMARY KEY) ENGINE=InnoDB; |
|
|
SET profiling_history_size=100; |
SET profiling = 1; |
SELECT variable_value INTO @old_lsn FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
--error ER_DUP_ENTRY
|
INSERT INTO t(a) SELECT seq&1048575 FROM seq_0_to_1048576; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
SET @old_lsn=@lsn; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
BEGIN; |
INSERT INTO t SET a=0; |
--error ER_DUP_ENTRY
|
INSERT INTO t(a) SELECT seq&1048575 FROM seq_1_to_1048576; |
ROLLBACK; |
|
|
SET @old_lsn=@lsn; |
SELECT (@lsn:= variable_value)-@old_lsn |
FROM INFORMATION_SCHEMA.GLOBAL_STATUS |
WHERE variable_name = 'INNODB_LSN_CURRENT'; |
|
|
SHOW PROFILES;
|
SET profiling = 0; |
DROP TABLE t; |
origin/bb-10.6-MDEV-515 bc9bc89b4275fe963d24d90de3c72bb01871f33f 2021-01-21T17:01:09+02:00
|
|
|
mysqld: /Server/bb-10.6-MDEV-515D/storage/innobase/btr/btr0cur.cc:3524: dberr_t btr_cur_optimistic_insert(ulint, btr_cur_t*, rec_offs**, mem_heap_t**, dtuple_t*, rec_t**, big_rec_t**, ulint, que_thr_t*, mtr_t*): Assertion `thr->graph->trx->id == trx_read_trx_id( static_cast<const byte*>( trx_id->data)) || static_cast<ins_node_t*>( thr->run_node)->bulk_insert' failed.
|
Query (0x62b0000a1238): INSERT LOW_PRIORITY IGNORE INTO `view_table2_innodb_key_pk_parts_2_int_autoinc` ( `pk` ) SELECT `col_int_key` FROM `view_table2_innodb_key_pk_parts_2_int_autoinc` AS X ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 6
|
Status: NOT_KILLED
|
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x00001c9651cad859 in __GI_abort () at abort.c:79
|
#2 0x00001c9651cad729 in __assert_fail_base (fmt=0x1c9651e43588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
|
assertion=0x56513cb12240 "thr->graph->trx->id == trx_read_trx_id( static_cast<const byte*>( trx_id->data)) || static_cast<ins_node_t*>( thr->run_node)->bulk_insert", file=0x56513cb0e1e0 "/Server/bb-10.6-MDEV-515D/storage/innobase/btr/btr0cur.cc", line=3524,
|
function=<optimized out>) at assert.c:92
|
#3 0x00001c9651cbef36 in __GI___assert_fail (assertion=0x56513cb12240 "thr->graph->trx->id == trx_read_trx_id( static_cast<const byte*>( trx_id->data)) || static_cast<ins_node_t*>( thr->run_node)->bulk_insert",
|
file=0x56513cb0e1e0 "/Server/bb-10.6-MDEV-515D/storage/innobase/btr/btr0cur.cc", line=3524, function=0x56513cb11dc0 "dberr_t btr_cur_optimistic_insert(ulint, btr_cur_t*, rec_offs**, mem_heap_t**, dtuple_t*, rec_t**, big_rec_t**, ulint, que_thr_t*, mtr_t*)")
|
at assert.c:101
|
#4 0x000056513b4b3b6e in btr_cur_optimistic_insert (flags=0, cursor=0x7fd49cd76090, offsets=0x7fd49cd76010, heap=0x7fd49cd75ff0, entry=0x6170002606a0, rec=0x7fd49cd76030, big_rec=0x7fd49cd75fd0, n_ext=0, thr=0x6250001c49a0, mtr=0x7fd49cd764b0)
|
at /Server/bb-10.6-MDEV-515D/storage/innobase/btr/btr0cur.cc:3524
|
#5 0x000056513b26714b in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x616000b52420, n_uniq=1, entry=0x6170002606a0, n_ext=0, thr=0x6250001c49a0) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:2776
|
#6 0x000056513b269af8 in row_ins_clust_index_entry (index=0x616000b52420, entry=0x6170002606a0, thr=0x6250001c49a0, n_ext=0) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3248
|
#7 0x000056513b26a4e4 in row_ins_index_entry (index=0x616000b52420, entry=0x6170002606a0, thr=0x6250001c49a0) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3373
|
#8 0x000056513b26b655 in row_ins_index_entry_step (node=0x6210006fb268, thr=0x6250001c49a0) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3542
|
#9 0x000056513b26c130 in row_ins (node=0x6210006fb268, thr=0x6250001c49a0) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3688
|
#10 0x000056513b26d2b5 in row_ins_step (thr=0x6250001c49a0) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3830
|
#11 0x000056513b2b757f in row_insert_for_mysql (mysql_rec=0x6190005a7e10 "\377", ' ' <repeats 12 times>, prebuilt=0x6210006fa5a0, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0mysql.cc:1427
|
#12 0x000056513af300fc in ha_innobase::write_row (this=0x61d000b874b8, record=0x6190005a7e10 "\377", ' ' <repeats 12 times>) at /Server/bb-10.6-MDEV-515D/storage/innobase/handler/ha_innodb.cc:7339
|
#13 0x000056513a435745 in handler::ha_write_row (this=0x61d000b874b8, buf=0x6190005a7e10 "\377", ' ' <repeats 12 times>) at /Server/bb-10.6-MDEV-515D/sql/handler.cc:7151
|
#14 0x000056513ace7c32 in ha_partition::write_row (this=0x61d000b86ab8, buf=0x6190005a7e10 "\377", ' ' <repeats 12 times>) at /Server/bb-10.6-MDEV-515D/sql/ha_partition.cc:4445
|
#15 0x000056513a435745 in handler::ha_write_row (this=0x61d000b86ab8, buf=0x6190005a7e10 "\377", ' ' <repeats 12 times>) at /Server/bb-10.6-MDEV-515D/sql/handler.cc:7151
|
#16 0x0000565139b42038 in write_record (thd=0x62b00009a218, table=0x6190005a7898, info=0x6290017053b0, sink=0x0) at /Server/bb-10.6-MDEV-515D/sql/sql_insert.cc:2106
|
#17 0x0000565139b53037 in select_insert::send_data (this=0x629001705360, values=...) at /Server/bb-10.6-MDEV-515D/sql/sql_insert.cc:4076
|
#18 0x0000565139d954d9 in select_result_sink::send_data_with_check (this=0x629001705360, items=..., u=0x62b00009e3e0, sent=2) at /Server/bb-10.6-MDEV-515D/sql/sql_class.h:5376
|
#19 0x0000565139d50576 in end_send (join=0x629001705420, join_tab=0x629001708a70, end_of_records=false) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:21794
|
#20 0x0000565139d4898a in evaluate_join_record (join=0x629001705420, join_tab=0x6290017086c0, error=0) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:20817
|
#21 0x0000565139d86cd6 in AGGR_OP::end_send (this=0x629001709510) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:28906
|
#22 0x0000565139d46118 in sub_select_postjoin_aggr (join=0x629001705420, join_tab=0x6290017086c0, end_of_records=true) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:20304
|
#23 0x0000565139d46acb in sub_select (join=0x629001705420, join_tab=0x629001708310, end_of_records=true) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:20539
|
#24 0x0000565139d455f8 in do_select (join=0x629001705420, procedure=0x0) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:20143
|
#25 0x0000565139cd235f in JOIN::exec_inner (this=0x629001705420) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:4472
|
#26 0x0000565139ccf94a in JOIN::exec (this=0x629001705420) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:4252
|
#27 0x0000565139cd38c4 in mysql_select (thd=0x62b00009a218, tables=0x62b0000a25c8, fields=..., conds=0x0, og_num=5, order=0x62b0000a3698, group=0x0, having=0x0, proc_param=0x0, select_options=2202245794560, result=0x629001705360, unit=0x62b00009e3e0,
|
select_lex=0x62b0000a1e88) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:4668
|
#28 0x0000565139ca54a8 in handle_select (thd=0x62b00009a218, lex=0x62b00009e318, result=0x629001705360, setup_tables_done_option=1073741824) at /Server/bb-10.6-MDEV-515D/sql/sql_select.cc:417
|
#29 0x0000565139c02d96 in mysql_execute_command (thd=0x62b00009a218) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:4594
|
#30 0x0000565139c19c13 in mysql_parse (thd=0x62b00009a218,
|
rawbuf=0x62b0000a1238 "INSERT LOW_PRIORITY IGNORE INTO `view_table2_innodb_key_pk_parts_2_int_autoinc` ( `pk` ) SELECT `col_int_key` FROM `view_table2_innodb_key_pk_parts_2_int_autoinc` AS X ORDER BY `col_char_12`,`col_char"..., length=281,
|
parser_state=0x7fd49cd797c0) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:7901
|
#31 0x0000565139bf08f1 in dispatch_command (command=COM_QUERY, thd=0x62b00009a218,
|
packet=0x629000159219 "INSERT LOW_PRIORITY IGNORE INTO `view_table2_innodb_key_pk_parts_2_int_autoinc` ( `pk` ) SELECT `col_int_key` FROM `view_table2_innodb_key_pk_parts_2_int_autoinc` AS X ORDER BY `col_char_12`,`col_char"..., packet_length=282)
|
at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:1833
|
#32 0x0000565139bed7b7 in do_command (thd=0x62b00009a218) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:1365
|
#33 0x000056513a02eea1 in do_handle_one_connection (connect=0x608000003038, put_in_cache=true) at /Server/bb-10.6-MDEV-515D/sql/sql_connect.cc:1410
|
#34 0x000056513a02e80a in handle_one_connection (arg=0x608000002ab8) at /Server/bb-10.6-MDEV-515D/sql/sql_connect.cc:1312
|
#35 0x000056513ad3208d in pfs_spawn_thread (arg=0x61500000ad18) at /Server/bb-10.6-MDEV-515D/storage/perfschema/pfs.cc:2201
|
#36 0x00001c9651e96609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#37 0x00001c9651daa293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
|
pluto:/data/Results/1611246287/tmp1/dev/shm/vardir/1611246287/96/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0
|
mleich, I hope that I fixed the latest failure, by adding one more ‘statement boundary’ call to ha_innobase::external_lock(). That trace was modifying partitioned tables, and for some reason the ‘normal’ functions ha_innobase::start_stmt() and trx_mark_sql_stat_end() were not being invoked. It seemed to me that we wrongly remained in bulk insert mode across statement boundaries.
origin/bb-10.6-MDEV-515 1f760570ada0ccf9be3d09f2b4f17eba0a034715 2021-01-22T15:43:37+02:00
|
mysqld: /Server/bb-10.6-MDEV-515D/storage/innobase/include/ut0byte.h:71: void* ut_align_down(void*, size_t): Assertion `ptr' failed.
|
|
|
Query (0x62b000157238): INSERT INTO t7 (col1,col2, col_int, col_string, col_text) VALUES ( 2, 2 - 1, 2, REPEAT(SUBSTR(CAST( 2 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 2 AS CHAR),1,1), @fill_amount) )
|
Status: NOT_KILLED
|
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x000000006fe0a859 in __GI_abort () at abort.c:79
|
#2 0x000000006fe0a729 in __assert_fail_base (fmt=0x6ffa0588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55f88764f4e0 "ptr", file=0x55f88764f3c0 "/Server/bb-10.6-MDEV-515D/storage/innobase/include/ut0byte.h", line=71,
|
function=<optimized out>) at assert.c:92
|
#3 0x000000006fe1bf36 in __GI___assert_fail (assertion=0x55f88764f4e0 "ptr", file=0x55f88764f3c0 "/Server/bb-10.6-MDEV-515D/storage/innobase/include/ut0byte.h", line=71, function=0x55f88764f420 "void* ut_align_down(void*, size_t)")
|
at assert.c:101
|
#4 0x000055f885cf4bb6 in ut_align_down (ptr=0x0, alignment=4096) at /Server/bb-10.6-MDEV-515D/storage/innobase/include/ut0byte.h:71
|
#5 0x000055f885d65a1b in page_align (ptr=0x0) at /Server/bb-10.6-MDEV-515D/storage/innobase/include/page0page.h:203
|
#6 0x000055f885d65a41 in page_align (ptr=0x0) at /Server/bb-10.6-MDEV-515D/storage/innobase/include/page0page.h:207
|
#7 0x000055f885d65c76 in page_rec_is_comp (rec=0x0) at /Server/bb-10.6-MDEV-515D/storage/innobase/include/page0page.h:276
|
#8 0x000055f885ebd5f4 in page_rec_is_metadata (rec=0x0) at /Server/bb-10.6-MDEV-515D/storage/innobase/include/page0page.h:286
|
#9 0x000055f885ead42b in lock_rec_print (file=0x615000003280, lock=0x77b320c0eb50, mtr=...) at /Server/bb-10.6-MDEV-515D/storage/innobase/lock/lock0lock.cc:4024
|
#10 0x000055f885eb8f87 in DeadlockChecker::print (lock=0x77b320c0eb50) at /Server/bb-10.6-MDEV-515D/storage/innobase/lock/lock0lock.cc:5922
|
#11 0x000055f885eb9b4b in DeadlockChecker::notify (this=0x6400009af530, lock=0x77b320c09480) at /Server/bb-10.6-MDEV-515D/storage/innobase/lock/lock0lock.cc:6046
|
#12 0x000055f885ebaf3f in DeadlockChecker::search (this=0x6400009af530) at /Server/bb-10.6-MDEV-515D/storage/innobase/lock/lock0lock.cc:6168
|
#13 0x000055f885ebbd0e in DeadlockChecker::check_and_resolve (lock=0x77b320c09be8, trx=0x77b320c08f18) at /Server/bb-10.6-MDEV-515D/storage/innobase/lock/lock0lock.cc:6308
|
#14 0x000055f885ea90e3 in lock_table_enqueue_waiting (mode=3, table=0x618000043520, thr=0x62100068d318, c_lock=0x77b320c02440) at /Server/bb-10.6-MDEV-515D/storage/innobase/lock/lock0lock.cc:3326
|
#15 0x000055f885ea9e9c in lock_table (flags=0, table=0x618000043520, mode=LOCK_X, thr=0x62100068d318) at /Server/bb-10.6-MDEV-515D/storage/innobase/lock/lock0lock.cc:3475
|
#16 0x000055f8860508ee in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x616007345920, n_uniq=1, entry=0x6170004532a0, n_ext=0, thr=0x62100068d318) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:2675
|
#17 0x000055f886053d39 in row_ins_clust_index_entry (index=0x616007345920, entry=0x6170004532a0, thr=0x62100068d318, n_ext=0) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3260
|
#18 0x000055f886054725 in row_ins_index_entry (index=0x616007345920, entry=0x6170004532a0, thr=0x62100068d318) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3385
|
#19 0x000055f886055896 in row_ins_index_entry_step (node=0x62100068ce30, thr=0x62100068d318) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3554
|
#20 0x000055f886056371 in row_ins (node=0x62100068ce30, thr=0x62100068d318) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3700
|
#21 0x000055f8860574f6 in row_ins_step (thr=0x62100068d318) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:3842
|
#22 0x000055f8860a1759 in row_insert_for_mysql (mysql_rec=0x61a0000d92b8 "\350\002", prebuilt=0x62100068c5a0, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0mysql.cc:1427
|
#23 0x000055f885d1a26a in ha_innobase::write_row (this=0x61d0028bb8b8, record=0x61a0000d92b8 "\350\002") at /Server/bb-10.6-MDEV-515D/storage/innobase/handler/ha_innodb.cc:7339
|
#24 0x000055f88521f8b3 in handler::ha_write_row (this=0x61d0028bb8b8, buf=0x61a0000d92b8 "\350\002") at /Server/bb-10.6-MDEV-515D/sql/handler.cc:7151
|
#25 0x000055f88492c1a6 in write_record (thd=0x62b000150218, table=0x619000602c98, info=0x6400009b1890, sink=0x0) at /Server/bb-10.6-MDEV-515D/sql/sql_insert.cc:2106
|
#26 0x000055f884923c63 in mysql_insert (thd=0x62b000150218, table_list=0x62b0001574b8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
|
at /Server/bb-10.6-MDEV-515D/sql/sql_insert.cc:1099
|
#27 0x000055f8849eb928 in mysql_execute_command (thd=0x62b000150218) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:4448
|
#28 0x000055f884a03d81 in mysql_parse (thd=0x62b000150218,
|
rawbuf=0x62b000157238 "INSERT INTO t7 (col1,col2, col_int, col_string, col_text) VALUES ( 2, 2 - 1, 2, REPEAT(SUBSTR(CAST( 2 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 2 AS CHAR),1,1), @fill_amount) ) /* E_R Thread11 QNO 839 C"..., length=212,
|
parser_state=0x6400009b27c0) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:7901
|
#29 0x000055f8849daa5f in dispatch_command (command=COM_QUERY, thd=0x62b000150218,
|
packet=0x629000cd5219 " INSERT INTO t7 (col1,col2, col_int, col_string, col_text) VALUES ( 2, 2 - 1, 2, REPEAT(SUBSTR(CAST( 2 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 2 AS CHAR),1,1), @fill_amount) ) /* E_R Thread11 QNO 839 "...,
|
packet_length=214) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:1833
|
#30 0x000055f8849d7925 in do_command (thd=0x62b000150218) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:1365
|
#31 0x000055f884e1900f in do_handle_one_connection (connect=0x608000016db8, put_in_cache=true) at /Server/bb-10.6-MDEV-515D/sql/sql_connect.cc:1410
|
#32 0x000055f884e18978 in handle_one_connection (arg=0x6080000035b8) at /Server/bb-10.6-MDEV-515D/sql/sql_connect.cc:1312
|
#33 0x000055f885b1c1fb in pfs_spawn_thread (arg=0x61500000c618) at /Server/bb-10.6-MDEV-515D/storage/perfschema/pfs.cc:2201
|
#34 0x00002475467d4609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#35 0x000000006ff07293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
sdp:/home/mleich/RQG_O/storage/1611325638/TBR-792/dev/shm/vardir/1611325638/68/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio
|
|
The latest failure looks like MDEV-20605. The disappearing lock was created during a row rollback operation (not using the MDEV-515 code path). As noted in MDEV-20605, rollback or purge should actually never modify any locks.
mysqld: /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0log.cc:3029: dberr_t row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*): Assertion `mrec_end == index->online_log->tail.block + index->online_log->tail.bytes' failed.
(rr) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00005a3c7f2ec859 in __GI_abort () at abort.c:79
#2 0x00005a3c7f2ec729 in __assert_fail_base (fmt=0x5a3c7f482588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55d4f2933f60 "mrec_end == index->online_log->tail.block + index->online_log->tail.bytes",
file=0x55d4f292fb40 "/Server/bb-10.6-MDEV-515D/storage/innobase/row/row0log.cc", line=3029, function=<optimized out>) at assert.c:92
#3 0x00005a3c7f2fdf36 in _GI__assert_fail (assertion=0x55d4f2933f60 "mrec_end == index->online_log->tail.block + index->online_log->tail.bytes", file=0x55d4f292fb40 "/Server/bb-10.6-MDEV-515D/storage/innobase/row/row0log.cc", line=3029,
function=0x55d4f2933580 "dberr_t row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*)") at assert.c:101
#4 0x000055d4f1223863 in row_log_table_apply_ops (thr=0x61a0006ff1e8, dup=0x4fbf186c78a0, stage=0x60800004cbb8) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0log.cc:3029
#5 0x000055d4f12248de in row_log_table_apply (thr=0x61a0006ff1e8, old_table=0x6180000e4120, table=0x4fbf186c9210, stage=0x60800004cbb8, new_table=0x618000110920) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0log.cc:3151
#6 0x000055d4f0f0c0f5 in ha_innobase::inplace_alter_table (this=0x61d00025c6b8, altered_table=0x4fbf186c9210, ha_alter_info=0x4fbf186c8d30) at /Server/bb-10.6-MDEV-515D/storage/innobase/handler/handler0alter.cc:8429
#7 0x000055d4efde8480 in handler::ha_inplace_alter_table (this=0x61d00025c6b8, altered_table=0x4fbf186c9210, ha_alter_info=0x4fbf186c8d30) at /Server/bb-10.6-MDEV-515D/sql/handler.h:4515
#8 0x000055d4efdc80a0 in mysql_inplace_alter_table (thd=0x62b0000bd218, table_list=0x62b0000c43d8, table=0x619000022198, altered_table=0x4fbf186c9210, ha_alter_info=0x4fbf186c8d30, target_mdl_request=0x4fbf186c8e10, alter_ctx=0x4fbf186c9c70)
at /Server/bb-10.6-MDEV-515D/sql/sql_table.cc:8087
#9 0x000055d4efddb3aa in mysql_alter_table (thd=0x62b0000bd218, new_db=0x62b0000c1c88, new_name=0x62b0000c2088, create_info=0x4fbf186cb030, table_list=0x62b0000c43d8, alter_info=0x4fbf186caf20, order_num=0, order=0x0, ignore=false,
if_exists=false) at /Server/bb-10.6-MDEV-515D/sql/sql_table.cc:10683
#10 0x000055d4eff7a5e8 in Sql_cmd_alter_table::execute (this=0x62b0000c4bd0, thd=0x62b0000bd218) at /Server/bb-10.6-MDEV-515D/sql/sql_alter.cc:539
#11 0x000055d4efb3b387 in mysql_execute_command (thd=0x62b0000bd218) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:5875
#12 0x000055d4efb48d81 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "ALTER TABLE t3 ADD PRIMARY KEY ( col1 ), ALGORITHM = INPLACE /* E_R Thread2 QNO 430 CON_ID 132 */", length=98, parser_state=0x4fbf186cc7c0)
at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:7901
#13 0x000055d4efb1fa5f in dispatch_command (command=COM_QUERY, thd=0x62b0000bd218, packet=0x629001298219 " ALTER TABLE t3 ADD PRIMARY KEY ( col1 ), ALGORITHM = INPLACE /* E_R Thread2 QNO 430 CON_ID 132 */ ", packet_length=100)
at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:1833
#14 0x000055d4efb1c925 in do_command (thd=0x62b0000bd218) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:1365
#15 0x000055d4eff5e00f in do_handle_one_connection (connect=0x60800008eb38, put_in_cache=true) at /Server/bb-10.6-MDEV-515D/sql/sql_connect.cc:1410
#16 0x000055d4eff5d978 in handle_one_connection (arg=0x608000002bb8) at /Server/bb-10.6-MDEV-515D/sql/sql_connect.cc:1312
#17 0x000055d4f0c611fb in pfs_spawn_thread (arg=0x61500000ad18) at /Server/bb-10.6-MDEV-515D/storage/perfschema/pfs.cc:2201
#18 0x000076a74dedd609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#19 0x00005a3c7f3e9293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr)
sdp:/home/mleich/RQG_O/storage/1611325638/tmp1/dev/shm/vardir/1611325638/34/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio
The latest failure looks like a MDEV-515 specific race condition between row_log_table_apply() (ALTER TABLE applying log) and a rollback:
#3 0x000055d4f1073396 in inline_mysql_mutex_lock (that=0x55d4f4926700 <log_sys+256>, src_file=0x55d4f2858920 "/Server/bb-10.6-MDEV-515D/storage/innobase/mtr/mtr0mtr.cc", src_line=414) at /Server/bb-10.6-MDEV-515D/include/mysql/psi/mysql_thread.h:765
|
#4 0x000055d4f1074dc9 in mtr_t::commit (this=0x4fbf186c51c0) at /Server/bb-10.6-MDEV-515D/storage/innobase/mtr/mtr0mtr.cc:414
|
#5 0x000055d4f13fb974 in btr_store_big_rec_extern_fields (pcur=0x4fbf186c57c0, offsets=0x4fbf186c6150, big_rec_vec=0x61f000040d20, btr_mtr=0x4fbf186c5900, op=BTR_STORE_INSERT) at /Server/bb-10.6-MDEV-515D/storage/innobase/btr/btr0cur.cc:7521
|
#6 0x000055d4f1194469 in row_ins_index_entry_big_rec (entry=0x621000b8a710, big_rec=0x61f000040d20, offsets=0x4fbf186c6150, heap=0x4fbf186c5f70, index=0x6160074b2a20, thd=0x62b0000bd218) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:2520
|
#7 0x000055d4f1196602 in row_ins_clust_index_entry_low (flags=23, mode=33, index=0x6160074b2a20, n_uniq=1, entry=0x621000b8a710, n_ext=0, thr=0x61a0006ff1e8) at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0ins.cc:2826
|
…
|
#19 0x000055d4efb48d81 in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "ALTER TABLE t3 ADD PRIMARY KEY ( col1 ), ALGORITHM = INPLACE /* E_R Thread2 QNO 430 CON_ID 132 */", length=98, parser_state=0x4fbf186cc7c0) at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:7901
|
As we can see, the ALTER TABLE is waiting for log_sys.flush_order_mutex, and should be holding the page latches. At the same time, a ROLLBACK is writing a record:
#0 row_log_table_empty (index=0x616011c59620)
|
at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0log.cc:4069
|
#1 0x000055d4f0f20254 in dict_table_t::clear (this=0x6180000e4120,
|
thr=0x6170006b6d68)
|
at /Server/bb-10.6-MDEV-515D/storage/innobase/handler/handler0alter.cc:11521
|
#2 0x000055d4f1673adb in row_undo_ins (node=0x61b0001fb920,
|
thr=0x6170006b6d68)
|
at /Server/bb-10.6-MDEV-515D/storage/innobase/row/row0uins.cc:607
|
…
|
#15 0x000055d4efb48d81 in mysql_parse (thd=0x62b0001dc218,
|
rawbuf=0x62b0001e3238 "ROLLBACK /* E_R Thread19 QNO 471 CON_ID 37 */",
|
length=46, parser_state=0x7f58a1b6a7c0)
|
at /Server/bb-10.6-MDEV-515D/sql/sql_parse.cc:7901
|
It should be perfectly valid to invoke the dict_table_t::clear() on the original table. But, the problem appears to be that the ALTER TABLE thread is expecting to hold an exclusive latch on the index->lock of the being-rebuilt table. The caller of row_log_table_empty() is not holding index->lock at all! Furthermore, the function row_log_table_empty() is missing an assertion that would have caught this race condition:
diff --git a/storage/innobase/row/row0log.cc b/storage/innobase/row/row0log.cc
|
index 8548d552a10..4c00e9b280d 100644
|
--- a/storage/innobase/row/row0log.cc
|
+++ b/storage/innobase/row/row0log.cc
|
@@ -4061,6 +4061,7 @@ row_log_apply(
|
|
void row_log_table_empty(dict_index_t *index)
|
{
|
+ ut_ad(index->lock.have_any());
|
row_log_t* log= index->online_log;
|
ulint avail_size;
|
if (byte* b = row_log_table_open(log, 1, &avail_size)) |
The writes of the added ROW_OP_EMPTY record (during the build of secondary indexes) is being logged correctly, by row_log_online_op(). So, we only have to adjust the calls to row_log_table_empty().
Note: sysbench prepare appears to issue multiple INSERT statements to populate a table. Hence, it will not benefit from this optimization. Only if a transaction performs a single INSERT or LOAD statement in order to write into an empty table or partition, it will bypass the row-level locking and undo logging.
Note, that size of single INSERT statement is limited by the max_allowed_packet, which is 16MB by default.
If you keep the title, this super downgraded scope becomes highly misleading. Please update the title accordingly there's not a thing 'bulk' about this.
In MDEV-24818, my plan is to implement an opt-in mechanism for this, to allow faster processing of mysqldump output:
SET foreign_key_checks=0, unique_checks=0; |
A nicer mechanism will be provided in MDEV-25036.
When we require the user to explicitly enable the table-level locking and undo logging, we can cover multiple INSERT into an initially empty table.
In my opinion, the fact that we disable row-level undo logging and thus reduce the purge of history does make this a ‘bulk’ operation, even though the originally planned scope was reduced by filing MDEV-24621 for the final part.
Although I appreciate the intent. The original description talked about "generating" transportable tablespaces and that is a huge leap comparatively.
Imagine having to import 4TB (as we do today) it would have brought import speeds to another level.
noel.diaz, once MDEV-11658 changes the .ibd file format so that the combination of .frm and .ibd files will be self-descriptive and allows the files to be ‘attached’ instantly, we could implement the originally envisioned tool. Changing the file format requires significant engineering effort.
Could this be implemented pretty easily using libmysqld with a modified InnoDB that skips redo logging? The tool would allocate some (configurable) buffer pool and existing code could take care of flushing pages and building InnoDB structures.