MySQL Bugs: #68811: Replication slave stuck on simple query with user variables.

Bug #68811	Replication slave stuck on simple query with user variables.
Submitted:	29 Mar 2013 8:56	Modified:	7 May 2013 8:03
Reporter:	Сергей Мельничук	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.6.10	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	binlog, performance, replication, variable

Description:
It takes enormous time for simple queries involving user variables to complete on slave server for unknown reason. This bug appears only on multimillion record tables. Queries complete normally on master server.

Here's sample table definition:
CREATE TABLE `subscr_payments` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `sreq_id` int(11) NOT NULL,
  `when_sent` datetime NOT NULL,
  `when_notified` datetime DEFAULT NULL,
  `price` decimal(8,2) unsigned NOT NULL,
  `price_real` decimal(8,2) unsigned NOT NULL,
  `remainder_real` decimal(8,2) unsigned NOT NULL,
  `transp_request_id` varchar(11) COLLATE utf8_bin DEFAULT NULL,
  `paid` tinyint(1) unsigned NOT NULL DEFAULT '0',
  `is_repeat` tinyint(1) unsigned NOT NULL DEFAULT '0',
  `service_number` varchar(22) COLLATE utf8_bin DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `idx_sreq_id_id` (`sreq_id`,`id`),
  UNIQUE KEY `idx_transp_request_id` (`transp_request_id`),
  KEY `idx_sreq_id` (`sreq_id`,`when_sent`),
  KEY `idx_when_notified` (`when_notified`)
) ENGINE=InnoDB AUTO_INCREMENT=121694508 DEFAULT CHARSET=utf8 COLLATE=utf8_bin

show index from subscr_payments\G
mysql> show index from subscr_payments\G
*************************** 1. row ***************************
        Table: subscr_payments
   Non_unique: 0
     Key_name: PRIMARY
 Seq_in_index: 1
  Column_name: id
    Collation: A
  Cardinality: 107109384
     Sub_part: NULL
       Packed: NULL
         Null:
   Index_type: BTREE
      Comment:
Index_comment:

How to repeat:
First of all, we need to fill table with tens of millions records.
For table described above it's something like this:
insert into subscr_payments set sreq_id=100500, when_sent='2012-01-01', when_notified='2012-01-01', price='0.00', price_real='0.00', remainder_real='0.00', transp_request_id='xxx', paid=0, is_repeat=0;

Then, in order to reproduce bug do the folowing:

insert into subscr_payments set sreq_id=100500, when_sent='2012-01-01', when_notified='2012-01-01', price='0.00', price_real='0.00', remainder_real='0.00', transp_request_id='xxx', paid=0, is_repeat=0;
set @pid := (select last_insert_id());
update subscr_payments set transp_request_id='yyy' where id=@pid;

Then, on slave:
show processlist\G
...
*************************** 7. row ***************************
     Id: 119972
   User: system user
   Host:
     db: subscriptions
Command: Connect
   Time: 1103
  State: updating
   Info: update subscr_payments set transp_request_id='yyy' where id=@pid

show engine innodb status\G
...
---TRANSACTION 5506825561, ACTIVE 1157 sec unlock_row
mysql tables in use 1, locked 1
198338 lock struct(s), heap size 22428088, 1 row lock(s)
MySQL thread id 119972, OS thread handle 0x9813afc00, query id 125794954 updating
update subscr_payments set transp_request_id='yyy' where id=@pid

Important notes.
The same query that uses numerical value instead of a user variable completes in no time.
The same queries involving variables, but issued on slave locally also complete normally. The problem is only reproduced on queries coming from replication master server.

Just a wild guess. Please, send the output of:

show variables like 'char%';

from master and from slave. It would be also useful to see the event with problematic UPDATE from the relay log on slave, using mysqlbinlog.

Charsets on both servers are the same. 

mysql> show variables like 'char%'\G
*************************** 1. row ***************************
Variable_name: character_set_client
        Value: cp1251
*************************** 2. row ***************************
Variable_name: character_set_connection
        Value: cp1251
*************************** 3. row ***************************
Variable_name: character_set_database
        Value: utf8
*************************** 4. row ***************************
Variable_name: character_set_filesystem
        Value: binary
*************************** 5. row ***************************
Variable_name: character_set_results
        Value: cp1251
*************************** 6. row ***************************
Variable_name: character_set_server
        Value: latin1
*************************** 7. row ***************************
Variable_name: character_set_system
        Value: utf8
*************************** 8. row ***************************
Variable_name: character_sets_dir
        Value: /usr/local/share/mysql/charsets/
8 rows in set (0.00 sec)

Binlog info:
# at 693267512
#130401 12:47:38 server id 197220  end_log_pos 693267346 CRC32 0xdb8e0720       Intvar
SET INSERT_ID=122449074/*!*/;
#130401 12:47:38 server id 197220  end_log_pos 693267638 CRC32 0xfcaffcdc       Query   thread_id=7459205       exec_time=1     error_code=0
use `subscriptions`/*!*/;
SET TIMESTAMP=1364806058/*!*/;
insert into subscr_payments set sreq_id=100500, when_sent='2012-01-01', when_notified='2012-01-01', price='0.00', price_real='0.00', remainder_real='0.00', transp_request_id='xxx', paid=0, is_repeat=0
/*!*/;
# at 693294294
#130401 12:47:52 server id 197220  end_log_pos 693294128 CRC32 0x52f78c9a       User_var
SET @`pid`:=122449074/*!*/;
#130401 12:47:52 server id 197220  end_log_pos 693294285 CRC32 0x5ace8e9a       Query   thread_id=7459205       exec_time=0     error_code=0
use `subscriptions`/*!*/;
SET TIMESTAMP=1364806072/*!*/;
update subscr_payments set transp_request_id='yyy1' where id=@pid
/*!*/;

I could not repeat any problem with the attached sql script...

Attachment: bug68811_simulation.txt (text/plain), 473 bytes.

Dear Shane.
We've tried your test case and here are the results.

Master server.
...
mysql> insert into `t1`(`b`) select `t1`.`b` from `t1`,`t1` `a`,`t1` `b`,`t1` `c`,
    -> `t1` `d`,`t1` `e`,`t1` `f`,`t1` `g`,`t1` `h`,`t1` `i`,`t1` `j`;
Query OK, 48828125 rows affected, 1 warning (13 min 24.09 sec)
Records: 48828125  Duplicates: 0  Warnings: 1

mysql> insert into `t1`(`b`) values (99);
Query OK, 1 row affected (0.00 sec)

mysql> set @`id`:=(select last_insert_id());
Query OK, 0 rows affected (0.00 sec)

mysql> update `t1` set `b`=0 where `a`=@`id`;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Slave server.

*************************** 3. row ***************************
    Id: 184467
  User: system user
  Host:
    db: subscriptions
Command: Connect
  Time: 43
 State: updating
  Info: update `t1` set `b`=0 where `a`=@`id`

---TRANSACTION 5531337833, ACTIVE 33 sec unlock_row
mysql tables in use 1, locked 1
67169 lock struct(s), heap size 10287544, 1 row lock(s)
MySQL thread id 184467, OS thread handle 0x9813b9000, query id 159965575 updating
update `t1` set `b`=0 where `a`=@`id`

So, request was completed in 40-50 seconds, i don't have exact time.

Same request with user variable issued on slave server locally completes in 0.00s:

mysql> set @a=48828125;
Query OK, 0 rows affected (0.00 sec)

mysql> update `t1` set `b`=0 where `a`=@a;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

We'll try this testcase again later with more rows in the table, but, even results above illustrate the problem with execution time (50 seconds vs. 0 seconds).

We've more data on this testcase from slow log:

# Time: 130402 14:05:10
# User@Host: [] @  []  Id: 184467
# Query_time: 42.576743  Lock_time: 0.000114 Rows_sent: 0  Rows_examined: 48828131
SET timestamp=1364897110;
update `t1` set `b`=0 where `a`=@`id`;

Thanks for testing.  So it seems the problem is simple, but I missed something.  Can you upload a .txt file containing the output of the following from master & slave:

SHOW GLOBAL VARIABLES;
SHOW SLAVE STATUS;
SHOW MASTER STATUS;

Then I could zero in on the offending configuration..

SHOW GLOBAL VARIABLES + SHOW SLAVE/MASTER STATUS

Attachment: server_variables.txt (text/plain), 27.60 KiB.

Hello, Shane.
Do you have any news about this (possibly) bug?

Duplicate of bug we already have interally:
Bug 16743559 - FULL TABLE SCAN ON SLAVE WITH USER DEFINED VARIABLES AND REPLICATE-WILD-DO-TABLE

The workaround is to remove the filter :

Replicate_Wild_Ignore_Table: mysql.%,test.%

The bug is linked to that option only.

Arnauld,

Depending on your replication configuration and the databases in the masters and slaves the work around you suggest of removing the configuration settings of Replicate_Wild_* may not be appropriate or wanted.

If it can be applied then it does seem to solve the problem.
Also seen on 5.6.11. (from Bug 16743559)

This has been fixed in 5.5.32, 5.6.12, and 5.7.2.