← Back to team overview

maria-developers team mailing list archive

  1. maria-developers team
  2. Mailing list archive
  3. Message #10170

Re: Fix for TokuDB and parallel replication

  Thread Previous • Date Previous • • Thread Next 
I've just check what happened at position 1046751490 in the binlog.
It seems the entry corresponds to a table having a trigger, don't know if it could have an impact on the parallel replication ? 


/*!100001 SET @@session.gtid_seq_no=482509269*//*!*/;
BEGIN
/*!*/;
# at 1046751112
#161209 11:50:35 server id 1 end_log_pos 1046751203 Table_map: `sc_2`.`sc_feed` mapped to number 93614 (has triggers) 
# at 1046751203
#161209 11:50:35 server id 1 end_log_pos 1046751299 Table_map: `sc_2`.`_sc_feed_new` mapped to number 197 
# at 1046751299
# at 1046751381
#161209 11:50:35 server id 1 end_log_pos 1046751381 Write_rows: table id 93614 #161209 11:50:35 server id 1 end_log_pos 1046751463 Write_rows: table id 197 flags: STMT_END_F 

BINLOG '
e4xKWBMBAAAAWwAAAOMnZD4AAK5tAQAAAAFABHNjXzIAB3NjX2ZlZWQAJAMDAwMDAwEBAQEBAQEB
AQ8DAQEBAwMDAwMDAwEDAwMDEREBDwYsAQAA/QL8///3CQ==
e4xKWBMBAAAAYAAAAEMoZD4AAMUAAAAAAAEABHNjXzIADF9zY19mZWVkX25ldwAkAwMDAwMDAQEB
AQEBAQEBDwMBAQEDAwMDAwMDAQMDAwMREQEPBiwBAAD9Avz///cJ
e4xKWBcBAAAAUgAAAJUoZD4AAK5tAQAAAAAAJP//////FPLf9/AwWw0HuAsGAF0SDQAXMboGBggH
AAAAAAAAAFhKjHtYSox7AQcAY3Jvbi0wMQ==
### INSERT INTO `sc_2`.`sc_feed`
### SET
###   @1=118315824 /* INT meta=0 nullable=0 is_null=0 */
###   @2=396216 /* INT meta=0 nullable=0 is_null=0 */
###   @3=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @4=856669 /* INT meta=0 nullable=1 is_null=0 */
###   @5=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @6=112865559 /* INT meta=0 nullable=1 is_null=0 */
###   @7=6 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @8=8 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @9=7 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @10=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @11=0 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @12=0 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @13=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @14=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @15=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @16=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
###   @17=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @18=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @19=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @20=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @21=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @22=0 /* INT meta=0 nullable=1 is_null=0 */
###   @23=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @24=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @25=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @26=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @27=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @28=0 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @29=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @30=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @31=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @32=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @33=1481280635 /* TIMESTAMP(0) meta=0 nullable=1 is_null=0 */
###   @34=1481280635 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
###   @35=1 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @36='cron-01' /* VARSTRING(765) meta=765 nullable=1 is_null=0 */
e4xKWBcBAAAAUgAAAOcoZD4AAMUAAAAAAAEAJP//////FPLf9/AwWw0HuAsGAF0SDQAXMboGBggH
AAAAAAAAAFhKjHtYSox7AQcAY3Jvbi0wMQ==
'/*!*/;
### INSERT INTO `sc_2`.`_sc_feed_new`
### SET
###   @1=118315824 /* INT meta=0 nullable=0 is_null=0 */
###   @2=396216 /* INT meta=0 nullable=0 is_null=0 */
###   @3=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @4=856669 /* INT meta=0 nullable=1 is_null=0 */
###   @5=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @6=112865559 /* INT meta=0 nullable=1 is_null=0 */
###   @7=6 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @8=8 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @9=7 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @10=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @11=0 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @12=0 /* TINYINT meta=0 nullable=1 is_null=0 */
###   @13=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @14=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @15=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @16=NULL /* VARSTRING(300) meta=300 nullable=1 is_null=1 */
###   @17=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @18=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @19=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @20=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @21=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @22=0 /* INT meta=0 nullable=1 is_null=0 */
###   @23=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @24=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @25=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @26=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @27=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @28=0 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @29=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @30=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @31=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @32=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @33=1481280635 /* TIMESTAMP(0) meta=0 nullable=1 is_null=0 */
###   @34=1481280635 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
###   @35=1 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @36='cron-01' /* VARSTRING(765) meta=765 nullable=1 is_null=0 */
# at 1046751463
#161209 11:50:35 server id 1  end_log_pos 1046751490     Xid = 9097980179
COMMIT/*!*/;
# at 1046751490

SHOW CREATE TRIGGER pt_osc_sc_2_sc_feed_ins\G
*************************** 1. row ***************************
               Trigger: pt_osc_sc_2_sc_feed_ins
sql_mode: NO_AUTO_VALUE_ON_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION SQL Original Statement: CREATE DEFINER=`root`@`localhost` TRIGGER `pt_osc_sc_2_sc_feed_ins` AFTER INSERT ON `sc_2`.`sc_feed` FOR EACH ROW REPLACE INTO `sc_2`.`_sc_feed_new` (`id`, `user_id`, `user_id_scout`, `product_id`, `contact_id`, `collection_id`, `type_id`, `subtype_id`, `rating`, `is_shopping_list`, `is_wish_list`, `is_wish_list_bis`, `is_recommend`, `is_review`, `is_current`, `list_id_product`, `list_id_list`, `is_like`, `is_comment_list`, `is_comment_review`, `feed_id_related`, `format_id`, `badge_id`, `param_index_id_trailer`, `message_id`, `shout_id`, `forum_topic_id`, `is_archive`, `application_id`, `gen_like_count`, `gen_comment_count`, `gen_message_topic_id`, `date_creation`, `date_last_update`, `flag_gen`, `host`) VALUES (NEW.`id`, NEW.`user_id`, NEW.`user_id_scout`, NEW.`product_id`, NEW.`contact_id`, NEW.`collection_id`, NEW.`type_id`, NEW.`subtype_id`, NEW.`rating`, NEW.`is_shopping_list`, NEW.`is_wish_list`, NEW.`is_wish_list_bis`, NEW.`is_recommend`, NEW.`is_review`, NEW.`is_current`, NEW.`list_id_product`, NEW.`list_id_list`, NEW.`is_like`, NEW.`is_comment_list`, NEW.`is_comment_review`, NEW.`feed_id_related`, NEW.`format_id`, NEW.`badge_id`, NEW.`param_index_id_trailer`, NEW.`message_id`, NEW.`shout_id`, NEW.`forum_topic_id`, NEW.`is_archive`, NEW.`application_id`, NEW.`gen_like_count`, NEW.`gen_comment_count`, NEW.`gen_message_topic_id`, NEW.`date_creation`, NEW.`date_last_update`, NEW.`flag_gen`, NEW.`host`) 
  character_set_client: latin1
  collation_connection: latin1_swedish_ci
    Database Collation: utf8_general_ci
1 row in set (0.00 sec)



Jocelyn Fournier
Founder
M : +33 6 51 21 54 10
https://www.softizy.com
Softizy - At your side to Optimize your PHP / MySQL applications

Le 09/12/2016 à 13:29, jocelyn fournier a écrit :


Ok, to make it clear, here are the actions related to the log entries :


*** Server startup : ***
2016-12-09 11:48:05 140259564768000 [Note] Slave I/O thread: connected to master 'repl@172.16.4.1:3306',replication starts at GTID position '0-1-482499150' 2016-12-09 11:48:05 140259546905344 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001443' at position 973807119, relay log './sql-slave-relay-bin.000001' position: 4; GTID position '0-1-482499150' 

stop slave; set global slave_parallel_mode=optimistic;
2016-12-09 11:50:29 140259546905344 [Note] Error reading relay log event: slave SQL thread was killed 2016-12-09 11:50:29 140259564768000 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.001443', position 1041861449; GTID position 0-1-482509090 

*** start slave; ***
2016-12-09 11:50:43 140259546905344 [Note] Slave I/O thread: connected to master 'repl@172.16.4.1:3306',replication starts at GTID position '0-1-482509090' 2016-12-09 11:50:43 140259548117760 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001443' at position 1041861449, relay log './sql-slave-relay-bin.000001' position: 4; GTID position '0-1-482509090' 

*** SQL thread stopping by itself : ***
2016-12-09 11:50:45 140259548117760 [Note] Error reading relay log event: slave SQL thread was killed 

(no message "Slave SQL thread exiting...")

Associated show slave status :

MariaDB [(none)]> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 172.16.4.1
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.001443
Read_Master_Log_Pos: 1047027234
Relay_Log_File: sql-slave-relay-bin.000002
Relay_Log_Pos: 4890750
Relay_Master_Log_File: mysql-bin.001443
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB: sc_2,percona
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: 1046751490
Relay_Log_Space: 5166796
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: NULL
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-482509567
Replicate_Do_Domain_Ids:
Replicate_Ignore_Domain_Ids:
Parallel_Mode: optimistic
1 row in set (0.00 sec)

*** start slave; ***
2016-12-09 11:52:03 140259547511552 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001443' at position 1046751490, relay log './sql-slave-relay-bin.000002' position: 4890750; GTID position '0-1-482509269' 

*** SQL thread stopping by itself ***

This time no slave "SQL thread was killed" message.
2016-12-09 11:52:05 140259547511552 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.001443' at position 1047219058; GTID position '0-1-482509775' 

MariaDB [(none)]> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 172.16.4.1
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.001444
Read_Master_Log_Pos: 6700262
Relay_Log_File: sql-slave-relay-bin.000002
Relay_Log_Pos: 5358318
Relay_Master_Log_File: mysql-bin.001443
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB: sc_2,percona
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: 1047219058
Relay_Log_Space: 38586524
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: NULL
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-482514272
Replicate_Do_Domain_Ids:
Replicate_Ignore_Domain_Ids:
Parallel_Mode: optimistic
1 row in set (0.00 sec)

HTH,


Jocelyn Fournier
Founder
M : +33 6 51 21 54 10
https://www.softizy.com
Softizy - At your side to Optimize your PHP / MySQL applications
Le 09/12/2016 à 12:01, jocelyn fournier a écrit :

Hi Kristian,
I've just tried your tokudb_optimistic_parallel_replication branch, and it behaves very strangely: the SQL thread stop by itself without any replication error when the parallel_mode is set to optimistic. 

In the error.log :
2016-12-09 11:48:05 140259564768000 [Note] Slave I/O thread: connected to master 'repl@172.16.4.1:3306',replication starts at GTID position '0-1-482499150' 2016-12-09 11:48:05 140259546905344 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001443' at position 973807119, relay log './sql-slave-relay-bin.000001' position: 4; GTID position '0-1-482499150' 2016-12-09 11:50:29 140259546905344 [Note] Error reading relay log event: slave SQL thread was killed 2016-12-09 11:50:29 140259564768000 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.001443', position 1041861449; GTID position 0-1-482509090 2016-12-09 11:50:43 140259546905344 [Note] Slave I/O thread: connected to master 'repl@172.16.4.1:3306',replication starts at GTID position '0-1-482509090' 2016-12-09 11:50:43 140259548117760 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001443' at position 1041861449, relay log './sql-slave-relay-bin.000001' position: 4; GTID position '0-1-482509090' 2016-12-09 11:50:45 140259548117760 [Note] Error reading relay log event: slave SQL thread was killed 2016-12-09 11:52:03 140259547511552 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001443' at position 1046751490, relay log './sql-slave-relay-bin.000002' position: 4890750; GTID position '0-1-482509269' 2016-12-09 11:52:05 140259547511552 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.001443' at position 1047219058; GTID position '0-1-482509775'
Switching back to conservative mode, and all is working properly. Any idea what could be wrong? 


Thanks!


Jocelyn Fournier
Founder
M : +33 6 51 21 54 10
https://www.softizy.com
Softizy - At your side to Optimize your PHP / MySQL applications

Le 28/11/2016 à 10:10, Kristian Nielsen a écrit :
Parallel replication so far did not work well with TokuDB, as some people who tried it found out. I have now pushed to 10.1 some patches to solve the 
problems. There are two main fixes:
1. Fix some races where a waiting transaction would miss its wakeup and get a lock timeout on a waiting row lock, even though the lock was released by the holding transaction. This fix is due to great work by Rich Prohaska. This problem is actually not specific to replication, normal transactions on 
a master will experience it too. But it hurts replication a lot, since
replication must commit transactions in order, so one stalled transaction 
stalls all following transactions as well.
2. Implement the conflict detection and handling necessary for optimistic 
parallel replication to work. This basically implements
thd_rpl_deadlock_check() and hton->kill_query methods. This should solve the problems where optimistic parallel replication with TokuDB breaks with lock 
wait timeouts.
If someone wants to test it, I have made a tree available with just these 
fixes on top of MariaDB 10.1.19:

https://github.com/knielsen/server/tree/tokudb_optimistic_parallel_replication

The fix should appear in 10.1.20 eventually.

The first part of the patch has also been submitted by Rich to
upstream. When this is (hopefully) merged upstream, and upstream merged into MariaDB, the MariaDB version of the fix should be replaced with the Percona one. I tried making the MariaDB version of the fix identical to Rich's pull request and keeping it in a separate commit, so this should hopefully be 
simple to do when the time comes.

  - Kristian.

_______________________________________________
Mailing list: https://launchpad.net/~maria-developers
Post to     : maria-developers@xxxxxxxxxxxxxxxxxxx
Unsubscribe : https://launchpad.net/~maria-developers
More help   : https://help.launchpad.net/ListHelp

Follow ups

References

  Thread Previous • Date Previous • • Thread Next