| 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: | |
| Category: | MySQL Server: Prepared statements | Severity: | S2 (Serious) |
| Version: | 5.6.7 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[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]
MySQL Verification Team
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]
MySQL Verification Team
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]
MySQL Verification Team
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]
MySQL Verification Team
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]
liu hickey
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]
liu hickey
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]
MySQL Verification Team
Also: http://bugs.mysql.com/bug.php?id=73056
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)) {