Bug #77827 reduce cpu time costs of creating dummy index while change buffer is enabled
Submitted: 24 Jul 2015 9:29 Modified: 22 Dec 2016 8:58
Reporter: zhai weixiang (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7, 5.6 OS:Any
Assigned to: CPU Architecture:Any
Tags: Contribution

[24 Jul 2015 9:29] zhai weixiang
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.
[24 Jul 2015 14:23] zhai weixiang
patch to prove the improvement, not fully tested

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: ibuf.diff (application/octet-stream, text), 5.72 KiB.

[22 Dec 2016 8:58] Umesh Shastry
Hello Zhai,

Thank you for the report and contribution.

Thanks,
Umesh