Bug #67676 prepared statement is very slow while binlog was enabled
Submitted: 22 Nov 2012 6:37 Modified: 25 Mar 2013 18:08
Reporter: zhai weixiang (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Prepared statements Severity:S2 (Serious)
Version:5.6.7 OS:Any
Assigned to: CPU Architecture:Any

[22 Nov 2012 6:37] zhai weixiang
Description:
It's very slow while we are using prepared statement to insert records into table.
we turned off general log, slow log and binary log, then everything works well.

From pt-pmp, the backtrace is as follows:
bmove_upp,String::replace,insert_params_with_log,Prepared_statement::set_parameters,Prepared_statement::execute_loop,mysqld_stmt_execute,dispatch_command,do_handle_one_connection,handle_one_connection,start_thread,clone

From perf top:
94.14%  bmove_upp                                                                                                                                                                                       
0.26%  setup_one_conversion_function(THD*, Item_param*, unsigned char)                                                                                                                                
0.26%  mtr_commit 

I noticed the function Prepared_statement::setup_set_params(quoted code from 5.6.7-rc):
  if ((mysql_bin_log.is_open() && is_update_query(lex->sql_command)) ||
      opt_log || opt_slow_log ||
      query_cache_is_cacheable_query(lex))
  {
    set_params_from_vars= insert_params_from_vars_with_log;
#ifndef EMBEDDED_LIBRARY
    set_params= insert_params_with_log;
#else
    set_params_data= emb_insert_params_with_log;
#endif
  }

Obviously, if binary log is open and is_update_query(lex->sql_command) is true , then   set_params= insert_params_with_log, no matter whether binlog_format is ROW or STATEMENT.

I think binlog_format should be taken into consideration because it's not needed to generate a query while binlog_format=row and the prepared statement can be logged in row format.

How to repeat:
I will upload a simple test later.

compile the test case and then execute it (slow log , query cache and general log should be closed and binlog_format=ROW before test)

orignal mysql 5.6.7:
./test 50000 1
SQL Too Long too print,Length 250048 !!
Inserted 50001 rows   AT   Thu Nov 22 14:26:55 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:00 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:06 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:12 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:18 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:23 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:29 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:35 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:40 2012
Inserted 50001 rows   AT   Thu Nov 22 14:27:46 2012

It costs 6 seconds to insert 50001 rows

mysql 5.6.7 with the patch bellow
$./test 50000 1
SQL Too Long too print,Length 250048 !!
Inserted 50001 rows   AT   Thu Nov 22 14:29:42 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:43 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:44 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:45 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:45 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:46 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:47 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:47 2012
Inserted 50001 rows   AT   Thu Nov 22 14:29:48 2012

It costs only 1 seconds to insert 50001 rows

I think the improvement is very obvious.

Suggested fix:
I hadn't taken DDL into consideration because I am not very familiar with prepared statement.
So bellow is a rough patch  used to prove my idea

--- a/sql/sql_prepare.cc        2012-09-19 07:06:30.000000000 +0800
+++ b/sql/sql_prepare.cc        2012-11-22 14:18:35.589798943 +0800
@@ -3133,7 +3133,7 @@
     Decide if we have to expand the query (because we must write it to logs or
     because we want to look it up in the query cache) or not.
   */
-  if ((mysql_bin_log.is_open() && is_update_query(lex->sql_command)) ||
+  if ((mysql_bin_log.is_open() && is_update_query(lex->sql_command)) && (!thd->is_current_stmt_binlog_format_row()) ||
       opt_log || opt_slow_log ||
       query_cache_is_cacheable_query(lex))
   {
[22 Nov 2012 6:38] zhai weixiang
test case

Attachment: test.c (application/octet-stream, text), 3.48 KiB.

[23 Nov 2012 19:57] Sveta Smirnova
Thank you for the report.

I can not repeat described behavior with current development sources: time is same for me. Please try with current version 5.6.8 and inform us if problem still exists in your environment.
[24 Nov 2012 3:06] zhai weixiang
I have  tested 5.6.8 and this bug still exists.
Please make sure general log, slow log and query cache is closed before running the test case.

Also make sue you are using row-based replication.

1. Orignal MySQL 5.6.8:
$./test 50000 1
SQL Too Long too print,Length 250048 !!
Inserted 50001 rows   AT   Sat Nov 24 10:51:24 2012
Inserted 50001 rows   AT   Sat Nov 24 10:51:30 2012
Inserted 50001 rows   AT   Sat Nov 24 10:51:36 2012
Inserted 50001 rows   AT   Sat Nov 24 10:51:42 2012
Inserted 50001 rows   AT   Sat Nov 24 10:51:47 2012
Inserted 50001 rows   AT   Sat Nov 24 10:51:53 2012
Inserted 50001 rows   AT   Sat Nov 24 10:51:59 2012
Inserted 50001 rows   AT   Sat Nov 24 10:52:05 2012
Inserted 50001 rows   AT   Sat Nov 24 10:52:11 2012
Inserted 50001 rows   AT   Sat Nov 24 10:52:16 2012

2. MySQL 5.6.8 with  the patch above

$./test 50000 1
SQL Too Long too print,Length 250048 !!
Inserted 50001 rows   AT   Sat Nov 24 10:55:22 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:23 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:23 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:24 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:25 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:25 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:26 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:27 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:28 2012
Inserted 50001 rows   AT   Sat Nov 24 10:55:28 2012
[26 Nov 2012 12:39] Shane Bester
Tatjana fixed very similar bug reported by me already. This might just be another occurrence of it. If unable to repeat, please ask her!
[27 Nov 2012 8:36] Jon Olav Hauglid
I guess Shane is thinking about one of these:
Bug#12884336
Bug#13958454
Bug#14073554
[22 Dec 2012 15:20] Shane Bester
I can see the problem, when using Intel VTune.
BTW, I used insert into blackhole engine with sync_binlog=0 and 8 varchar parameters.   I attach a picture of the profiler output...
[22 Dec 2012 15:21] Shane Bester
profiler output from 5.7.1

Attachment: bug67676_profiler_5.7.1_output.jpg (image/jpeg, text), 196.05 KiB.

[22 Dec 2012 15:51] Shane Bester
Timings for 2 minute run of inserts into blackhole
--------------------------------------------------------
Setting:  --log-bin --sync-binlog=0 --binlog-format=row
--------------------------------------------------------

Unpatched:
-------------------
run 1:  1226747 rows inserted
run 2:  1222369 rows inserted
run 3:  1207924 rows inserted

Patched:
-------------------
run 1:  1388651 rows inserted
run 2:  1382982 rows inserted
run 3:  1356249 rows inserted

So I see improvement.  Devs must figure out what to do with DDL statements that are always logged in statement.
[23 Jan 2013 4:18] hui liu
Some possible perf tuning for bmove_upp.

void bmove_upp(register uchar *dst, register const uchar *src,
               register size_t len)
{
//  while (len-- != 0) *--dst = *--src;

  while (1)
  {
    if (len>=16)
    {
      memcpy(dst-16, src-16, 16);
      dst-=16;
      len-=16;
    }
    if (len>=8)
    {
      memcpy(dst-8, src-8, 8);
      dst-=8;
      len-=8;
    }
    else if (len>=4)
    {
      memcpy(dst-4, src-4, 4);
      dst-=4;
      len-=4;
    }
    else if (len>=2)
    {
       memcpy(dst-2, src-2, 2);
      dst-=2;
      len-=2;
    }
    else
    {
       *--dst = *--src;
       len--;
       break;
    }
  }
}

Without patched mysqld, insert is ~X2 faster.

$ ./test 50000 1 
Inserted 50001 rows   AT   Wed Jan 23 10:48:36 2013
Inserted 50001 rows   AT   Wed Jan 23 10:48:44 2013
Inserted 50001 rows   AT   Wed Jan 23 10:48:51 2013
Inserted 50001 rows   AT   Wed Jan 23 10:48:59 2013
Inserted 50001 rows   AT   Wed Jan 23 10:49:06 2013
Inserted 50001 rows   AT   Wed Jan 23 10:49:14 2013
Inserted 50001 rows   AT   Wed Jan 23 10:49:21 2013
Inserted 50001 rows   AT   Wed Jan 23 10:49:28 2013
Inserted 50001 rows   AT   Wed Jan 23 10:49:36 2013

About 7~8 sec

top perf:
Events: 20K cycles, Thread: mysqld(24288)
 91.32%  mysqld              [.] bmove_upp                                                                                                                              ?
  0.23%  mysqld              [.] log_block_calc_checksum(unsigned char const*)                                                                                          ?
  0.19%  mysqld              [.] base_list_iterator::next_fast()                                                                                                        ?
  0.16%  mysqld              [.] ut_fold_ulint_pair(unsigned long, unsigned long)                                                                                       ?
  0.15%  mysqld              [.] my_utf8_uni
  
  
$ ./test 50000 1 
Inserted 50001 rows   AT   Wed Jan 23 12:13:12 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:16 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:20 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:24 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:27 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:32 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:35 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:39 2013
Inserted 50001 rows   AT   Wed Jan 23 12:13:43 2013

About 3-5 sec
[23 Jan 2013 4:19] hui liu
top perf:
Events: 115K cycles, DSO: mysqld
 23.96%  memcpy@plt
 22.12%  skip_trailing_space                                                                                                                                            ?
 12.71%  bmove_upp                                                                                                                                                      ?
  2.34%  0x7e9e47                                                                                                                                                       ?
  1.19%  log_block_calc_checksum(unsigned char const*)                                                                                                                  ?
  0.81%  ut_fold_ulint_pair(unsigned long, unsigned long)                                                                                                               ?
  0.58%  my_utf8_uni                                                                                                                                                    ?
  0.50%  base_list_iterator::next_fast()                                                                                                                                ?
  0.49%  rec_get_converted_size_comp_prefix(dict_index_t const*, dfield_t const*, unsigned long, unsigned long*)
[25 Mar 2013 18:08] Paul Dubois
Noted in 5.7.2 changelog.

Performance of prepared DML statements containing ? parameter
substitution markers was improved under row-based logging format:
Since the binary log in this case need not include the statement
text, and since the statement will not be forced to statement-based
logging as some DDL statements might be, there is no need to
substitute ? markers to produce a statement suitable for logging.
[14 Jul 2014 12:23] Shane Bester
Also:
http://bugs.mysql.com/bug.php?id=73056