Description:
While testing write-only workload with change buffer enabled, the cpu time cost of create/free dummy index/table become very obvious.
my test environment : buffer pool = 4G, SSD, 24core, mysql-5.7.7-rc
run 64 threads, with INSERT workload
200 tables with same schema:
mysql> show create table sbtest1\G
*************************** 1. row ***************************
Table: sbtest1
Create Table: CREATE TABLE `sbtest1` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`k` int(10) unsigned NOT NULL DEFAULT '0',
`c` char(120) NOT NULL DEFAULT '',
`pad` char(60) NOT NULL DEFAULT '',
PRIMARY KEY (`id`),
KEY `k_1` (`k`),
KEY `kc_1` (`k`,`c`(80)),
KEY `kp_1` (`k`,`pad`(30))
) ENGINE=InnoDB AUTO_INCREMENT=1027557 DEFAULT CHARSET=utf8 MAX_ROWS=1000000
1 row in set (0.00 sec)
Output from perf record && perf report:
+ 10.59% mysqld mysqld [.] ut_delay(unsigned long) ◆
- 2.73% mysqld libc-2.15.so [.] __strcmp_sse42 ▒
- __strcmp_sse42 ▒
- 96.48% ut_allocator<unsigned char>::get_mem_key(char const*) const ▒
- 90.56% mem_heap_create_block_func(mem_block_info_t*, unsigned long, unsigned long) ▒
- 61.39% mem_heap_add_block(mem_block_info_t*, unsigned long) ▒
- 51.87% dict_mem_index_create(char const*, char const*, unsigned long, unsigned long, unsigned long) ▒
+ ibuf_build_entry_from_ibuf_rec_func(unsigned char const*, mem_block_info_t*, dict_index_t**) ▒
- 33.29% dict_mem_table_create(char const*, unsigned long, unsigned long, unsigned long, unsigned long) ▒
+ ibuf_build_entry_from_ibuf_rec_func(unsigned char const*, mem_block_info_t*, dict_index_t**) ▒
- 13.88% mem_heap_strdup(mem_block_info_t*, char const*) ▒
dict_mem_index_create(char const*, char const*, unsigned long, unsigned long, unsigned long) ▒
- ibuf_build_entry_from_ibuf_rec_func(unsigned char const*, mem_block_info_t*, dict_index_t**) ▒
+ 84.31% ibuf_get_volume_buffered_count_func(unsigned char const*, unsigned long*, unsigned long, long*) [clone .constprop.84] ▒
+ 8.41% ibuf_rec_get_volume_func(unsigned char const*) ▒
+ 7.29% ibuf_merge_or_delete_for_page(buf_block_t*, page_id_t const&, page_size_t const*, unsigned long) ▒
+ 10.25% ibuf_get_volume_buffered_count_func(unsigned char const*, unsigned long*, unsigned long, long*) [clone .constprop.84] ▒
I also found such backtrace from output of pt-pmp:
pfs_memory_alloc_v1(pfs.cc:6283),allocate_trace(ut0new.h:682),allocate(ut0new.h:682),mem_heap_create_block_func(ut0new.h:682),mem_heap_add_block(mem0mem.cc:408),mem_heap_alloc(mem0mem.ic:204),mem_heap_zalloc(mem0mem.ic:204),dict_mem_index_create(mem0mem.ic:204),ibuf_dummy_index_create(ibuf0ibuf.cc:1475),ibuf_build_entry_from_ibuf_rec_func(ibuf0ibuf.cc:1475),ibuf_get_volume_buffered_count_func(ibuf0ibuf.cc:2954),ibuf_get_volume_buffered(ibuf0ibuf.cc:3029),ibuf_insert_low(ibuf0ibuf.cc:3029),ibuf_insert(ibuf0ibuf.cc:3810),btr_cur_search_to_nth_level(btr0cur.cc:1111),row_ins_sec_index_entry_low(row0ins.cc:2845),row_ins_sec_index_entry(row0ins.cc:3253),row_ins_index_entry(row0ins.cc:3299),row_ins_index_entry_step(row0ins.cc:3299),row_ins(row0ins.cc:3299),row_ins_step(row0ins.cc:3299),row_insert_for_mysql_using_ins_graph(row0mysql.cc:1689),ha_innobase::write_row(ha_innodb.cc:6807),handler::ha_write_row(handler.cc:7518),write_record(sql_insert.cc:1760),Sql_cmd_insert::mysql_insert(sql_insert.cc:687),Sql_cmd_insert::execute(sql_insert.cc:3015),mysql_execute_command(sql_parse.cc:4477),mysql_parse(sql_parse.cc:5159),dispatch_command(sql_parse.cc:1249),handle_connection(connection_handler_per_thread.cc:298),pfs_spawn_thread(pfs.cc:2147),start_thread(libpthread.so.0),clone(libc.so.6)
Before buffering the operation, in order to calculate volume of the page after merging all ibuf entries that belong to this page, it need to build dummy index and dummy table for each ibuf record that affects the page size.
So with more and more operations buffered, it will spend more time on building dummy index.
I think we can reuse the dummy index and dummy table during one call of function ibuf_get_volume_buffered
How to repeat:
described above
Suggested fix:
Try to reuse the dummy index and dummy table in function ibuf_get_volume_buffered
I will attach a patch later.
Description: While testing write-only workload with change buffer enabled, the cpu time cost of create/free dummy index/table become very obvious. my test environment : buffer pool = 4G, SSD, 24core, mysql-5.7.7-rc run 64 threads, with INSERT workload 200 tables with same schema: mysql> show create table sbtest1\G *************************** 1. row *************************** Table: sbtest1 Create Table: CREATE TABLE `sbtest1` ( `id` int(10) unsigned NOT NULL AUTO_INCREMENT, `k` int(10) unsigned NOT NULL DEFAULT '0', `c` char(120) NOT NULL DEFAULT '', `pad` char(60) NOT NULL DEFAULT '', PRIMARY KEY (`id`), KEY `k_1` (`k`), KEY `kc_1` (`k`,`c`(80)), KEY `kp_1` (`k`,`pad`(30)) ) ENGINE=InnoDB AUTO_INCREMENT=1027557 DEFAULT CHARSET=utf8 MAX_ROWS=1000000 1 row in set (0.00 sec) Output from perf record && perf report: + 10.59% mysqld mysqld [.] ut_delay(unsigned long) ◆ - 2.73% mysqld libc-2.15.so [.] __strcmp_sse42 ▒ - __strcmp_sse42 ▒ - 96.48% ut_allocator<unsigned char>::get_mem_key(char const*) const ▒ - 90.56% mem_heap_create_block_func(mem_block_info_t*, unsigned long, unsigned long) ▒ - 61.39% mem_heap_add_block(mem_block_info_t*, unsigned long) ▒ - 51.87% dict_mem_index_create(char const*, char const*, unsigned long, unsigned long, unsigned long) ▒ + ibuf_build_entry_from_ibuf_rec_func(unsigned char const*, mem_block_info_t*, dict_index_t**) ▒ - 33.29% dict_mem_table_create(char const*, unsigned long, unsigned long, unsigned long, unsigned long) ▒ + ibuf_build_entry_from_ibuf_rec_func(unsigned char const*, mem_block_info_t*, dict_index_t**) ▒ - 13.88% mem_heap_strdup(mem_block_info_t*, char const*) ▒ dict_mem_index_create(char const*, char const*, unsigned long, unsigned long, unsigned long) ▒ - ibuf_build_entry_from_ibuf_rec_func(unsigned char const*, mem_block_info_t*, dict_index_t**) ▒ + 84.31% ibuf_get_volume_buffered_count_func(unsigned char const*, unsigned long*, unsigned long, long*) [clone .constprop.84] ▒ + 8.41% ibuf_rec_get_volume_func(unsigned char const*) ▒ + 7.29% ibuf_merge_or_delete_for_page(buf_block_t*, page_id_t const&, page_size_t const*, unsigned long) ▒ + 10.25% ibuf_get_volume_buffered_count_func(unsigned char const*, unsigned long*, unsigned long, long*) [clone .constprop.84] ▒ I also found such backtrace from output of pt-pmp: pfs_memory_alloc_v1(pfs.cc:6283),allocate_trace(ut0new.h:682),allocate(ut0new.h:682),mem_heap_create_block_func(ut0new.h:682),mem_heap_add_block(mem0mem.cc:408),mem_heap_alloc(mem0mem.ic:204),mem_heap_zalloc(mem0mem.ic:204),dict_mem_index_create(mem0mem.ic:204),ibuf_dummy_index_create(ibuf0ibuf.cc:1475),ibuf_build_entry_from_ibuf_rec_func(ibuf0ibuf.cc:1475),ibuf_get_volume_buffered_count_func(ibuf0ibuf.cc:2954),ibuf_get_volume_buffered(ibuf0ibuf.cc:3029),ibuf_insert_low(ibuf0ibuf.cc:3029),ibuf_insert(ibuf0ibuf.cc:3810),btr_cur_search_to_nth_level(btr0cur.cc:1111),row_ins_sec_index_entry_low(row0ins.cc:2845),row_ins_sec_index_entry(row0ins.cc:3253),row_ins_index_entry(row0ins.cc:3299),row_ins_index_entry_step(row0ins.cc:3299),row_ins(row0ins.cc:3299),row_ins_step(row0ins.cc:3299),row_insert_for_mysql_using_ins_graph(row0mysql.cc:1689),ha_innobase::write_row(ha_innodb.cc:6807),handler::ha_write_row(handler.cc:7518),write_record(sql_insert.cc:1760),Sql_cmd_insert::mysql_insert(sql_insert.cc:687),Sql_cmd_insert::execute(sql_insert.cc:3015),mysql_execute_command(sql_parse.cc:4477),mysql_parse(sql_parse.cc:5159),dispatch_command(sql_parse.cc:1249),handle_connection(connection_handler_per_thread.cc:298),pfs_spawn_thread(pfs.cc:2147),start_thread(libpthread.so.0),clone(libc.so.6) Before buffering the operation, in order to calculate volume of the page after merging all ibuf entries that belong to this page, it need to build dummy index and dummy table for each ibuf record that affects the page size. So with more and more operations buffered, it will spend more time on building dummy index. I think we can reuse the dummy index and dummy table during one call of function ibuf_get_volume_buffered How to repeat: described above Suggested fix: Try to reuse the dummy index and dummy table in function ibuf_get_volume_buffered I will attach a patch later.