Small Datum: regressions

Showing posts with label regressions. Show all posts

Thursday, August 8, 2024

MySQL regressions: delete vs InnoDB

The numbers below are the percentage of perf samples from a function and its callees and this is a proxy for CPU time. Here I used cycles as the HW counter with perf but I have more tests in progress to get flamegraphs with other counters. The flamegraphs are here.

I am curious about whether more data is written to the binlog per transaction with 8.0.37, but I have to repeat tests to get that data. While my helper scripts archive results from SHOW GLOBAL STATUS which provides the Binlog_bytes_written counter, that counter is only in MariaDB and Percona Server. For upstream MySQL I have to use this much more fun query to get the answer from the perf schema.

select SUM_NUMBER_OF_BYTES_WRITE from file_summary_by_event_name where EVENT_NAME="wait/io/file/sql/binlog"

Time is spent in background and foreground work. The background work are mostly purge and writeback. The foreground work is networking, SQL and binlog. At a high level the percentage of time in SQL + binlog is about 2X larger with MySQL 8.0.37 vs 5.6.51 from ~30% to ~60%. It will take time to understand why.

5.6.51

---

17.77 mysql_delete

0.35 QUICK_RANGE_SELECT::reset

1.69 SQL_SELECT::test_quick_select

0.30 THD::binlog_query

1.40 binlog_log_row

4.52 handler::ha_delete_row

0.60 lock_tables

1.16 mysql_prepare_delete

1.28 open_normal_and_derived_tables

0.73 optimize_cond

4.06 rr_quick

9.82 ha_commit_trans

5.61 MYSQL_BIN_LOG::commit

1.83 MYSQL_BIN_LOG::process_commit_stage_queue

0.86 MYSQL_BIN_LOG::process_flush_stage_queue

2.26 my_b_flush_io_cache

3.78 ha_prepare_low

5.7.44

---

36.79 Sql_cmd_delete::execute

0.73 QUICK_RANGE_SELECT::reset

1.58 Sql_cmd_delete::mysql_prepare_delete

0.60 THD::binlog_query

3.33 binlog_log_row

9.59 handler::ha_delete_row

1.47 lock_tables

2.09 open_tables_for_query

1.03 optimize_cond

8.65 rr_quick

3.45 test_quick_select

18.04 ha_commit_trans

16.28 MYSQL_BIN_LOG::commit

3.81 MYSQL_BIN_LOG::flush_cache_to_file

4.22 MYSQL_BIN_LOG::process_commit_stage_queue

6.67 MYSQL_BIN_LOG::process_flush_stage_queue

1.70 MYSQL_BIN_LOG::flush_thread_caches

4.58 ha_flush_logs

0.99 ha_prepare_low

8.0.37

---

37.60 Sql_cmd_dml::execute

28.57 Sql_cmd_delete::delete_from_single_table

6.80 IndexRangeScanIterator::Read

0.83 THD::binlog_query

6.89 binlog_log_row

6.32 handler::ha_delete_row

1.24 optimize_cond

3.27 test_quick_select

0.73 Sql_cmd_delete::check_privileges

0.81 Sql_cmd_delete::restore_cmd_properties

1.83 lock_tables

4.04 open_tables_for_query

20.26 ha_commit_trans

17.41 MYSQL_BIN_LOG::commit

0.75 MYSQL_BIN_LOG::change_stage

3.09 MYSQL_BIN_LOG::flush_cache_to_file

3.29 MYSQL_BIN_LOG::process_commit_stage_queue

8.37 MYSQL_BIN_LOG::process_flush_stage_queue

5.42 MYSQL_BIN_LOG::fetch_and_process_flush_stage_queue

2.40 MYSQL_BIN_LOG::flush_thread_caches

1.37 MYSQL_BIN_LOG::prepare

Wednesday, August 7, 2024

MySQL regressions: update-nonindex vs InnoDB

I created flamegraphs while running sysbench with cached databases (more likely to be CPU bound) and the problem here occurs on an 8-core PN53 where sysbench was run with 1 thread. Here I use perf record -e cycles to collect data for flamegraphs and then I focus on the percentage of samples in a given function (and its callees) as a proxy for CPU overhead.

The flamegraphs are here.

The workload here is the update-nonindex microbenchmark. The throughput for a release relative to MySQL 5.6.51 is -> (QPS for $version) / (QPS for 5.6.51). The results below show that 8.0.37 gets about 62% of the QPS relative to 5.6.51.

0.86 in 5.7.44
0.79 in 8.0.11
0.67 in 8.0.28
0.62 in 8.0.37

From the numbers above there will soon be a release that only gets 50% of the QPS relative to 5.6.51. From the flamegraphs there is time spent in purge, networking and processing update statements. I focus on the time spent processing update statements. The percentage of samples (a proxy for CPU time) in mysqld_stmt_execute and its callees is:

32.77% in 5.6.51 from ~17% in mysql_update and ~12% from trans_commit_stmt
65.89% in 5.7.44 from ~39% in Sql_cmd_update::execute and ~22% from trans_commit_stmt
67.30% in 8.0.28 from ~38% in Sql_cmd_dml::execute and ~23% from trans_commit_stmt
67.97% in 8.0.37 from ~40% in Sql_cmd_dml::execute and ~21% from trans_commit_stmt

MySQL regressions: skip_concurrency_ticket

I created flamegraphs while running sysbench with cached databases (more likely to be CPU bound) and the problem here occurs on an 8-core PN53 where sysbench was run with 1 thread. Here I use perf record -e cycles to collect data for flamegraphs and then I focus on the percentage of samples in a given function (and its callees) as a proxy for CPU overhead.

The problem here is that during the scan benchymark the skip_concurrency_ticket function accounts for ~3% of CPU in 8.0.37, half that in 5.7.44 and the function doesn't exist in 5.6.51. It is called from innobase_srv_conc_enter_innodb which was a bit simpler in 5.6.

The flamegraphs (*.svg files) are here.

Also visible in those flamegraphs, the percentage of samples (CPU overhead prox) accounted for by row_sel_store_mysql_rec and callees

27.20% in 5.6.51
25.46% in 5.7.44
31.17% in 8.0.28
34.99% in 8.0.37

MySQL regressions: binlog_log_row

I started to look at CPU overheads in MyRocks and upstream InnoDB. While I am happy to file bugs for MyRocks as they are likely to be fixed, I am not sure how much energy I want to put into proper bug reports for upstream InnoDB. So I will just write blog posts about them for now.

I created flamegraphs while running sysbench with cached databases (more likely to be CPU bound) and the problem here occurs on an 8-core PN53 where sysbench was run with 1 thread. For the insert microbenchmark the insert rate ...

in MySQL 5.7.44 is 82% of the rate in MySQL 5.6.51
in MySQL 8.0.11 is 72% of the rate in MySQL 5.6.51
in MySQL 8.0.37 is 57% of the rate in MySQL 5.6.51

Here I use perf record -e cycles to collect data for flamegraphs and then I focus on the percentage of samples in a given function (and its callees) as a proxy for CPU overhead.

The percentage of samples that binlog_log_row and its children account for is ...

3.04% in MySQL 5.6.51
4.28% in MySQL 5.7.44
10.29% in MySQL 8.0.37

I don't know what happened to make this so much more expensive in 8.0. The numbers below are the percentage samples in the function and the functions it calls. The flamegraph (*.svg) files are here.

For MySQL 5.6.51 with InnoDB

3.04 binlog_log_row

2.23 THD::binlog_write_table_map

0.41 Table_map_log_event::Table_map_log_event

0.52 binlog_cache_data::write_event

0.92 binlog_start_trans_and_stmt

0.59 Write_rows_log_event::binlog_row_logging_function

0.51 THD::binlog_write_row

For MySQL 5.7.44 with InnoDB

4.28 binlog_log_row

3.13 THD::binlog_write_table_map

0.82 Write_rows_log_event::binlog_row_logging_function

For MySQL 8.0.37 with InnoDB

10.29 binlog_log_row

5.79 THD::binlog_write_table_map

2.53 Table_map_log_event::Table_map_log_event

0.60 binlog_cache_data::write_event

1.74 binlog_start_trans_and_stmt

2.97 Write_rows_log_event::binlog_row_logging_function

2.87 THD::binlog_write_row

0.49 add_pke