| Bug #69236 | performance regressions for single-threaded workloads, part 2 | ||
|---|---|---|---|
| Submitted: | 14 May 2013 22:12 | Modified: | 1 Sep 2015 14:38 |
| Reporter: | Mark Callaghan | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S5 (Performance) |
| Version: | 5.6.11 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[14 May 2013 22:12]
Mark Callaghan
[15 May 2013 12:48]
Mark Callaghan
For 5.6, charsets are: character_set_client latin1 character_set_connection latin1 character_set_database latin1 character_set_filesystem binary character_set_results latin1 character_set_server latin1 character_set_system utf8
[15 May 2013 14:53]
Mark Callaghan
CPU times for the mysql client: 5.6 user 0m25.121s sys 0m0.629s -> 25.8 5.1 user 0m19.884s sys 0m0.747s -> 20.6 5.0 user 0m18.700s sys 0m0.853s -> 19.6 4.0 user 0m8.994s sys 0m0.923s -> 9.9
[15 May 2013 14:56]
Mark Callaghan
CPU times for the client that reloads a 1.6M row sysbench table using "mysqldump --opt" output. There were 1.6M rows and the total time was about 140 seconds for 4.0 growing to ~200 seconds for 5.6 (with perf schema disabled at compile time) and 210 seconds for 5.6 (with perf schema enabled at compile time). The "mysql" client was on the same host as mysqld.
[15 May 2013 16:29]
Mark Callaghan
Using "insert into foo select * from bar" where bar is the sysbench table I previously loaded and foo is empty at the start with the same DDL as bar. This removes overhead from the optimizer and mysql client. The overhead should be dominated by InnoDB and until 5.6 results were steady. Note that 5.1 below is the plugin InnoDB. This workload can be subject to wait stalls but the difference between 5.6 with and without perf-schema shows there are CPU issues. 4.0 -> 137.3 secs 5.0 -> 146.8 secs 5.1 -> 137.5 secs 5.6 -> 150.3 secs -> mysqld with perf schema disabled at compile time 5.5 -> 166.1 secs -> mysqld with perf schema enabled at compile time
[15 May 2013 16:41]
Mark Callaghan
Linux perf output from 5.1.63 and 5.6.11 for the "insert into foo select * from bar" workload. Note that 5.6 has an advantage as it uses CRC32 checksums and 5.1 spends more CPU time doing that.
5.1
12.85% mysqld mysqld [.] buf_calc_page_new_checksum
6.25% mysqld mysqld [.] log_group_write_buf
4.96% mysqld libc-2.13.so [.] __memcpy_ssse3
4.10% mysqld mysqld [.] mtr_commit
2.92% mysqld mysqld [.] row_sel_store_mysql_rec
2.59% mysqld mysqld [.] btr_search_guess_on_hash
2.11% mysqld mysqld [.] row_search_for_mysql
1.80% mysqld mysqld [.] mlog_open_and_write_index
1.76% mysqld mysqld [.] rec_get_offsets_func
1.71% mysqld mysqld [.] page_cur_insert_rec_write_log
1.67% mysqld mysqld [.] trx_undo_report_row_operation
1.67% mysqld mysqld [.] rec_init_offsets_comp_ordinary
1.63% mysqld mysqld [.] btr_cur_optimistic_insert
1.51% mysqld mysqld [.] buf_page_get_known_nowait
1.35% mysqld mysqld [.] cmp_dtuple_rec_with_match
1.31% mysqld mysqld [.] field_conv(Field*, Field*)
1.22% mysqld mysqld [.] buf_page_get_gen
1.18% mysqld mysqld [.] row_ins_step
1.15% mysqld mysqld [.] rw_lock_x_lock_func
1.14% mysqld libc-2.13.so [.] __memmove_ssse3
1.14% mysqld mysqld [.] lock_rec_insert_check_and_lock
1.05% mysqld mysqld [.] page_cur_insert_rec_low
1.03% mysqld mysqld [.] btr_search_check_guess
[15 May 2013 16:42]
Mark Callaghan
5.6
6.30% mysqld mysqld.orig [.] log_group_write_buf(log_group_t*, unsigned char*, unsigned long, unsigned long, unsigned long)
4.80% mysqld libc-2.13.so [.] __memcpy_ssse3
3.24% mysqld mysqld.orig [.] rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned long*, unsigned long, mem_block_info_t**, char const*, unsigned long)
2.89% mysqld mysqld.orig [.] trx_undo_report_row_operation(unsigned long, unsigned long, que_thr_t*, dict_index_t*, dtuple_t const*, upd_t const*, unsigned long, unsigned char const*, unsigned long const*, unsigned long*)
2.75% mysqld mysqld.orig [.] btr_search_guess_on_hash(dict_index_t*, btr_search_t*, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, mtr_t*)
2.37% mysqld mysqld.orig [.] btr_cur_optimistic_insert(unsigned long, btr_cur_t*, unsigned long**, mem_block_info_t**, dtuple_t*, unsigned char**, big_rec_t**, unsigned long, que_thr_t*, mtr_t*)
2.18% mysqld mysqld.orig [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
2.09% mysqld mysqld.orig [.] _ZL40row_sel_field_store_in_mysql_format_funcPhPK17mysql_row_templ_tPKhm
1.96% mysqld mysqld.orig [.] buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*)
1.77% mysqld mysqld.orig [.] mlog_open_and_write_index(mtr_t*, unsigned char const*, dict_index_t const*, unsigned char, unsigned long)
1.73% mysqld [iomemory_vsl] [k] 0x000000000006b16a
1.59% mysqld mysqld.orig [.] _ZL26mtr_memo_slot_release_funcP15mtr_memo_slot_t
1.56% mysqld mysqld.orig [.] _ZL29page_cur_insert_rec_write_logPhmS_P12dict_index_tP5mtr_t
1.56% mysqld mysqld.orig [.] mtr_commit(mtr_t*)
1.52% mysqld mysqld.orig [.] rec_convert_dtuple_to_rec(unsigned char*, dict_index_t const*, dtuple_t const*, unsigned long)
1.49% mysqld mysqld.orig [.] page_cur_insert_rec_low(unsigned char*, dict_index_t*, unsigned char const*, unsigned long*, mtr_t*)
1.43% mysqld mysqld.orig [.] _ZL35mtr_add_dirtied_pages_to_flush_listP5mtr_t
1.40% mysqld mysqld.orig [.] cmp_dtuple_rec_with_match_low(dtuple_t const*, unsigned char const*, unsigned long const*, unsigned long, unsigned long*, unsigned long*)
1.32% mysqld mysqld.orig [.] row_insert_for_mysql(unsigned char*, row_prebuilt_t*)
1.31% mysqld mysqld.orig [.] field_conv(Field*, Field*)
1.26% mysqld mysqld.orig [.] row_ins_step(que_thr_t*)
1.15% mysqld mysqld.orig [.] _ZL29lock_rec_convert_impl_to_explPK11buf_block_tPKhP12dict_index_tPKm
1.12% mysqld mysqld.orig [.] malloc
1.10% mysqld mysqld.orig [.] rw_lock_x_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long)
1.09% mysqld mysqld.orig [.] _ZL14ut_crc32_sse42PKhm
1.04% mysqld mysqld.orig [.] buf_page_get_known_nowait(unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*)
1.03% mysqld mysqld.orig [.] lock_rec_insert_check_and_lock(unsigned long, unsigned char const*, buf_block_t*, dict_index_t*, que_thr_t*, mtr_t*, unsigned long*)
1.02% mysqld [kernel.kallsyms] [k] clear_page_c
1.00% mysqld libc-2.13.so [.] __memmove_ssse3
1.00% mysqld libc-2.13.so [.] __memset_sse2
5.6 is spending a lot more time in:
rec_get_offsets_func
trx_undo_report_row_operation
btr_cur_optimistic_insert
[16 Jun 2013 13:04]
MySQL Verification Team
The perf output here shows server/innodb. Let's leave the client stuff for another bug. Anyway, it looks like the 5.6 client wasn't given --default-character-set=latin1 option. I filed this internally a while ago: Bug 14057034 - WASTED CPU CYCLES IN MY_UTF8_UNI WHERE RESULTING MY_WC_T RESULT IS NOT USED And we have related known contributions: http://bugs.mysql.com/search.php?cmd=display&status=Active&reporter=5981421
[21 Jun 2013 8:12]
MySQL Verification Team
Hello Mark, Thank you for the report. Thanks, Umesh
[23 Aug 2015 14:25]
Peter Laursen
see also http://bugs.mysql.com/bug.php?id=78176
[1 Sep 2015 14:38]
Mark Callaghan
regressions continue with mysql 5.7.8 http://smalldatum.blogspot.com/2015/08/single-threaded-linkbench-performance.html
[31 Mar 2016 12:22]
Andrii Nikitin
If problem query calls many stored functions or triggers - see also bug #80923 (and maybe bug #80922)
