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:
None 
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
Description:
Single-threaded workloads can be much slower on 5.6 than on 4.0
See http://mysqlha.blogspot.com/2013/03/mysql-56-single-threaded-read-only.html and http://bugs.mysql.com/bug.php?id=68825, but 68825 is open for the optimizer now. So Roy requested a new issue for non-optimizer issues.

How to repeat:
See http://mysqlha.blogspot.com/2013/03/mysql-56-single-threaded-read-only.html and http://bugs.mysql.com/bug.php?id=68825

Suggested fix:
One problem is 3X more CPU used by the MySQL client in what looks like utf8 functions.
[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)