[MDEV-7888] ANALYZE TABLE does wakeup_subsequent_commits(), causing wrong binlog order and parallel replication hang Created: 2015-03-31  Updated: 2015-04-08  Resolved: 2015-04-08

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.0.17, 10.1
Fix Version/s: 10.0.18, 10.1.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Kristian Nielsen
Resolution: Fixed Votes: 0
Labels: parallelslave

Attachments: File mysql-bin.000001    
Issue Links:
Relates
relates to MDEV-7929 record_gtid() for non-transactional e... Closed

 Description   

All threads seem to be waiting for some 'prior transaction' which is not there.

MariaDB [(none)]> show processlist;
 
+----+-------------+-----------------+-------+---------+------+--------------------------------------------------------------------------------+---------------------------------------------------+----------+
 
| Id | User        | Host            | db    | Command | Time | State                                                                          | Info                                              | Progress |
 
+----+-------------+-----------------+-------+---------+------+--------------------------------------------------------------------------------+---------------------------------------------------+----------+
 
|  2 | system user |                 | NULL  | Connect | 6220 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
|  3 | system user |                 | NULL  | Connect | 6033 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
|  4 | system user |                 | NULL  | Connect | 6220 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
|  5 | system user |                 | NULL  | Connect | 6063 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
|  6 | system user |                 | NULL  | Connect | 6035 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
|  7 | system user |                 | NULL  | Connect | 6065 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
|  8 | system user |                 | NULL  | Connect | 6063 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
|  9 | system user |                 | NULL  | Connect | 6064 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 10 | system user |                 | NULL  | Connect | 6035 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 11 | system user |                 | NULL  | Connect | 6122 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 12 | system user |                 | NULL  | Connect | 6220 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 13 | system user |                 | NULL  | Connect | 6220 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 14 | system user |                 | NULL  | Connect | 6122 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 15 | system user |                 | NULL  | Connect | 6220 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 16 | system user |                 | NULL  | Connect | 6064 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 17 | system user |                 | NULL  | Connect | 6064 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 18 | system user |                 | NULL  | Connect | 6064 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 19 | system user |                 | NULL  | Connect | 6122 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 20 | system user |                 | NULL  | Connect | 6064 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 21 | system user |                 | NULL  | Connect | 6122 | Waiting for prior transaction to start commit before starting next transaction | NULL                                              |    0.000 |
 
| 22 | root        | localhost:46784 | mysql | Query   | 5863 | Waiting for the slave SQL thread to advance position                           | SELECT MASTER_POS_WAIT('mysql-bin.000001',168906) |    0.000 |
 
| 23 | system user |                 | NULL  | Connect | 6279 | Waiting for master to send event                                               | NULL                                              |    0.000 |
 
| 24 | system user |                 | NULL  | Connect | 6279 | Slave has read all relay log; waiting for the slave I/O thread to update it    | NULL                                              |    0.000 |
 
| 42 | root        | localhost:47011 | NULL  | Query   |    0 | init                                                                           | show processlist                                  |    0.000 |
 
+----+-------------+-----------------+-------+---------+------+--------------------------------------------------------------------------------+---------------------------------------------------+----------+
 

MariaDB [(none)]> show slave status \G
 
*************************** 1. row ***************************
 
               Slave_IO_State: Waiting for master to send event
 
                  Master_Host: 127.0.0.1
 
                  Master_User: root
 
                  Master_Port: 10730
 
                Connect_Retry: 1
 
              Master_Log_File: mysql-bin.000001
 
          Read_Master_Log_Pos: 168906
 
               Relay_Log_File: mysql-relay-bin.000002
 
                Relay_Log_Pos: 127819
 
        Relay_Master_Log_File: mysql-bin.000001
 
             Slave_IO_Running: Yes
 
            Slave_SQL_Running: Yes
 
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
 
                   Last_Error: 
                 Skip_Counter: 0
 
          Exec_Master_Log_Pos: 127532
 
              Relay_Log_Space: 169490
 
              Until_Condition: None
 
               Until_Log_File: 
                Until_Log_Pos: 0
 
           Master_SSL_Allowed: No
 
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 6063
 
Master_SSL_Verify_Server_Cert: No
 
                Last_IO_Errno: 0
 
                Last_IO_Error: 
               Last_SQL_Errno: 0
 
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
                   Using_Gtid: Slave_Pos
 
                  Gtid_IO_Pos: 0-1-483
 
      Replicate_Do_Domain_Ids: 
  Replicate_Ignore_Domain_Ids: 
                Parallel_Mode: optimistic
 
1 row in set (0.00 sec)

Fragment of the binlog, 100 lines before and 100 lines after the current Exec_Master_Log_Pos: 127532

 
/*!*/;
 
# at 126456
 
#150331  0:48:15 server id 1  end_log_pos 126484 	Intvar
 
SET INSERT_ID=60/*!*/;
 
# at 126484
 
#150331  0:48:15 server id 1  end_log_pos 126621 	Query	thread_id=43	exec_time=1	error_code=0
 
SET TIMESTAMP=1427752095/*!*/;
 
REPLACE LOW_PRIORITY INTO `table0_innodb_int_autoinc` (`pk`) VALUES (NULL)
 
/*!*/;
 
# at 126621
 
#150331  0:48:15 server id 1  end_log_pos 126648 	Xid = 2409
 
COMMIT/*!*/;
 
# at 126648
 
#150331  0:48:14 server id 1  end_log_pos 126686 	GTID 0-1-375
 
/*!100001 SET @@session.gtid_seq_no=375*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 126686
 
# at 126760
 
#150331  0:48:14 server id 1  end_log_pos 126760 	Table_map: `test`.`table100_innodb_int_autoinc` mapped to number 126
 
#150331  0:48:14 server id 1  end_log_pos 126839 	Delete_rows: table id 126 flags: STMT_END_F
 
### DELETE FROM `test`.`table100_innodb_int_autoinc`
 
### WHERE
 
###   @1=26
 
###   @2=138
 
###   @3=NULL
 
###   @4=NULL
 
###   @5='4'
 
### DELETE FROM `test`.`table100_innodb_int_autoinc`
 
### WHERE
 
###   @1=7
 
###   @2=4
 
###   @3='was'
 
###   @4=245
 
###   @5='3'
 
### DELETE FROM `test`.`table100_innodb_int_autoinc`
 
### WHERE
 
###   @1=9
 
###   @2=6
 
###   @3='yeah'
 
###   @4=5
 
###   @5='3'
 
# at 126839
 
#150331  0:48:14 server id 1  end_log_pos 126866 	Xid = 2357
 
COMMIT/*!*/;
 
# at 126866
 
#150331  0:48:14 server id 1  end_log_pos 126904 	GTID 0-1-376
 
/*!100001 SET @@session.gtid_seq_no=376*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 126904
 
#150331  0:48:14 server id 1  end_log_pos 126932 	Intvar
 
SET INSERT_ID=45/*!*/;
 
# at 126932
 
#150331  0:48:14 server id 1  end_log_pos 127113 	Query	thread_id=35	exec_time=2	error_code=0
 
SET TIMESTAMP=1427752094/*!*/;
 
REPLACE LOW_PRIORITY INTO `table1_innodb_int_autoinc` ( `col_int_key`, `col_char_12` ) VALUES ( 'm', 2 ), ( 166, 238 )
 
/*!*/;
 
# at 127113
 
#150331  0:48:14 server id 1  end_log_pos 127140 	Xid = 2378
 
COMMIT/*!*/;
 
# at 127140
 
#150331  0:48:14 server id 1  end_log_pos 127178 	GTID 0-1-377
 
/*!100001 SET @@session.gtid_seq_no=377*//*!*/;
 
# at 127178
 
#150331  0:48:14 server id 1  end_log_pos 127336 	Query	thread_id=37	exec_time=2	error_code=0
 
SET TIMESTAMP=1427752094/*!*/;
 
ANALYZE TABLE `table0_innodb_key_pk_parts_2_int_autoinc` PERSISTENT FOR COLUMNS ALL INDEXES ALL
 
/*!*/;
 
# at 127336
 
#150331  0:48:16 server id 1  end_log_pos 127374 	GTID 0-1-378
 
/*!100001 SET @@session.gtid_seq_no=378*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 127374
 
# at 127446
 
#150331  0:48:16 server id 1  end_log_pos 127446 	Table_map: `test`.`table2_innodb_int_autoinc` mapped to number 123
 
#150331  0:48:16 server id 1  end_log_pos 127505 	Delete_rows: table id 123 flags: STMT_END_F
 
### DELETE FROM `test`.`table2_innodb_int_autoinc`
 
### WHERE
 
###   @1=NULL
 
###   @2=69
 
###   @3=NULL
 
###   @4=NULL
 
###   @5=NULL
 
### DELETE FROM `test`.`table2_innodb_int_autoinc`
 
### WHERE
 
###   @1=NULL
 
###   @2=70
 
###   @3=NULL
 
###   @4=NULL
 
###   @5=NULL
 
### DELETE FROM `test`.`table2_innodb_int_autoinc`
 
### WHERE
 
###   @1=NULL
 
###   @2=74
 
###   @3=2
 
###   @4='1404370944'
 
###   @5=NULL
 
# at 127505
 
#150331  0:48:16 server id 1  end_log_pos 127532 	Xid = 2435
 
COMMIT/*!*/;
 
# at 127532
 
#150331  0:48:14 server id 1  end_log_pos 127570 	GTID 0-1-379
 
/*!100001 SET @@session.gtid_seq_no=379*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 127570
 
#150331  0:48:14 server id 1  end_log_pos 127874 	Query	thread_id=34	exec_time=2	error_code=0
 
SET TIMESTAMP=1427752094/*!*/;
 
CREATE OR REPLACE TABLE `create_or_replace_tmp` (
 
  `col_int` int(11) DEFAULT NULL,
 
  `col_int_key` int(11) DEFAULT NULL,
 
  `col_char_12` char(12) DEFAULT NULL,
 
  `pk` int(11) NOT NULL DEFAULT '0',
 
  `col_char_12_key` char(12) DEFAULT NULL
 
)
 
/*!*/;
 
# at 127874
 
# at 127942
 
#150331  0:48:14 server id 1  end_log_pos 127942 	Table_map: `test`.`create_or_replace_tmp` mapped to number 137
 
#150331  0:48:14 server id 1  end_log_pos 128275 	Write_rows: table id 137 flags: STMT_END_F
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=NULL
 
###   @3='2147483647'
 
###   @4=11
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=9
 
###   @2=NULL
 
###   @3=NULL
 
###   @4=15
 
###   @5='77987840'
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=0
 
###   @2=NULL
 
###   @3=NULL
 
###   @4=17
 
###   @5='77987840'
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=9
 
###   @2=8
 
###   @3=NULL
 
###   @4=25
 
###   @5='182'
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=NULL
 
###   @3='13'
 
###   @4=43
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=NULL
 
###   @3='10'
 
###   @4=45
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=219
 
###   @3='211'
 
###   @4=47
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=NULL
 
###   @3='54'
 
###   @4=49
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=NULL
 
###   @3='55'
 
###   @4=51
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=NULL
 
###   @3='10'
 
###   @4=53
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=9
 
###   @2=NULL
 
###   @3=NULL
 
###   @4=55
 
###   @5=NULL
 
### INSERT INTO `test`.`create_or_replace_tmp`
 
### SET
 
###   @1=NULL
 
###   @2=NULL

Full binlog is attached as mysql-bin.000001.

When I feed the same binlog to a slave via a master again, I get it stuck in a slightly different way:

MariaDB [test]> show processlist;
 
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------------------------------+------------------+----------+
 
| Id | User        | Host            | db   | Command | Time | State                                                                          | Info             | Progress |
 
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------------------------------+------------------+----------+
 
|  2 | system user |                 | NULL | Connect | 9338 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  3 | system user |                 | NULL | Connect | 9331 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  4 | system user |                 | NULL | Connect | 9332 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  5 | system user |                 | NULL | Connect | 9331 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  6 | system user |                 | NULL | Connect | 9338 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  7 | system user |                 | NULL | Connect | 9333 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  8 | system user |                 | NULL | Connect | 9331 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
|  9 | system user |                 | NULL | Connect | 9333 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 10 | system user |                 | NULL | Connect | 9332 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 11 | system user |                 | NULL | Connect | 9333 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 12 | system user |                 | NULL | Connect | 9333 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 13 | system user |                 | NULL | Connect | 9342 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 14 | system user |                 | NULL | Connect | 9332 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 15 | system user |                 | NULL | Connect | 9332 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 16 | system user |                 | NULL | Connect | 9310 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 17 | system user |                 | NULL | Connect | 9331 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 18 | system user |                 | NULL | Connect | 9333 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 19 | system user |                 | NULL | Connect | 9330 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 20 | system user |                 | NULL | Connect | 9310 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 21 | system user |                 | NULL | Connect | 9310 | Waiting for prior transaction to start commit before starting next transaction | NULL             |    0.000 |
 
| 23 | root        | localhost:49859 | test | Query   |    0 | init                                                                           | show processlist |    0.000 |
 
| 24 | system user |                 | NULL | Connect |  292 | Waiting for master to send event                                               | NULL             |    0.000 |
 
| 25 | system user |                 | NULL | Connect |  291 | Waiting for prior transaction to commit                                        | NULL             |    0.000 |
 
+----+-------------+-----------------+------+---------+------+--------------------------------------------------------------------------------+------------------+----------+
 

MariaDB [test]> show slave status \G
 
*************************** 1. row ***************************
 
               Slave_IO_State: Waiting for master to send event
 
                  Master_Host: 127.0.0.1
 
                  Master_User: root
 
                  Master_Port: 10730
 
                Connect_Retry: 1
 
              Master_Log_File: mysql-bin.000002
 
          Read_Master_Log_Pos: 326
 
               Relay_Log_File: wheezy-64-relay-bin.000002
 
                Relay_Log_Pos: 36518
 
        Relay_Master_Log_File: mysql-bin.000001
 
             Slave_IO_Running: Yes
 
            Slave_SQL_Running: Yes
 
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
 
                   Last_Error: 
                 Skip_Counter: 0
 
          Exec_Master_Log_Pos: 36231
 
              Relay_Log_Space: 169859
 
              Until_Condition: None
 
               Until_Log_File: 
                Until_Log_Pos: 0
 
           Master_SSL_Allowed: No
 
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 9331
 
Master_SSL_Verify_Server_Cert: No
 
                Last_IO_Errno: 0
 
                Last_IO_Error: 
               Last_SQL_Errno: 0
 
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
 
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
                   Using_Gtid: Slave_Pos
 
                  Gtid_IO_Pos: 0-1-483
 
      Replicate_Do_Domain_Ids: 
  Replicate_Ignore_Domain_Ids: 
                Parallel_Mode: optimistic
 
1 row in set (0.01 sec)

Similar 201-line fragment from the binlog, for position 36231

 
/*!*/;
 
# at 35314
 
#150331  0:44:33 server id 1  end_log_pos 35341 	Xid = 434
 
COMMIT/*!*/;
 
# at 35341
 
#150331  0:44:54 server id 1  end_log_pos 35379 	GTID 0-1-104
 
/*!100001 SET @@session.gtid_seq_no=104*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 35379
 
# at 35451
 
#150331  0:44:54 server id 1  end_log_pos 35451 	Table_map: `test`.`table1_innodb_int_autoinc` mapped to number 120
 
#150331  0:44:54 server id 1  end_log_pos 35504 	Update_rows: table id 120 flags: STMT_END_F
 
### UPDATE `test`.`table1_innodb_int_autoinc`
 
### WHERE
 
###   @1='91'
 
###   @2=6
 
###   @3=NULL
 
###   @4=NULL
 
###   @5=2147483647
 
### SET
 
###   @1='5'
 
###   @2=6
 
###   @3=NULL
 
###   @4=NULL
 
###   @5=2147483647
 
# at 35504
 
#150331  0:44:54 server id 1  end_log_pos 35531 	Xid = 508
 
COMMIT/*!*/;
 
# at 35531
 
#150331  0:44:54 server id 1  end_log_pos 35569 	GTID 0-1-105
 
/*!100001 SET @@session.gtid_seq_no=105*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 35569
 
#150331  0:44:54 server id 1  end_log_pos 35597 	Intvar
 
SET INSERT_ID=8/*!*/;
 
# at 35597
 
#150331  0:44:54 server id 1  end_log_pos 35776 	Query	thread_id=46	exec_time=2	error_code=0
 
SET TIMESTAMP=1427751894/*!*/;
 
REPLACE LOW_PRIORITY INTO `table1_innodb_int_autoinc` ( `col_int_key`, `col_int` ) VALUES ( 'v', 'c' ), ( 'v', 106 )
 
/*!*/;
 
# at 35776
 
#150331  0:44:54 server id 1  end_log_pos 35803 	Xid = 520
 
COMMIT/*!*/;
 
# at 35803
 
#150331  0:44:54 server id 1  end_log_pos 35841 	GTID 0-1-106
 
/*!100001 SET @@session.gtid_seq_no=106*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 35841
 
# at 35913
 
#150331  0:44:54 server id 1  end_log_pos 35913 	Table_map: `test`.`table1_innodb_int_autoinc` mapped to number 120
 
#150331  0:44:54 server id 1  end_log_pos 36021 	Update_rows: table id 120 flags: STMT_END_F
 
### UPDATE `test`.`table1_innodb_int_autoinc`
 
### WHERE
 
###   @1=NULL
 
###   @2=8
 
###   @3=NULL
 
###   @4=0
 
###   @5=0
 
### SET
 
###   @1=NULL
 
###   @2=8
 
###   @3=NULL
 
###   @4=0
 
###   @5=2147483647
 
### UPDATE `test`.`table1_innodb_int_autoinc`
 
### WHERE
 
###   @1=NULL
 
###   @2=9
 
###   @3=NULL
 
###   @4=106
 
###   @5=0
 
### SET
 
###   @1=NULL
 
###   @2=9
 
###   @3=NULL
 
###   @4=106
 
###   @5=2147483647
 
### UPDATE `test`.`table1_innodb_int_autoinc`
 
### WHERE
 
###   @1='159'
 
###   @2=7
 
###   @3=NULL
 
###   @4=NULL
 
###   @5=0
 
### SET
 
###   @1='159'
 
###   @2=7
 
###   @3=NULL
 
###   @4=NULL
 
###   @5=2147483647
 
# at 36021
 
#150331  0:44:54 server id 1  end_log_pos 36048 	Xid = 519
 
COMMIT/*!*/;
 
# at 36048
 
#150331  0:44:34 server id 1  end_log_pos 36086 	GTID 0-1-107
 
/*!100001 SET @@session.gtid_seq_no=107*//*!*/;
 
# at 36086
 
#150331  0:44:34 server id 1  end_log_pos 36231 	Query	thread_id=37	exec_time=30	error_code=0
 
SET TIMESTAMP=1427751874/*!*/;
 
ANALYZE TABLE `table100_innodb_int_autoinc` PERSISTENT FOR COLUMNS ( ) INDEXES ALL
 
/*!*/;
 
# at 36231
 
#150331  0:45:04 server id 1  end_log_pos 36269 	GTID 0-1-108
 
/*!100001 SET @@session.gtid_seq_no=108*//*!*/;
 
# at 36269
 
#150331  0:45:04 server id 1  end_log_pos 36423 	Query	thread_id=34	exec_time=1	error_code=0
 
SET TIMESTAMP=1427751904/*!*/;
 
SET @@session.pseudo_thread_id=34/*!*/;
 
CREATE OR REPLACE TEMPORARY TABLE `create_or_replace_tmp` LIKE `table10_innodb_int_autoinc`
 
/*!*/;
 
# at 36423
 
#150331  0:45:05 server id 1  end_log_pos 36461 	GTID 0-1-109
 
/*!100001 SET @@session.gtid_seq_no=109*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 36461
 
#150331  0:44:30 server id 1  end_log_pos 36489 	Intvar
 
SET INSERT_ID=11/*!*/;
 
# at 36489
 
#150331  0:44:30 server id 1  end_log_pos 36641 	Query	thread_id=44	exec_time=0	error_code=0
 
SET TIMESTAMP=1427751870/*!*/;
 
INSERT LOW_PRIORITY INTO `table10_innodb_key_pk_parts_2_int_autoinc` (`pk`) VALUES (NULL)
 
/*!*/;
 
# at 36641
 
#150331  0:44:33 server id 1  end_log_pos 36669 	Intvar
 
SET INSERT_ID=6/*!*/;
 
# at 36669
 
#150331  0:44:33 server id 1  end_log_pos 36820 	Query	thread_id=44	exec_time=0	error_code=0
 
SET TIMESTAMP=1427751873/*!*/;
 
INSERT LOW_PRIORITY INTO `table1_innodb_key_pk_parts_2_int_autoinc` (`pk`) VALUES (NULL)
 
/*!*/;
 
# at 36820
 
# at 36894
 
#150331  0:44:33 server id 1  end_log_pos 36894 	Table_map: `test`.`table100_innodb_int_autoinc` mapped to number 117
 
#150331  0:44:33 server id 1  end_log_pos 37009 	Update_rows: table id 117 flags: STMT_END_F
 
### UPDATE `test`.`table100_innodb_int_autoinc`
 
### WHERE
 
###   @1=NULL
 
###   @2=19
 
###   @3='did'
 
###   @4=3
 
###   @5='eeeif'
 
### SET
 
###   @1=NULL
 
###   @2=19
 
###   @3='did'
 
###   @4=3
 
###   @5='j'
 
### UPDATE `test`.`table100_innodb_int_autoinc`
 
### WHERE
 
###   @1=9
 
###   @2=6
 
###   @3='yeah'
 
###   @4=1
 
###   @5='yuxleyeiieee'
 
### SET
 
###   @1=9
 
###   @2=6
 
###   @3='yeah'
 
###   @4=1
 
###   @5='j'
 
# at 37009
 
#150331  0:44:34 server id 1  end_log_pos 37037 	Intvar
 
SET INSERT_ID=105/*!*/;
 
# at 37037
 
#150331  0:44:34 server id 1  end_log_pos 37182 	Query	thread_id=44	exec_time=0	error_code=0
 
SET TIMESTAMP=1427751874/*!*/;
 
INSERT LOW_PRIORITY IGNORE INTO `table100_innodb_int_autoinc` (`pk`) VALUES (NULL)
 
/*!*/;
 
# at 37182
 
# at 37270
 
#150331  0:44:34 server id 1  end_log_pos 37270 	Table_map: `test`.`table10_innodb_key_pk_parts_2_int_autoinc` mapped to number 121
 
#150331  0:44:34 server id 1  end_log_pos 37482 	Update_rows: table id 121 flags: STMT_END_F
 
### UPDATE `test`.`table10_innodb_key_pk_parts_2_int_autoinc`
 
### WHERE
 
###   @1=NULL
 
###   @2=NULL
 
###   @3=NULL
 
###   @4=NULL
 
###   @5=11
 
### SET
 
###   @1=NULL
 
###   @2=NULL
 
###   @3=NULL
 
###   @4='183'
 
###   @5=11
 
### UPDATE `test`.`table10_innodb_key_pk_parts_2_int_autoinc`
 
### WHERE
 
###   @1='7'
 
###   @2=2
 
###   @3=NULL
 
###   @4='bgnesyuxle'
 
###   @5=6
 
### SET
 
###   @1='7'
 
###   @2=2
 
###   @3=NULL
 
###   @4='183'
 
###   @5=6
 
### UPDATE `test`.`table10_innodb_key_pk_parts_2_int_autoinc`
 
### WHERE
 
###   @1='7'

Again, bad things seem to happen around CREATE OR REPLACE TABLE, so maybe it's related.

To reproduce:

  • start master with the provided binary log, no special options needed

    My master command line options

    		 
    --server_id=1 --log-bin=mysql-bin

  • start slave with parallel threads and optimistic mode

    My slave command line options

    		 
    --server_id=2 --slave-parallel-mode=optimistic --slave-parallel-threads=20

  • start replication (with or without GTID, doesn't matter)
  • wait until it gets stuck, for me it's always at Exec_Master_Log_Pos: 36231.

Not reproducible without the optimistic mode.



 Comments   
Comment by Kristian Nielsen [ 2015-04-01 ]

Ok, the problem here seems to be ANALYZE TABLE. It does ha_trans_commit()
during its processing, which incorrectly makes the code think that the
statement has completed and binlogged on the slave (which it has not). This
then causes out-of-order binlogging and further grief.

(The bug should be in 10.0 / "conservative" mode also, but probably harder to
trigger).

So a work-around is to not binlog ANALYZE TABLE, meanwhile I'll find a way to
fix it properly...

Comment by Elena Stepanova [ 2015-04-02 ]

Just keep in mind that ANALYZE TABLE, among other things, might affect persistent statistics. I'm not saying that not binlogging it is a bad idea (in fact, I was always wondering why it was binlogged, and we just recently had a request from danblack for not doing it), but it can stop collecting persistent statistics on the slave in setups which now rely on it.

Comment by Daniel Black [ 2015-04-02 ]

clarifying, I was more after an option to binlog the results of the analyze table but not the command itself. Analyze table already has NO_WRITE_TO_BINLOG | LOCAL. (MDEV-7829)

Comment by Kristian Nielsen [ 2015-04-08 ]

http://lists.askmonty.org/pipermail/commits/2015-April/007723.html

Comment by Kristian Nielsen [ 2015-04-08 ]

10.1-specific part:

http://lists.askmonty.org/pipermail/commits/2015-April/007724.html

Comment by Elena Stepanova [ 2015-04-08 ]

Interestingly, I got this problem a lot with optimistic mode, but haven't got it even one time with the conservative mode, otherwise the same flow and options. So, apparently there is something about the optimistic mode that seriously increases the probability.

Comment by Kristian Nielsen [ 2015-04-08 ]

Yes, looking more, I was not actually able to trigger the observed problem directly in 10.0 (or in 10.1 conservative mode).

The logical problem exists in the code in 10.0 (and I have fixed it there). However, ANALYZE cannot actually be binlogged in the same group-commit as another event group, so it may not be possible to trigger it directly in conservative mode. (In the test case, I artificially simulate same group commit using DBUG injection).

So I agree this particular hang may not be possible to get in 10.0/conservative. I think maybe another consequence of the bug could be observable in 10.1 / conservative: out-of-order binlogging (different binlog order on slave compared to master). But I haven't actually checked that this is possible, and if it is the window of opportunity for the race should be very small, so hard to trigger.

Generated at Thu Feb 08 07:23:01 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.