Marko Mäkelä added a comment - 2020-02-14 06:36 The following test case, derived from main.sum_distinct-big , is showing a significant regression due to MDEV-12353 . It seems to be mostly explained by the increased redo log volume: --source include/have_innodb.inc --source include/have_sequence.inc show status like 'innodb_lsn_current' ; CREATE TABLE t2 ENGINE=InnoDB SELECT * FROM seq_1_to_2097152; show status like 'innodb_lsn_current' ; DROP TABLE t2; revision LSN1 LSN2-LSN1 time 10.5 ac51bcfd8d3b08b62d88350fd9de8ae43f7b1637 (before) 62,998 128,417,353 15.9s 10.5 f8a9f906679e1d1ab026c245f7d24c652050d8b3 (after MDEV-12353 ) 53,077 214,956,466 25.7s Because the perf report output was ‘polluted’ by PERFORMANCE_SCHEMA functions, I decided to rebuild with cmake -DPLUGIN_PERFSCHEMA_NO . I also disabled the concurrent purge activity ( MDEV-12288 ) to remove one source of nondeterminism: perf record ./mtr --mysqld=--innodb-force-recovery=2 main.ib revision LSN1 LSN2-LSN1 time 10.5 ac51bcfd8d3b08b62d88350fd9de8ae43f7b1637 (before) 60,516 128,417,675 14.9s 10.5 f8a9f906679e1d1ab026c245f7d24c652050d8b3 (after MDEV-12353 ) 51,149 215,006,904 23.9s The execution times include the perf record overhead. Here is the perf report output ( evaluate_join_record() and anything that consumed more time): 10.5 ac51bcfd8d3b08b62d88350fd9de8ae43f7b1637 (before) 12.02% mysqld [.] rec_get_offsets_func 9.36% mysqld [.] buf_page_get_gen 6.32% mysqld [.] cmp_dtuple_rec_with_match_low 6.31% mysqld [.] page_cur_search_with_match 6.30% mysqld [.] btr_cur_search_to_nth_level_func 2.99% mysqld [.] cmp_data 2.04% mysqld [.] row_ins_step 1.92% mysqld [.] mtr_t::commit 1.88% mysqld [.] trx_undo_report_row_operation 1.68% mysqld [.] page_cur_insert_rec_low 1.63% mysqld [.] row_ins_clust_index_entry_low 1.57% mysqld [.] rw_lock_x_lock_func 1.51% mysqld [.] btr_cur_optimistic_insert 1.39% mysqld [.] page_cur_insert_rec_write_log 1.26% mysqld [.] rw_lock_x_lock_wait_func 1.25% mysqld [.] rec_get_converted_size_comp 1.24% mysqld [.] ReleaseLatches::operator() 1.10% mysqld [.] mlog_open_and_write_index 1.00% mysqld [.] row_insert_for_mysql 1.00% mysqld [.] mtr_t::memo_push 1.00% mysqld [.] TTASEventMutex<GenericPolicy>::enter 0.98% mysqld [.] rec_convert_dtuple_to_rec_comp<false> 0.94% mysqld [.] ut_crc32_hw 0.83% mysqld [.] rw_lock_x_lock_low 0.82% mysqld [.] ReleaseBlocks::add_dirty_page_to_flush_list 0.82% mysqld [.] log_margin_checkpoint_age 0.78% mysqld [.] mtr_t::prepare_write 0.72% mysqld [.] TTASEventMutex<BlockMutexPolicy>::enter 0.70% mysqld [.] buf_LRU_remove_block 0.69% mysqld [.] mtr_t::release_block_at_savepoint 0.66% mysqld [.] lock_rec_insert_check_and_lock 0.66% mysqld [.] btr_node_ptr_max_size 0.63% mysqld [.] ha_seq::index_next 0.62% mysqld [.] mtr_t::finish_write 0.60% mysqld [.] handler::ha_index_next 0.59% mysqld [.] btr_cur_ins_lock_and_undo 0.58% mysqld [.] fill_record 0.57% mysqld [.] write_record 0.56% mysqld [.] page_cur_tuple_insert 0.53% mysqld [.] handler::ha_write_row 0.52% mysqld [.] row_mysql_store_col_in_innobase_format 0.52% mysqld [.] ha_innobase::write_row 0.50% mysqld [.] evaluate_join_record 10.5 f8a9f906679e1d1ab026c245f7d24c652050d8b3 (after) 10.03% mysqld [.] rec_get_offsets_func 9.41% mysqld [.] buf_page_get_gen 7.35% mysqld [.] page_cur_search_with_match 5.60% mysqld [.] btr_cur_search_to_nth_level_func 5.46% mysqld [.] cmp_dtuple_rec_with_match_low 3.44% mysqld [.] page_cur_insert_rec_low 3.29% mysqld [.] mtr_t::log_write<(unsigned char)48> 2.64% mysqld [.] cmp_data 2.01% mysqld [.] mtr_t::commit 1.94% mysqld [.] row_ins_step 1.92% mysqld [.] trx_undo_report_row_operation 1.84% mysqld [.] rec_get_converted_size_comp 1.64% mysqld [.] mtr_t::memcpy_low 1.49% mysqld [.] row_ins_clust_index_entry_low 1.47% mysqld [.] rw_lock_x_lock_func 1.40% mysqld [.] btr_cur_optimistic_insert 1.30% mysqld [.] rec_convert_dtuple_to_rec_comp<false> 1.17% mysqld [.] mtr_t::memo_push 1.16% mysqld [.] rw_lock_x_lock_wait_func 1.09% mysqld [.] ReleaseLatches::operator() 1.08% mysqld [.] ut_crc32_hw 1.03% mysqld [.] row_insert_for_mysql 0.81% mysqld [.] handler::ha_index_next 0.79% mysqld [.] TTASEventMutex<GenericPolicy>::enter 0.77% mysqld [.] ReleaseBlocks::add_dirty_page_to_flush_list 0.77% mysqld [.] btr_node_ptr_max_size 0.74% mysqld [.] rw_lock_x_lock_low 0.73% mysqld [.] lock_rec_insert_check_and_lock 0.71% mysqld [.] mtr_t::prepare_write 0.69% mysqld [.] log_margin_checkpoint_age 0.68% mysqld [.] TTASEventMutex<BlockMutexPolicy>::enter 0.60% mysqld [.] ha_innobase::write_row 0.57% mysqld [.] mtr_t::release_block_at_savepoint 0.55% mysqld [.] row_mysql_store_col_in_innobase_format 0.55% mysqld [.] btr_cur_ins_lock_and_undo 0.54% mysqld [.] buf_LRU_remove_block 0.54% mysqld [.] evaluate_join_record As expected, rec_get_offsets_func() was removed from the top, because we no longer call it when writing log for an insert. The function trx_undo_report_row_operation() is taking slightly more time, and mtr_t::log_write<WRITE>() and mtr_t::memcpy_low() are new entries related to the new redo log format. We also spend some more time on ut_crc32_hw() due to the 67% increase of redo log volume. With a single-row INSERT , there is no regression: --source include/have_innodb.inc CREATE TABLE t2 (a BIGINT ) ENGINE=InnoDB; show status like 'innodb_lsn_current' ; INSERT INTO t2 VALUES (1); show status like 'innodb_lsn_current' ; DROP TABLE t2; ./mtr --mysqld=--innodb-force-recovery=2 main.ib1 revision LSN1 LSN2-LSN1 before 61,792 204 after 52,361 175

Marko Mäkelä added a comment - 2020-02-17 16:16 I think that to highlight the impact of undo log and B-tree operations, it is better to use a variation of the test, so that updates of the DICT_HDR page will be avoided (they will be done even for TEMPORARY TABLE , until MDEV-19506 is fixed): --source include/have_innodb.inc --source include/have_sequence.inc show status like 'innodb_lsn_current' ; CREATE TABLE t2 (a INT PRIMARY KEY ) ENGINE=InnoDB; show status like 'innodb_lsn_current' ; INSERT INTO t2 SELECT * FROM seq_1_to_2097152; show status like 'innodb_lsn_current' ; DROP TABLE t2; Even if I disable the redo logging in btr_page_reorganize_low() , the log volume will not be reduced much. Similarly, there is very little impact of disabling logging in page_copy_rec_list_end_no_locks() , page_copy_rec_list_end() , page_copy_rec_list_start() . Once I disabled the logging for page_cur_insert_rec_low() , the redo log volume will be reduced by 72%. The rest is almost entirely attributed to trx_undo_page_set_next_prev_and_add() (writing an undo log record).

Marko Mäkelä added a comment - 2020-02-17 16:56 I disabled all other redo log sources and set a breakpoint on mtr_t::finish_write() . Most inserts are logged as 47‥55 bytes, and every time the page directory is split, the length can be as much as 80 bytes. The record payload is 5+4+6+7=22 bytes. We must typically update 4+2+4=10 page header bytes when the page directory does not grow. On about 20% of the cases, we must write at least 2+2+1 more bytes to grow the page directory, but this should be doable in much less than 80 bytes. One more idea, in addition to those mentioned in the Description, is that we could avoid writing leading zero bytes for DB_TRX_ID when the page already contains zeroes in that area. That would save space when the transaction ID fits in 32 bits or less. In the old format, MLOG_COMP_REC_INSERT is 30 bytes at the start of this test case (with small page numbers and transaction identifiers). We may have to introduce a special redo log record for inserting an index page record. That should fit in less than 30 bytes for 80% of the cases (not adjusting the page directory). Currently, we seem to be writing 60 bytes in the average, which is an 100% increase over the 30 bytes.

Marko Mäkelä added a comment - 2020-02-27 16:44 I posted some detailed log size statistics for a simple 2-row INSERT transaction in a comment in MDEV-12353 . Here are the statistics for the test case in this ticket again. Only the last line is new: revision LSN1 LSN2-LSN1 time 10.5 ac51bcfd8d3b08b62d88350fd9de8ae43f7b1637 (before MDEV-12353 ) 62,998 128,417,353 15.9s 10.5 f8a9f906679e1d1ab026c245f7d24c652050d8b3 (after MDEV-12353 ) 53,077 214,956,466 25.7s 10.5 8db623038f7158529e804e9607362939bff37337 (after MDEV-21724 ) 46,615 91,201,573 7.63s In our example, we are writing 29% less log for the 2,097,152-row INSERT and spending 52% less total time than before MDEV-12353 . Because log_write_up_to() is calculating log block checksums inside a mutex, even a small decrease in log size can greatly reduce the total execution time. In MDEV-14425 we will hopefully improve the log writing further, by only doing a memcpy() inside the mutex.

Marko Mäkelä added a comment - 2024-01-31 06:24 For the record, in MDEV-27774 after MDEV-14425 , also the memcpy() is done inside a shared log_sys.latch , that is, multiple threads executing mtr_t::commit() may concurrently copy their local log into log_sys.buf . An exclusive log_sys.latch would be acquired during a log checkpoint, to ensure that no writes are in progress.