| Bug #76002 | different plan when executing query using procedure | ||
|---|---|---|---|
| Submitted: | 23 Feb 2015 8:14 | Modified: | 25 Feb 2015 1:35 |
| Reporter: | zhai weixiang (OCA) | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: Optimizer | Severity: | S3 (Non-critical) |
| Version: | 5.6 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[23 Feb 2015 14:03]
zhai weixiang
From the output of optimizer trace :
execute the statement directly, the sql will be converted to:
"join_preparation": {
"select#": 1,
"steps": [
{
"expanded_query": "/* select#1 */ select `t1`.`col2` AS `col2` from `t1` where (`t1`.`col1` = convert(NAME_CONST('isn',(_utf8'tr' collate utf8_general_ci)) using gbk))"
}
]
}
Call the procedure, and check the optimizer trace:
"join_preparation": {
"select#": 1,
"steps": [
{
"expanded_query": "/* select#1 */ select `t1`.`col2` AS `col2` from `t1` where (convert(`t1`.`col1` using utf8) = isn@0)"
}
]
}
[24 Feb 2015 12:52]
MySQL Verification Team
C:\dbs>c:\dbs\5.6\bin\mysql -uroot --port=3560 --debug-info --prompt="mysql 5.6 > "
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.24 Source distribution pull: 2015.feb20
Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql 5.6 > create database xx1 character set utf8;
Query OK, 1 row affected (0.00 sec)
mysql 5.6 > use xx1;
Database changed
mysql 5.6 > CREATE TABLE t1 ( `col1` varchar(10) NOT NULL, `col2` bigint(11) NOT NULL DEFAULT '0', PRIMARY KEY (`col1`)) ENGINE=InnoDB DEFAULT CHARSET=gbk;
Query OK, 0 rows affected (0.27 sec)
mysql 5.6 > insert into t1 values ('ac',2),('del',3),('sp',5),('tr',12);
Query OK, 4 rows affected (0.11 sec)
Records: 4 Duplicates: 0 Warnings: 0
mysql 5.6 > DELIMITER //
mysql 5.6 > CREATE PROCEDURE proc1(IN isn CHAR(20))
-> BEGIN
-> START TRANSACTION;
-> SELECT col2 FROM t1 WHERE col1= isn FOR UPDATE;
-> COMMIT;
-> END //
Query OK, 0 rows affected (0.05 sec)
mysql 5.6 > DELIMITER ;
mysql 5.6 > flush status;
Query OK, 0 rows affected (0.00 sec)
mysql 5.6 > show session status like '%handler%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| Handler_commit | 0 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 0 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 0 |
| Handler_read_key | 0 |
| Handler_read_last | 0 |
| Handler_read_next | 0 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 0 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 0 |
+----------------------------+-------+
18 rows in set (0.00 sec)
mysql 5.6 > call proc1('tr');
+------+
| col2 |
+------+
| 12 |
+------+
1 row in set (0.00 sec)
Query OK, 0 rows affected (0.02 sec)
mysql 5.6 > show session status like '%handler%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| Handler_commit | 2 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 4 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 1 |
| Handler_read_key | 2 |
| Handler_read_last | 0 |
| Handler_read_next | 0 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 5 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 0 |
+----------------------------+-------+
18 rows in set (0.00 sec)
mysql 5.6 > flush status;
Query OK, 0 rows affected (0.00 sec)
mysql 5.6 > START TRANSACTION;
Query OK, 0 rows affected (0.00 sec)
mysql 5.6 > SELECT col2 FROM t1 WHERE col1= NAME_CONST('isn',_utf8'tr' COLLATE 'utf8_general_ci') FOR UPDATE;
+------+
| col2 |
+------+
| 12 |
+------+
1 row in set (0.00 sec)
mysql 5.6 > COMMIT;
Query OK, 0 rows affected (0.00 sec)
mysql 5.6 > show session status like '%handler%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| Handler_commit | 2 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_external_lock | 2 |
| Handler_mrr_init | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 0 |
| Handler_read_key | 1 |
| Handler_read_last | 0 |
| Handler_read_next | 0 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 0 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 0 |
+----------------------------+-------+
18 rows in set (0.00 sec)
[24 Feb 2015 16:00]
MySQL Verification Team
I have analyzed this bug and discovered that it is specific to 5.6 only. It also seems that it can only be caused by different character sets between database and table (column). Fully verified.
[24 Feb 2015 16:31]
MySQL Verification Team
Sorry, I just noticed the mistake. Problem is that the stored routine does not explicitly declare the charset of the parameter that is passed to the stored routine. It must match the column's charset to which you're comparing it to. Try changing it to: "IN isn CHAR(20)charset gbk" and it will use the index properly.
[25 Feb 2015 1:35]
zhai weixiang
Thank you, Sinisa !! This problem happened while master has different default character set with slave . And the stored routine didn't explicitly declare it's character set. So it's ok when running this stored routine on master. But when the slave is promoted to master, problem happened. It's better if the character set is auto-generated for the statement that create the procedure before writing it to binlog. :) Anyway, I agree this is not a bug !
Description: Create a table for test: create database xx1 character set utf8; use xx1; Create a table using different charset: CREATE TABLE t1 ( `col1` varchar(10) NOT NULL, `col2` bigint(11) NOT NULL DEFAULT '0', PRIMARY KEY (`col1`)) ENGINE=InnoDB DEFAULT CHARSET=gbk; generate some records: insert into t1 values ('ac',2),('del',3),('sp',5),('tr',12); Create a procedure: DELIMITER // CREATE PROCEDURE proc1(IN isn CHAR(20)) BEGIN START TRANSACTION; SELECT col2 FROM t1 WHERE col1= isn FOR UPDATE; COMMIT; END // DELIMITER ; flush status; root@xx1 04:03:26>show session status like '%handler%'; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Handler_commit | 0 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 0 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 0 | | Handler_read_key | 0 | | Handler_read_last | 0 | | Handler_read_next | 0 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 0 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 0 | +----------------------------+-------+ 18 rows in set (0.00 sec) root@xx1 04:03:44>call proc1('tr'); +------+ | col2 | +------+ | 12 | +------+ 1 row in set (7.55 sec) Query OK, 0 rows affected (8.32 sec) root@xx1 04:04:00>show session status like '%handler%'; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Handler_commit | 2 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 4 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 1 | | Handler_read_key | 2 | | Handler_read_last | 0 | | Handler_read_next | 0 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 5 | --------->obviously, a full table scan happened | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 0 | +----------------------------+-------+ 18 rows in set (0.00 sec) In order to find out how procedure executes a select..for update statement, I enabled general log, setting binlog_format=statement, tx_isolation=REPEATABLE-READ, and attach to the process using gdb: Breakpoint 2, sp_instr_stmt::exec_core (this=0x2ae15404bc30, thd=0x3787f410, nextp=0x2ae14c0ff648) at /u01/project/mysql-lab/mysql-5.6.23/sql/sp_instr.cc:895 895 thd->lex->set_sp_current_parsing_ctx(get_parsing_ctx()); (gdb) p thd->query_string $8 = {string = {str = 0x2ae1540544f0 "START TRANSACTION", length = 17}, cs = 0x1321f20} (gdb) c Continuing. Breakpoint 2, sp_instr_stmt::exec_core (this=0x2ae154021648, thd=0x3787f410, nextp=0x2ae14c0ff648) at /u01/project/mysql-lab/mysql-5.6.23/sql/sp_instr.cc:895 895 thd->lex->set_sp_current_parsing_ctx(get_parsing_ctx()); (gdb) p thd->query_string $9 = {string = {str = 0x2ae154054588 "SELECT col2 FROM t1 WHERE col1= NAME_CONST('isn',_utf8'tr' COLLATE 'utf8_general_ci') FOR UPDATE", length = 97}, cs = 0x1321f20} (gdb) c Continuing. Breakpoint 2, sp_instr_stmt::exec_core (this=0x2ae154021770, thd=0x3787f410, nextp=0x2ae14c0ff648) at /u01/project/mysql-lab/mysql-5.6.23/sql/sp_instr.cc:895 895 thd->lex->set_sp_current_parsing_ctx(get_parsing_ctx()); (gdb) p thd->query_string $10 = {string = {str = 0x2ae1540544f0 "COMMIT", length = 6}, cs = 0x1321f20} Then I execute the statment directly: root@xx1 04:06:36>flush status; Query OK, 0 rows affected (0.00 sec) root@xx1 04:07:04>START TRANSACTION; Query OK, 0 rows affected (0.00 sec) root@xx1 04:07:12>SELECT col2 FROM t1 WHERE col1= NAME_CONST('isn',_utf8'tr' COLLATE 'utf8_general_ci') FOR UPDATE; +------+ | col2 | +------+ | 12 | +------+ 1 row in set (0.00 sec) root@xx1 04:07:24>COMMIT; Query OK, 0 rows affected (0.00 sec) root@xx1 04:07:34>show session status like '%handler%'; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Handler_commit | 2 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 2 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 0 | | Handler_read_key | 1 | | Handler_read_last | 0 | | Handler_read_next | 0 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 0 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 0 | +----------------------------+-------+ 18 rows in set (0.00 sec) root@xx1 04:07:48>EXPLAIN SELECT col2 FROM t1 WHERE col1= NAME_CONST('isn',_utf8'tr' COLLATE 'utf8_general_ci') FOR UPDATE; +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------+ | 1 | SIMPLE | t1 | const | PRIMARY | PRIMARY | 22 | const | 1 | NULL | +----+-------------+-------+-------+---------------+---------+---------+-------+------+-------+ 1 row in set (0.00 sec) How to repeat: above/ Suggested fix: I don't know.