Bug #1735555 “RBR Replication with concurrent XA in READ-COMMITT...” : Series 5.6 : Bugs : Percona Server moved to https://jira.percona.com/projects/PS

Kenny Gryp (gryp) on 2017-11-30

summary:

RBR Replication with concurrent XA in READ-COMMITTED takes supremum
- pseudo-records
+ pseudo-records and breaks replication

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2017-12-07:

#1

This is not the complete answer, just a note MySQL documentation says:

"If you use READ COMMITTED, you must use row-based binary logging. "

Vlad Lesin (vlad-lesin) on 2017-12-11

Changed in percona-server:
assignee:	nobody → Vlad Lesin (vlad-lesin)

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2017-12-12:

#2

Download full text (25.1 KiB)

I am working with 5.7.19-17.

I modified the code a little bit with the following patch:

==============patch==============================
--- a/storage/innobase/lock/lock0lock.cc
+++ b/storage/innobase/lock/lock0lock.cc
@@ -51,6 +51,27 @@ Created 5/7/1996 Heikki Tuuri

#include <set>

+extern "C" LEX_CSTRING thd_query_unsafe(MYSQL_THD thd);
+
+static void inline print_info_if_supremum(
+ const buf_block_t* block,
+ ulint heap_no,
+ ulint mode) {
+
+ const char *query = current_thd ? thd_query_unsafe(current_thd).str : "";
+
+ if (!query)
+ query = "";
+
+ if (heap_no == PAGE_HEAP_NO_SUPREMUM) {
+ ib::info() << ">>>>>>>> supremum is locked for page "
+ << block->page.id.page_no()
+ << ", mode " << mode
+ << ", query: " << query;
+ }
+
+}
+
/* Flag to enable/disable deadlock detector. */
my_bool innobase_deadlock_detect = TRUE;

@@ -2058,6 +2079,8 @@ lock_rec_lock(
|| mode - (LOCK_MODE_MASK & mode) == 0);
ut_ad(dict_index_is_clust(index) || !dict_index_is_online_ddl(index));

+ print_info_if_supremum(block, heap_no, mode);
+
        /* We try a simplified and faster subroutine for the most
        common cases */
        switch (lock_rec_lock_fast(impl, mode, block, heap_no, index, thr)) {

=================patch=============================

This patch outputs some info to error log on supremum page lock.

Then I modified the above test case, just added header, footer and the ability to change isolation level:

====================test=========================
--source include/master-slave.inc
--source include/have_innodb.inc
--source include/have_binlog_format_mixed.inc

#--let $isolation_level=REPEATABLE READ
--let $isolation_level=READ COMMITTED

--connection slave

--eval SET TRANSACTION ISOLATION LEVEL $isolation_level;

--connection master

--eval SET TRANSACTION ISOLATION LEVEL $isolation_level;

CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB;

INSERT INTO t1 VALUES (10000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (20000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (30000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (40000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (50000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (60000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (70000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (80000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (90000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (100000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (110000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (120000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (130000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (140000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (150000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (160000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (170000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (180000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (190000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (200000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (210000, REPEAT("a", 2165));

DELETE FROM t1 WHERE t1_pk IN (90000, 80000);

CREATE TABLE t2 (t2_pk INT PRIM...

I am working with 5.7.19-17.

I modified the code a little bit with the following patch:

==============patch==============================
--- a/storage/innobase/lock/lock0lock.cc
+++ b/storage/innobase/lock/lock0lock.cc
@@ -51,6 +51,27 @@ Created 5/7/1996 Heikki Tuuri
 
 #include <set>
 
+extern "C" LEX_CSTRING thd_query_unsafe(MYSQL_THD thd);
+
+static void inline print_info_if_supremum(
+  const buf_block_t*   block,
+       ulint                   heap_no,
+  ulint                        mode) {
+
+  const char *query = current_thd ? thd_query_unsafe(current_thd).str : "";
+
+  if (!query)
+    query = "";
+
+  if (heap_no == PAGE_HEAP_NO_SUPREMUM) {
+    ib::info() << ">>>>>>>> supremum is locked for page "
+               << block->page.id.page_no()
+               << ", mode " << mode
+               << ", query: " << query;
+  }
+
+}
+
 /* Flag to enable/disable deadlock detector. */
 my_bool        innobase_deadlock_detect = TRUE;
 
@@ -2058,6 +2079,8 @@ lock_rec_lock(
              || mode - (LOCK_MODE_MASK & mode) == 0);
        ut_ad(dict_index_is_clust(index) || !dict_index_is_online_ddl(index));
 
+  print_info_if_supremum(block, heap_no, mode);
+
        /* We try a simplified and faster subroutine for the most
        common cases */
        switch (lock_rec_lock_fast(impl, mode, block, heap_no, index, thr)) {

=================patch=============================

This patch outputs some info to error log on supremum page lock.

Then I modified the above test case, just added header, footer and the ability to change isolation level:

====================test=========================
--source include/master-slave.inc
--source include/have_innodb.inc
--source include/have_binlog_format_mixed.inc

#--let $isolation_level=REPEATABLE READ
--let $isolation_level=READ COMMITTED

--connection slave

--eval SET TRANSACTION ISOLATION LEVEL $isolation_level;

--connection master

--eval SET TRANSACTION ISOLATION LEVEL $isolation_level;

CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB;

INSERT INTO t1 VALUES (10000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (20000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (30000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (40000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (50000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (60000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (70000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (80000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (90000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (100000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (110000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (120000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (130000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (140000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (150000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (160000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (170000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (180000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (190000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (200000, REPEAT("a", 2165));
INSERT INTO t1 VALUES (210000, REPEAT("a", 2165));

DELETE FROM t1 WHERE t1_pk IN (90000, 80000);

CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
  FOREIGN KEY (t1_pk) REFERENCES t1 (t1_pk)) ENGINE=InnoDB;

--connect(con2,localhost,root)
XA START '2';
INSERT INTO t1 VALUES (85000, NULL);

#-- We are inserting a value between 80000,100000

--connection master
XA START '1';
INSERT INTO t2 VALUES (1, 100000);

#-- This causes an S lock on 100000

XA END '1';
XA PREPARE '1';

--connection con2
XA END '2';
XA PREPARE '2';

--connection con2
XA COMMIT '2';

--connection master
XA COMMIT '1';

--sync_slave_with_master

--connection master
DROP TABLE t2;
DROP TABLE t1;

--source include/rpl_end.inc
======================test=============================

My goal was to see what supremum's are locked for the following options:

"binlog_format=MIXED, tx_isolation=READ COMMITTED : the events will be logged in RBR and replication will not break. There will be no supremum pseudo-record S locks"

I use the following command line to run the test:

./mtr --force --max-test-fail=1 --parallel=1 --debug-server lp-1735555

to see the output of the injected code the following commands can be used:

echo "master"; fgrep '>>>>>>>>' var/log/mysqld.1.err; echo "slave"; fgrep '>>>>>>>>' var/log/mysqld.2.err

The "lock-wait-timeout" error is not stable. I can repeat it only with mtr --repeat=20 options, so usually the first several times the test finished with success and then fails.

The output which I see for the "success" case:

============success output====================
master
2017-12-12T16:41:12.187081Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 3, query:
2017-12-12T16:41:12.261063Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.278305Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.278400Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.285368Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.285997Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.286218Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.287009Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.287344Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.589188Z 5 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: RESET MASTER
2017-12-12T16:41:12.669696Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.669762Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.670909Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.671303Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.671503Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.671672Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.674200Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query:
2017-12-12T16:41:12.675444Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query:
2017-12-12T16:41:12.687507Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.687559Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.689312Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.689918Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.690100Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.690266Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.690429Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.690590Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.690755Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.690940Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.693330Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 5, mode 2, query: INSERT INTO t2 VALUES (1, 100000)
2017-12-12T16:41:12.701107Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.701976Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.702763Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 273, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.702951Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 270, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.702981Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 271, mode 2, query: DROP TABLE t2
2017-12-12T16:41:12.703453Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 2, query: DROP TABLE t2
2017-12-12T16:41:12.703563Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 12, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.703843Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.704024Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 10, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.704184Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 8, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.704297Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.704404Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.704905Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 278, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.705060Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 282, mode 3, query: DROP TABLE t2
2017-12-12T16:41:12.706013Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: DROP TABLE t1
2017-12-12T16:41:12.708205Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 278, mode 3, query: DROP TABLE t1
2017-12-12T16:41:12.708294Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 282, mode 3, query: DROP TABLE t1
slave
2017-12-12T16:41:12.223650Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 3, query: 
2017-12-12T16:41:12.245553Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:41:12.262189Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:41:12.262285Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:41:12.276356Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:41:12.276998Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:41:12.277220Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.277951Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.278186Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:41:12.577703Z 4 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: RESET MASTER
2017-12-12T16:41:12.673576Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.673633Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.674627Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.674935Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.675133Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.675337Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:41:12.678018Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query:
2017-12-12T16:41:12.680092Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query:
2017-12-12T16:41:12.692699Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.692752Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.694810Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.695570Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.695782Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.695954Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.696124Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.696295Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.696464Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.696635Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:41:12.698486Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 5, mode 2, query: INSERT INTO t2 VALUES (1, 100000)
2017-12-12T16:41:12.706262Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.707094Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.708259Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 273, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.708444Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 270, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.708474Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 271, mode 2, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.708916Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 2, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.709023Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 12, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.709298Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.709487Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 10, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.709645Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 8, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.709757Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.709863Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.709954Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 278, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.710093Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 282, mode 3, query: DROP TABLE `t2` /* generated by server */
2017-12-12T16:41:12.710980Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: DROP TABLE `t1` /* generated by server */
2017-12-12T16:41:12.713121Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 278, mode 3, query: DROP TABLE `t1` /* generated by server */
2017-12-12T16:41:12.713208Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 282, mode 3, query: DROP TABLE `t1` /* generated by server */
=======================success output=========================

i.e. there is no S-lock for "INSERT INTO t2..." statement.

The output for the fail is the following:

=====================fail output==========
master
2017-12-12T16:45:08.126593Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 3, query:
2017-12-12T16:45:08.197859Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:45:08.214508Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query:
2017-12-12T16:45:08.214603Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.221567Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.222197Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.222418Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.223052Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.223307Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.558970Z 5 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: RESET MASTER
2017-12-12T16:45:08.638371Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.638428Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.639399Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.639686Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.639914Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.640079Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.642214Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: 
2017-12-12T16:45:08.644236Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: 
2017-12-12T16:45:08.656225Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.656277Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.658070Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.658678Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.658880Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.659045Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.659235Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.659414Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.659607Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.659798Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.662233Z 8 [Note] InnoDB: >>>>>>>> supremum is locked for page 5, mode 2, query: INSERT INTO t2 VALUES (1, 100000)
slave
2017-12-12T16:45:08.158843Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 11, mode 3, query: 
2017-12-12T16:45:08.234648Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.251726Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.251825Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.259350Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.260019Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.260250Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.260913Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.261148Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 2, query: 
2017-12-12T16:45:08.547449Z 4 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: RESET MASTER
2017-12-12T16:45:08.642087Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.642143Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.643216Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.643555Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.643748Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.643952Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB
2017-12-12T16:45:08.646202Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query:
2017-12-12T16:45:08.648104Z 0 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query:
2017-12-12T16:45:08.661656Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 276, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.661717Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 275, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.664067Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.664780Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.665053Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.665225Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.665401Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.665576Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.665741Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.665903Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 3, mode 3, query: CREATE TABLE t2 (t2_pk INT PRIMARY KEY, t1_pk DECIMAL(20,0),
2017-12-12T16:45:08.667206Z 7 [Note] InnoDB: >>>>>>>> supremum is locked for page 5, mode 2, query: INSERT INTO t2 VALUES (1, 100000)
========================fail output===========================

Here we can see supremum S-lock, but I don't see supremum X-lock. Probably the fail or success depends on data layout inside the page and we need more determinate test case.

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2017-12-12:

#3

Forgot to mention that the bug can be repeated on 5.7.19-17, but I can't repeat it on the latest 5.7 branch. But this does not mean it was fixed because our test results are unpredictable.

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2017-12-15:

#4

The test stops failing (at least for --repeat=100) on the following commit:

commit afb6d4b56f8e57b9a7f72022e912b401e570124b
Author: Laurynas Biveinis <email address hidden>
Date: Thu Aug 31 11:48:44 2017 +0300

Fix bug 1711781 (Redundant GTID unsafe mark for CREATE/DROP TEMPORARY TABLE in RBR/MBR)

  After fixing bug 1668602, bug 1539504, and bug 1313901, CREATE
  TEMPORARY TABLE is only logged under statement binary log mode, and
  DROP TEMPORARY TABLE is only logged if the corresponding CREATE
  TEMPORARY TABLE has been logged. However, a corresponding
  enforce_gtid_consistency check in THD::is_ddl_gtid_compatible has not
  been relaxed accordingly. This resulted that CREATE/DROP TEMPORARY
  TABLE statements were forbidden incorrectly in transactional contexts,
  including function and trigger calls, even when they required no
  binary logging at all.

  Fix by keeping only the CREATE TEMPORARY TABLE check in
  THD::is_ddl_gtid_compatible and lifting its restriction for row/mixed
  binary log modes. For DROP TEMPORARY TABLE, since its check requires
  knowing the binlog format at the corresponding CREATE TEMPORARY TABLE,
  move it to mysql_rm_table.

  Convert binlog.binlog_enforce_gtid_consistency test to an include file
  that is shared between two new binlog format-dependent tests
  binlog_stm_enforce_gtid_consistency and
  binlog_row_mix_enforce_gtid_consistency.

Revision history for this message

Kenny Gryp (gryp) wrote on 2017-12-15:

#5

The customers problem (XA Replication deadlock) can now be reproduced both on 5.7.19 as well as 5.7.20

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2017-12-27:

#6

There is some progress in understanding the case.

Here https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.19-logging-and-stable-test is the branch with additional logging and some facilities for debugging. It's based on 5.7.19 and all the following analysis is for 5.7.19 too. There is also stable mtr test suite which uses DEBUG_SYNC and DEBUG system variables. The code is quite dirty, so don't pay attention on cosmetics, it's just for debugging.

The first, the bug description is the same as I see in the error log after I added some diagnostics.

What is happening:

1) When slave thread executes "INSERT INTO t2 VALUES (1, 100000)" the supremum of the page which contains records if t1 for pk values 40000-90000 is S-locked. The lock must be released on commit, but commit for this transaction has not yet executed, so the supremum stays S-locked.

2) After some binlog events "INSERT INTO t1 VALUES (85000, NULL)" is executed and the supremum is tried to be X-locked. But it can't be X-locked because it has been already S-locked on step 1. As there was not commit for the transaction in (1), the supremum stays S-locked and after timeout the current transaction tries to X-lock the supremum again with the same result.

That's why slave thread is stopped.

The question is why the test is unstable. The answer is "because of purge". When some records are deleted from innodb page, they are marked as "deleted", but they still consume the space inside the page. "Purge" process deallocates this space. So, what's going on when the test passes successfully?

1) When "DELETE FROM t1 WHERE t1_pk IN (90000, 80000)" is executed the correspondent events inside of the page are marked as "deleted".

2) When slave thread executes "INSERT INTO t2 VALUES (1, 100000)" the supremum of the page which contains records of t1 for pk values 40000-90000 is S-locked.

3) After some binlog events "INSERT INTO t1 VALUES (85000, NULL)" is executed. As there was not "purge" on the page, there is no enough space in the page for the new record, the record is inserted in another page and the supremum of another space is X-locked successfully for this operation.

What was done to make the test stable(for 5.7.19)?

1) Wait until "DELETE FROM t1 WHERE t1_pk IN (90000, 80000)" is committed and deleted records are unlocked.

2) Wait until "purge" thread frees space from deleted records inside of the page.

3) Continue the test execution.

Despite my test(mysql-test/suite/rpl/t/lp-1735555-sync-points.test in the above branch) is stable for 5.7.19, I can't repeat the bug on 5.7.20.

There is some progress in understanding the case.

Here https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.19-logging-and-stable-test is the branch with additional logging and some facilities for debugging. It's based on 5.7.19 and all the following analysis is for 5.7.19 too. There is also stable mtr test suite which uses DEBUG_SYNC and DEBUG system variables. The code is quite dirty, so don't pay attention on cosmetics, it's just for debugging.

The first, the bug description is the same as I see in the error log after I added some diagnostics.

What is happening:

1) When slave thread executes "INSERT INTO t2 VALUES (1, 100000)" the supremum of the page which contains records if t1 for pk values 40000-90000 is S-locked. The lock must be released on commit, but commit for this transaction has not yet executed, so the supremum stays S-locked.

2) After some binlog events "INSERT INTO t1 VALUES (85000, NULL)" is executed and the supremum is tried to be X-locked. But it can't be X-locked because it has been already S-locked on step 1. As there was not commit for the transaction in (1), the supremum stays S-locked and after timeout the current transaction tries to X-lock the supremum again with the same result.

That's why slave thread is stopped.

The question is why the test is unstable. The answer is "because of purge". When some records are deleted from innodb page, they are marked as "deleted", but they still consume the space inside the page. "Purge" process deallocates this space. So, what's going on when the test passes successfully?

1) When "DELETE FROM t1 WHERE t1_pk IN (90000, 80000)" is executed the correspondent events inside of the page are marked as "deleted".

2) When slave thread executes "INSERT INTO t2 VALUES (1, 100000)" the supremum of the page which contains records of t1 for pk values 40000-90000 is S-locked.

3) After some binlog events "INSERT INTO t1 VALUES (85000, NULL)" is executed. As there was not "purge" on the page, there is no enough space in the page for the new record, the record is inserted in another page and the supremum of another space is X-locked successfully for this operation.

What was done to make the test stable(for 5.7.19)?

1) Wait until "DELETE FROM t1 WHERE t1_pk IN (90000, 80000)" is committed and deleted records are unlocked.

2) Wait until "purge" thread frees space from deleted records inside of the page.

3) Continue the test execution.

Despite my test(mysql-test/suite/rpl/t/lp-1735555-sync-points.test in the above branch) is stable for 5.7.19, I can't repeat the bug on 5.7.20.

Vlad Lesin (vlad-lesin) on 2017-12-28

Changed in percona-server:
status:	New → In Progress
importance:	Undecided → High

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2017-12-29:

#7

Download full text (13.1 KiB)

This is the answer on the question why I can't repeat the bug on 5.7.20 and why it can be repeated on the customer's environment with 5.7.20.

For this analysis I use the following code which contains my additional diagnostics and some variants of the test:

https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.19-logging-and-stable-test
https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.20-logging-and-stable-test

1) Let's look at the backtrace where S-lock is set on 5.7.19 slave:

==================bt 1.1==============================
#1 0x0000000001ae40bb in lock_rec_lock (impl=false, mode=2, block=0x7fffea66ff60, heap_no=1, index=0x7fff9c017610, thr=0x7fff9c02b300)
    at ./storage/innobase/lock/lock0lock.cc:2085
#2 0x0000000001aee27d in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffea66ff60, rec=0x7fffeac58070 "supremumu\210", index=0x7fff9c017610,
    offsets=0x7ffff10fcd30, mode=LOCK_S, gap_mode=0, thr=0x7fff9c02b300) at ./storage/innobase/lock/lock0lock.cc:6321
#3 0x0000000001b99e22 in row_ins_set_shared_rec_lock (type=0, block=0x7fffea66ff60, rec=0x7fffeac58070 "supremumu\210", index=0x7fff9c017610, offsets=0x7ffff10fcd30,
    thr=0x7fff9c02b300) at ./storage/innobase/row/row0ins.cc:1498
#4 0x0000000001b9a55d in row_ins_check_foreign_constraint (check_ref=1, foreign=0x7fff9c034e00, table=0x7fff9c02da90, entry=0x7fff9c02bba8, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:1725
#5 0x0000000001b9ac49 in row_ins_check_foreign_constraints (table=0x7fff9c02da90, index=0x7fff9c0350c0, entry=0x7fff9c02bba8, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:1964
#6 0x0000000001b9e7ac in row_ins_sec_index_entry (index=0x7fff9c0350c0, entry=0x7fff9c02bba8, thr=0x7fff9c02b300, dup_chk_only=false)
    at ./storage/innobase/row/row0ins.cc:3400
#7 0x0000000001b9ea7b in row_ins_index_entry (index=0x7fff9c0350c0, entry=0x7fff9c02bba8, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:3477
#8 0x0000000001b9efd5 in row_ins_index_entry_step (node=0x7fff9c02b088, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:3625
#9 0x0000000001b9f379 in row_ins (node=0x7fff9c02b088, thr=0x7fff9c02b300) at ./storage/innobase/row/row0ins.cc:3767
#10 0x0000000001b9f98d in row_ins_step (thr=0x7fff9c02b300) at ./storage/innobase/row/row0ins.cc:3952
#11 0x0000000001bc0895 in row_insert_for_mysql_using_ins_graph (mysql_rec=0x7fff9c0334b0 "\375\001", prebuilt=0x7fff9c02aae0)
    at ./storage/innobase/row/row0mysql.cc:2278
#12 0x0000000001bc0e8c in row_insert_for_mysql (mysql_rec=0x7fff9c0334b0 "\375\001", prebuilt=0x7fff9c02aae0)
    at ./storage/innobase/row/row0mysql.cc:2402
#13 0x0000000001a546da in ha_innobase::write_row (this=0x7fff9c02ee30, record=0x7fff9c0334b0 "\375\001")
    at ./storage/innobase/handler/ha_innodb.cc:8278
#14 0x0000000000fd7b48 in handler::ha_write_row (this=0x7fff9c02ee30, buf=0x7fff9c0334b0 "\375\001")
    at ./sql/handler.cc:8434
#15 0x000000000188a1af in write_record (thd=0x7fff9c000950, table=0x7fff9c02e470, info=0x7ffff10fdfb0, update=0x7ffff10fe030)
    at ./sql/sql_insert.cc:1875
#16 0x0000000001886ff9 in Sql...

This is the answer on the question why I can't repeat the bug on 5.7.20 and why it can be repeated on the customer's environment with 5.7.20.

For this analysis I use the following code which contains my additional diagnostics and some variants of the test:

https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.19-logging-and-stable-test
https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.20-logging-and-stable-test

1) Let's look at the backtrace where S-lock is set on 5.7.19 slave:

==================bt 1.1==============================
#1  0x0000000001ae40bb in lock_rec_lock (impl=false, mode=2, block=0x7fffea66ff60, heap_no=1, index=0x7fff9c017610, thr=0x7fff9c02b300)
    at ./storage/innobase/lock/lock0lock.cc:2085
#2  0x0000000001aee27d in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fffea66ff60, rec=0x7fffeac58070 "supremumu\210", index=0x7fff9c017610, 
    offsets=0x7ffff10fcd30, mode=LOCK_S, gap_mode=0, thr=0x7fff9c02b300) at ./storage/innobase/lock/lock0lock.cc:6321
#3  0x0000000001b99e22 in row_ins_set_shared_rec_lock (type=0, block=0x7fffea66ff60, rec=0x7fffeac58070 "supremumu\210", index=0x7fff9c017610, offsets=0x7ffff10fcd30, 
    thr=0x7fff9c02b300) at ./storage/innobase/row/row0ins.cc:1498
#4  0x0000000001b9a55d in row_ins_check_foreign_constraint (check_ref=1, foreign=0x7fff9c034e00, table=0x7fff9c02da90, entry=0x7fff9c02bba8, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:1725
#5  0x0000000001b9ac49 in row_ins_check_foreign_constraints (table=0x7fff9c02da90, index=0x7fff9c0350c0, entry=0x7fff9c02bba8, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:1964
#6  0x0000000001b9e7ac in row_ins_sec_index_entry (index=0x7fff9c0350c0, entry=0x7fff9c02bba8, thr=0x7fff9c02b300, dup_chk_only=false)
    at ./storage/innobase/row/row0ins.cc:3400
#7  0x0000000001b9ea7b in row_ins_index_entry (index=0x7fff9c0350c0, entry=0x7fff9c02bba8, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:3477
#8  0x0000000001b9efd5 in row_ins_index_entry_step (node=0x7fff9c02b088, thr=0x7fff9c02b300)
    at ./storage/innobase/row/row0ins.cc:3625
#9  0x0000000001b9f379 in row_ins (node=0x7fff9c02b088, thr=0x7fff9c02b300) at ./storage/innobase/row/row0ins.cc:3767
#10 0x0000000001b9f98d in row_ins_step (thr=0x7fff9c02b300) at ./storage/innobase/row/row0ins.cc:3952
#11 0x0000000001bc0895 in row_insert_for_mysql_using_ins_graph (mysql_rec=0x7fff9c0334b0 "\375\001", prebuilt=0x7fff9c02aae0)
    at ./storage/innobase/row/row0mysql.cc:2278
#12 0x0000000001bc0e8c in row_insert_for_mysql (mysql_rec=0x7fff9c0334b0 "\375\001", prebuilt=0x7fff9c02aae0)
    at ./storage/innobase/row/row0mysql.cc:2402
#13 0x0000000001a546da in ha_innobase::write_row (this=0x7fff9c02ee30, record=0x7fff9c0334b0 "\375\001")
    at ./storage/innobase/handler/ha_innodb.cc:8278
#14 0x0000000000fd7b48 in handler::ha_write_row (this=0x7fff9c02ee30, buf=0x7fff9c0334b0 "\375\001")
    at ./sql/handler.cc:8434
#15 0x000000000188a1af in write_record (thd=0x7fff9c000950, table=0x7fff9c02e470, info=0x7ffff10fdfb0, update=0x7ffff10fe030)
    at ./sql/sql_insert.cc:1875
#16 0x0000000001886ff9 in Sql_cmd_insert::mysql_insert (this=0x7fff9c0069f8, thd=0x7fff9c000950, table_list=0x7fff9c006468)
    at ./sql/sql_insert.cc:769
#17 0x000000000188e139 in Sql_cmd_insert::execute (this=0x7fff9c0069f8, thd=0x7fff9c000950) at ./sql/sql_insert.cc:3117
#18 0x000000000164b4e0 in mysql_execute_command (thd=0x7fff9c000950, first_level=true) at ./sql/sql_parse.cc:3748
#19 0x0000000001651ba6 in mysql_parse (thd=0x7fff9c000950, parser_state=0x7ffff10ff510) at ./sql/sql_parse.cc:5891
#20 0x00000000018d3c7b in Query_log_event::do_apply_event (this=0x7fff9c00eed0, rli=0x3917d20, query_arg=0x7fff9c017219 "INSERT INTO t2 VALUES (1, 100000)", 
    q_len_arg=33) at ./sql/log_event.cc:4718
#21 0x00000000018d2aa3 in Query_log_event::do_apply_event (this=0x7fff9c00eed0, rli=0x3917d20) at ./sql/log_event.cc:4437
#22 0x00000000018cf81a in Log_event::apply_event (this=0x7fff9c00eed0, rli=0x3917d20) at ./sql/log_event.cc:3447
#23 0x000000000194b7e1 in apply_event_and_update_pos (ptr_ev=0x7ffff10ff8a0, thd=0x7fff9c000950, rli=0x3917d20)
    at ./sql/rpl_slave.cc:4762
#24 0x000000000194cfa9 in exec_relay_log_event (thd=0x7fff9c000950, rli=0x3917d20) at ./sql/rpl_slave.cc:5277
#25 0x0000000001954395 in handle_slave_sql (arg=0x38b8120) at ./sql/rpl_slave.cc:7488
#26 0x0000000001e7cf07 in pfs_spawn_thread (arg=0x7fffa0103970) at ./storage/perfschema/pfs.cc:2188
#27 0x00007ffff6f5e6ba in start_thread (arg=0x7ffff1100700) at pthread_create.c:333
#28 0x00007ffff63f33dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
========================================

The key function here is row_ins_check_foreign_constraint(). If we look into this function we will see the criteria of gap locking:

------------code 1.1--------------------
dberr_t
row_ins_check_foreign_constraint(...)
{
...
	bool		skip_gap_lock;

skip_gap_lock = (trx->isolation_level <= TRX_ISO_READ_COMMITTED);
...
}
----------------------------------------

So gap locking is skipped if transaction isolation level is less than or equal to "READ COMMITTED". In other words, gap locking for the procedure of checking foreign keys is enabled only for "REPEATABLE READ" and "SERIALIZABLE" isolation levels.

2) Despite the global transaction isolation level the default transaction isolation level for slave thread is "REPEATABLE READ". It can be changed during relay log events execution.

3) The original binlog format is "mixed".

a) For 5.7.19 the statemets "INSERT INTO t2 VALUES (1, 100000)" and "INSERT INTO t1 VALUES (85000, NULL)" inside of different XA transactions are logged in statement based format. As the default slave thread tx isolation level is "REPEATABLE READ" the query event execution for "INSERT INTO t2 VALUES (1, 100000)" causes our supremum S-lock (see (1)).

b) For 5.7.20 the situation is different.

The first, before binary log events for our two XA transactions there is Gtid_log_event sent by master. If we look into Gtid_log_event::do_apply_event() we will see the following comments:

-----------code 3b.1------------------
int Gtid_log_event::do_apply_event(Relay_log_info const *rli)
{
...
  /*
    If the current transaction contains no changes logged with SBR
    we can assume this transaction as a pure row based replicated one.

Based on this assumption, we can set current transaction tx_isolation to
    READ COMMITTED in order to avoid concurrent transactions to be blocked by
    InnoDB gap locks.

The session tx_isolation will be restored:
    - When the transaction finishes with QUERY(COMMIT|ROLLBACK),
      as the MySQL server does for ordinary user sessions;
    - When applying a Xid_log_event, after committing the transaction;
    - When applying a XA_prepare_log_event, after preparing the transaction;
    - When the applier needs to abort a transaction execution.

Notice that when a transaction is being "gtid skipped", its statements are
    not actually executed (see mysql_execute_command()). So, the call to the
    function that would restore the tx_isolation after finishing the transaction
    may not happen.
  */
  if (DBUG_EVALUATE_IF("force_trx_as_rbr_only", true,
                       !may_have_sbr_stmts &&
                       thd->tx_isolation > ISO_READ_COMMITTED &&
                       gtid_pre_statement_checks(thd) != GTID_STATEMENT_SKIP))
  {
    DBUG_ASSERT(thd->get_transaction()->is_empty(Transaction_ctx::STMT));
    DBUG_ASSERT(thd->get_transaction()->is_empty(Transaction_ctx::SESSION));
    DBUG_ASSERT(!thd->lock);
    DBUG_PRINT("info", ("setting tx_isolation to READ COMMITTED"));
    set_tx_isolation(thd, ISO_READ_COMMITTED, true/*one_shot*/);
  }
...
}
------------------------------------------

As we can see slave thread transaction isolation level is changed during this binlog event execution on some condition. The backtrace for this action is the following:

==========bt 3b.1===========
(gdb) bt
#0  set_tx_isolation (thd=0x7fff9c000950, tx_isolation=ISO_READ_COMMITTED, one_shot=true) at ./sql/handler.cc:9180
#1  0x00000000018f6c1d in Gtid_log_event::do_apply_event (this=0x7fff9c016d60, rli=0x3934ac0) at ./sql/log_event.cc:13760
#2  0x00000000018d5628 in Log_event::apply_event (this=0x7fff9c016dd8, rli=0x3934ac0) at ./sql/log_event.cc:3534
#3  0x0000000001954423 in apply_event_and_update_pos (ptr_ev=0x7ffff10ff8a0, thd=0x7fff9c000950, rli=0x3934ac0)
    at ./sql/rpl_slave.cc:4786
#4  0x0000000001955c89 in exec_relay_log_event (thd=0x7fff9c000950, rli=0x3934ac0) at ./sql/rpl_slave.cc:5310
#5  0x000000000195d1a7 in handle_slave_sql (arg=0x38d5690) at ./sql/rpl_slave.cc:7545
#6  0x0000000001e8ded5 in pfs_spawn_thread (arg=0x7fffa01b2d50) at ./storage/perfschema/pfs.cc:2190
#7  0x00007ffff6f5e6ba in start_thread (arg=0x7ffff1100700) at pthread_create.c:333
#8  0x00007ffff63f33dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
========================================

The backtrace of restoring slave thread isolation level to "REPEATABLE READ" is the following:

===================bt 3b.2=================
#0  trans_reset_one_shot_chistics (thd=0x7fff9c000950) at ./sql/transaction.cc:56
#1  0x000000000177b26d in applier_reset_xa_trans (thd=0x7fff9c000950) at ./sql/xa.cc:1327
#2  0x000000000177a104 in Sql_cmd_xa_prepare::execute (this=0x7fff9c0061e8, thd=0x7fff9c000950) at ./sql/xa.cc:835
#3  0x00000000018e2e8d in XA_prepare_log_event::do_commit (this=0x7fff9c02f690, thd=0x7fff9c000950)
    at ./sql/log_event.cc:7605
#4  0x00000000018e24a9 in Xid_apply_log_event::do_apply_event (this=0x7fff9c02f778, rli=0x3934ac0)
    at ./sql/log_event.cc:7428
#5  0x00000000018d5628 in Log_event::apply_event (this=0x7fff9c02f778, rli=0x3934ac0) at ./sql/log_event.cc:3534
#6  0x0000000001954423 in apply_event_and_update_pos (ptr_ev=0x7ffff10ff8a0, thd=0x7fff9c000950, rli=0x3934ac0)
    at ./sql/rpl_slave.cc:4786
#7  0x0000000001955c89 in exec_relay_log_event (thd=0x7fff9c000950, rli=0x3934ac0) at ./sql/rpl_slave.cc:5310
#8  0x000000000195d1a7 in handle_slave_sql (arg=0x38d5690) at ./sql/rpl_slave.cc:7545
#9  0x0000000001e8ded5 in pfs_spawn_thread (arg=0x7fffa01b2d50) at ./storage/perfschema/pfs.cc:2190
#10 0x00007ffff6f5e6ba in start_thread (arg=0x7ffff1100700) at pthread_create.c:333
#11 0x00007ffff63f33dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
=====================================

And the second difference between 5.7.20 and 5.7.19 is that binary log events for "INSERT INTO t2 VALUES (1, 100000)" and "INSERT INTO t1 VALUES (85000, NULL)" statements are in row-based format for 5.7.20 and statement-based format for 5.7.19.

So the sequence of binary log events execution for 5.7.20 is the following:

-----------sequence 3b.1 (for 5.7.20)------------
Gtid_log_event - which changes slave thread isolation level to "READ COMMITTED";
Query_log_event - for XA START 1;
Table_map_log_event - row based;
Write_rows_log_event - row based, for "INSERT INTO t2 VALUES (1, 100000)";
Query_log_event - for XA END 1;
XA_prepare_log_event - for XA PREPARE 1, it changes slave thread tx level to "REPEATABLE READ" (see bt 3b.2);

Gtid_log_event - which changes slave thread isolation level to "READ COMMITTED";
Query_log_event - for XA START 2;
Table_map_log_event - row based;
Write_rows_log_event - row based, for "INSERT INTO t1 VALUES (85000, NULL)";
Query_log_event - for XA END 2;
XA_prepare_log_event - for XA PREPARE 2, it changes slave thread tx level to "REPEATABLE READ" (see bt3b.2);
------------------------------

The sequence of binary log events execution for 5.7.19 is the following:

--------------sequence 3b.2 (for 5.7.19)-------------
Gtid_log_event - does not change slave thread isolation level because the condition "!may_have_sbr_stmts" is not true (see code 3b.1);
Query_log_event - for XA START 1;
Query_log_event - statement based, for "INSERT INTO t2 VALUES (1, 100000)";
Query_log_event - for XA END 1;
XA_prepare_log_event - for XA PREPARE 1;

Gtid_log_event - does not change slave thread isolation level because the condition "!may_have_sbr_stmts" is not true (see code 3b.1);
Query_log_event - for XA START 2;
Query_log_event - statement based, for "INSERT INTO t1 VALUES (85000, NULL)";
Query_log_event - for XA END 2;
XA_prepare_log_event - for XA PREPARE 2;
--------------------------------

Summing up:

This above explains why the test fails for 5.7.19 and passes for 5.7.20. For 5.7.19 binary log events for the statements inside of XA blocks are in statement-based format, while for 5.7.20 they are in row-based format. Gtid_log_event generated by master before binlog events for XA blocks for 5.7.20 contains "rbr_only" flag set to "true", which causes changing slave thread transaction isolation level to "READ COMMITTED", while 5.7.19 master does not set that flag, and slave thread transaction isolation level stays "REPEATABLE READ". As a result there is no supremum S-lock for 5.7.20 during foreign keys check, and for 5.7.19 that lock is caused by corresponding transaction isolation level.

The general question is why the bug can be repeated on the customer's environment with 5.7.20 slave. Because master's version is still 5.7.19, and binary log events are generated in the sequence of 5.7.19(see sequence 3b.2).

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2018-01-08:

#8

Download full text (13.0 KiB)

What I see on the customer's host does not correspond to the bug
description. The general difference is suggestion about the cause of
S-lock is wrong.

I used the following branch for debugging:
https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.20-logging-and-stable-test-cust

Pay attention to transaction id's.
28911602068 - for S-lock
28911602059 - for X-lock

2) The following is the backtrace of the S-lock:

=========bt 2.1===============
Breakpoint 1, RecLock::init (this=this@entry=0x7ff49c058af0,
page=<optimized out>) at ./storage/innobase/include/lock0priv.h:863
863 ib::info() << "^^^^^^^^^^^^^^^^^^SET BREAKPOINT
HERE!";
Missing separate debuginfos, use: debuginfo-install
glibc-2.17-196.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64
krb5-libs-1.15.1-8.el7.x86_64 libaio-0.3.109-13.el7.x86_64
libcom_err-1.42.9-10.el7.x86_64 libgcc-4.8.5-16.el7_4.1.x86_64
libselinux-2.5-11.el7.x86_64 libstdc++-4.8.5-16.el7_4.1.x86_64
nss-softokn-freebl-3.28.3-8.el7_4.x86_64
openssl-libs-1.0.2k-8.el7.x86_64 pcre-8.32-17.el7.x86_64
zlib-1.2.7-17.el7.x86_64
(gdb) p m_trx
$1 = (trx_t *) 0x0
(gdb) bt
#0 RecLock::init (this=this@entry=0x7ff49c058af0, page=<optimized out>)
at ./storage/innobase/include/lock0priv.h:863
#1 0x0000000000f3c5fd in RecLock (mode=<optimized out>,
heap_no=140724951089696, block=0x7ffd14b88220, index=0x7ff40cb5e858,
this=0x7ff49c058af0)
    at ./storage/innobase/include/lock0priv.h:697
#2 lock_rec_add_to_queue (type_mode=<optimized out>,
block=block@entry=0x7ffd14b88220, heap_no=heap_no@entry=1,
index=0x7ff40cb5e858, trx=0x7fffea8650c8, caller_owns_trx_mutex=false)
    at ./storage/innobase/lock/lock0lock.cc:1880
#3 0x0000000000f3c790 in lock_rec_inherit_to_gap
(heir_block=heir_block@entry=0x7ffd14b88220,
block=block@entry=0x7ffd14b91fa0, heir_heap_no=heir_heap_no@entry=1,
heap_no=heap_no@entry=2)
    at ./storage/innobase/lock/lock0lock.cc:2744
#4 0x0000000000f3cf50 in lock_update_split_right
(right_block=right_block@entry=0x7ffd14b91fa0,
left_block=left_block@entry=0x7ffd14b88220)
    ...

What I see on the customer's host does not correspond to the bug
description. The general difference is suggestion about the cause of
S-lock is wrong.

I used the following branch for debugging:
https://github.com/vlad-lesin/percona-server/tree/lp-1735555-xa-transaction-lock-5.7.20-logging-and-stable-test-cust

Pay attention to transaction id's.
28911602068 - for S-lock
28911602059 - for X-lock

2) The following is the backtrace of the S-lock:

=========bt 2.1===============
Breakpoint 1, RecLock::init (this=this@entry=0x7ff49c058af0,
page=<optimized out>) at ./storage/innobase/include/lock0priv.h:863
863                     ib::info() << "^^^^^^^^^^^^^^^^^^SET BREAKPOINT
HERE!";
Missing separate debuginfos, use: debuginfo-install
glibc-2.17-196.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64
krb5-libs-1.15.1-8.el7.x86_64 libaio-0.3.109-13.el7.x86_64
libcom_err-1.42.9-10.el7.x86_64 libgcc-4.8.5-16.el7_4.1.x86_64
libselinux-2.5-11.el7.x86_64 libstdc++-4.8.5-16.el7_4.1.x86_64
nss-softokn-freebl-3.28.3-8.el7_4.x86_64
openssl-libs-1.0.2k-8.el7.x86_64 pcre-8.32-17.el7.x86_64
zlib-1.2.7-17.el7.x86_64
(gdb) p m_trx
$1 = (trx_t *) 0x0
(gdb) bt
#0  RecLock::init (this=this@entry=0x7ff49c058af0, page=<optimized out>)
at ./storage/innobase/include/lock0priv.h:863
#1  0x0000000000f3c5fd in RecLock (mode=<optimized out>,
heap_no=140724951089696, block=0x7ffd14b88220, index=0x7ff40cb5e858,
this=0x7ff49c058af0)
    at ./storage/innobase/include/lock0priv.h:697
#2  lock_rec_add_to_queue (type_mode=<optimized out>,
block=block@entry=0x7ffd14b88220, heap_no=heap_no@entry=1,
index=0x7ff40cb5e858, trx=0x7fffea8650c8, caller_owns_trx_mutex=false)
    at ./storage/innobase/lock/lock0lock.cc:1880
#3  0x0000000000f3c790 in lock_rec_inherit_to_gap
(heir_block=heir_block@entry=0x7ffd14b88220,
block=block@entry=0x7ffd14b91fa0, heir_heap_no=heir_heap_no@entry=1,
heap_no=heap_no@entry=2)
    at ./storage/innobase/lock/lock0lock.cc:2744
#4  0x0000000000f3cf50 in lock_update_split_right
(right_block=right_block@entry=0x7ffd14b91fa0,
left_block=left_block@entry=0x7ffd14b88220)
    at ./storage/innobase/lock/lock0lock.cc:3318
#5  0x00000000010a10e3 in btr_page_split_and_insert
(flags=flags@entry=0, cursor=cursor@entry=0x7ff49c059070,
offsets=offsets@entry=0x7ff49c058fd0, heap=heap@entry=0x7ff49c058fc0,
    tuple=tuple@entry=0x7ff40d196c58, n_ext=<optimized out>,
mtr=mtr@entry=0x7ff49c0597b0) at ./storage/innobase/btr/btr0btr.cc:2846
#6  0x00000000010af38a in btr_cur_pessimistic_insert
(flags=flags@entry=0, cursor=cursor@entry=0x7ff49c059070,
offsets=offsets@entry=0x7ff49c058fd0, heap=heap@entry=0x7ff49c058fc0,
    entry=entry@entry=0x7ff40d196c58, rec=rec@entry=0x7ff49c059490,
big_rec=big_rec@entry=0x7ff49c058fb0, n_ext=n_ext@entry=0,
thr=thr@entry=0x7ff40d1951e8, mtr=mtr@entry=0x7ff49c0597b0)
    at ./storage/innobase/btr/btr0cur.cc:3497
#7  0x0000000000fcb442 in row_ins_clust_index_entry_low
(flags=flags@entry=0, mode=<optimized out>, mode@entry=33,
index=index@entry=0x7ff40cb5e858, n_uniq=n_uniq@entry=1,
    entry=entry@entry=0x7ff40d196c58, n_ext=n_ext@entry=0,
thr=thr@entry=0x7ff40d1951e8, dup_chk_only=dup_chk_only@entry=false) at
./storage/innobase/row/row0ins.cc:2655
#8  0x0000000000fcf6f7 in row_ins_clust_index_entry
(index=0x7ff40cb5e858, entry=0x7ff40d196c58,
thr=thr@entry=0x7ff40d1951e8, n_ext=n_ext@entry=0,
dup_chk_only=dup_chk_only@entry=false)
    at ./storage/innobase/row/row0ins.cc:3397
#9  0x0000000000fd0c28 in row_ins_index_entry (thr=0x7ff40d1951e8,
entry=<optimized out>, index=<optimized out>) at
./storage/innobase/row/row0ins.cc:3513
#10 row_ins_index_entry_step (thr=0x7ff40d1951e8, node=0x7ff40cb56310)
at ./storage/innobase/row/row0ins.cc:3665
#11 row_ins (thr=0x7ff49c059f00, node=<optimized out>) at
./storage/innobase/row/row0ins.cc:3811
#12 row_ins_step (thr=thr@entry=0x7ff40d1951e8) at
./storage/innobase/row/row0ins.cc:4003
#13 0x0000000000fe357b in row_insert_for_mysql_using_ins_graph
(mysql_rec=mysql_rec@entry=0x7ff40cb4a7c0 "",
prebuilt=prebuilt@entry=0x7ff40cb555c8)
    at ./storage/innobase/row/row0mysql.cc:2279
#14 0x0000000000fe72d4 in row_insert_for_mysql
(mysql_rec=mysql_rec@entry=0x7ff40cb4a7c0 "",
prebuilt=prebuilt@entry=0x7ff40cb555c8)
    at ./storage/innobase/row/row0mysql.cc:2403
#15 0x0000000000ef7ac1 in ha_innobase::write_row (this=0x7ff40cb4a280,
record=<optimized out>) at ./storage/innobase/handler/ha_innodb.cc:8315
#16 0x00000000007ff122 in handler::ha_write_row (this=0x7ff40cb4a280,
buf=0x7ff40cb4a7c0 "") at ./sql/handler.cc:8437
#17 0x0000000000e3101d in Write_rows_log_event::write_row
(this=this@entry=0x7ff40d2c28b0, rli=<optimized out>, overwrite=false)
at ./sql/log_event.cc:12650
#18 0x0000000000e31349 in Write_rows_log_event::do_exec_row
(this=0x7ff40d2c28b0, rli=<optimized out>) at ./sql/log_event.cc:12850
#19 0x0000000000e1e256 in Rows_log_event::do_apply_row
(this=this@entry=0x7ff40d2c28b0, rli=rli@entry=0x3e92dc0) at
./sql/log_event.cc:10206
#20 0x0000000000e2f336 in Rows_log_event::do_apply_event
(this=0x7ff40d2c28b0, rli=0x3e92dc0) at ./sql/log_event.cc:11385
#21 0x0000000000e27b62 in Log_event::apply_event
(this=this@entry=0x7ff40d2c28b0, rli=rli@entry=0x3e92dc0) at
./sql/log_event.cc:3411
#22 0x0000000000e6d251 in apply_event_and_update_pos
(ptr_ev=ptr_ev@entry=0x7ff49c05a8d0, thd=thd@entry=0x7ff40c000910,
rli=rli@entry=0x3e92dc0) at ./sql/rpl_slave.cc:4782
#23 0x0000000000e795c2 in exec_relay_log_event (rli=0x3e92dc0,
thd=0x7ff40c000910) at ./sql/rpl_slave.cc:5306
#24 handle_slave_sql (arg=arg@entry=0x3dd7760) at ./sql/rpl_slave.cc:7541
#25 0x0000000001228974 in pfs_spawn_thread (arg=0x7ff4819fce40) at
./storage/perfschema/pfs.cc:2190
#26 0x00007ffff7bc6e25 in start_thread () from /lib64/libpthread.so.0
#27 0x00007ffff5fa634d in clone () from /lib64/libc.so.6
(gdb) fr 2
#2  lock_rec_add_to_queue (type_mode=<optimized out>,
block=block@entry=0x7ffd14b88220, heap_no=heap_no@entry=1,
index=0x7ff40cb5e858, trx=0x7fffea8650c8, caller_owns_trx_mutex=false)
    at ./storage/innobase/lock/lock0lock.cc:1880
1880            RecLock         rec_lock(index, block, heap_no, type_mode);
(gdb) p trx->id
$2 = 28911602059
====================================

Please, pay attention to transaction id: 28911602059. It corresponds to
S-lock transaction id from PFS in (1).

If we look at the backtrace we will see that the S-lock is caused by
innodb page split process.

I added some additional logging to error log to debug. And the XA which
causes the S-lock is the following:
XA START
X'46966a009c509b3869702d31302d3230352d322d37322c7365727665722c503337323331',X'69702d31302d3230352d322d37322c7365727665722c5033373233312c00',4871251

So if we have query log, we can find the transaction.

3) The X-lock backtrace is the following:

==========bt 3.1===================
Breakpoint 1, RecLock::init (this=this@entry=0x7ff49c058c70,
page=<optimized out>) at ./storage/innobase/include/lock0priv.h:863
863                     ib::info() << "^^^^^^^^^^^^^^^^^^SET BREAKPOINT
HERE!";
(gdb) bt
#0  RecLock::init (this=this@entry=0x7ff49c058c70, page=<optimized out>)
at ./storage/innobase/include/lock0priv.h:863
#1  0x0000000000f4543f in RecLock (prdt=0x0, mode=2563, heap_no=1,
block=0x7ffd14b88220, index=0x7ff40cb5e858, thr=0x1, this=0x7ff49c058c70)
    at ./storage/innobase/include/lock0priv.h:656
#2  lock_rec_insert_check_and_lock (flags=flags@entry=0, rec=<optimized
out>, block=0x7ffd14b88220, index=index@entry=0x7ff40cb5e858,
thr=thr@entry=0x7ff40d1951e8,
    mtr=mtr@entry=0x7ff49c0597b0, inherit=inherit@entry=0x7ff49c058eb0)
at ./storage/innobase/lock/lock0lock.cc:5969
#3  0x00000000010af519 in btr_cur_ins_lock_and_undo
(inherit=0x7ff49c058eb0, mtr=0x7ff49c0597b0, mtr@entry=0x7ff40cb5e858,
thr=0x7ff40d1951e8, thr@entry=0x7ff49c058fb0,
    entry=0x7ff40d196c58, cursor=0x7ff49c059070, flags=<optimized out>)
at ./storage/innobase/btr/btr0cur.cc:3035
#4  btr_cur_pessimistic_insert (flags=flags@entry=0,
cursor=cursor@entry=0x7ff49c059070,
offsets=offsets@entry=0x7ff49c058fd0, heap=heap@entry=0x7ff49c058fc0,
    entry=entry@entry=0x7ff40d196c58, rec=rec@entry=0x7ff49c059490,
big_rec=big_rec@entry=0x7ff49c058fb0, n_ext=n_ext@entry=0,
thr=thr@entry=0x7ff40d1951e8, mtr=mtr@entry=0x7ff49c0597b0)
    at ./storage/innobase/btr/btr0cur.cc:3438
#5  0x0000000000fcb442 in row_ins_clust_index_entry_low
(flags=flags@entry=0, mode=<optimized out>, mode@entry=33,
index=index@entry=0x7ff40cb5e858, n_uniq=n_uniq@entry=1,
    entry=entry@entry=0x7ff40d196c58, n_ext=n_ext@entry=0,
thr=thr@entry=0x7ff40d1951e8, dup_chk_only=dup_chk_only@entry=false) at
./storage/innobase/row/row0ins.cc:2655
#6  0x0000000000fcf6f7 in row_ins_clust_index_entry
(index=0x7ff40cb5e858, entry=0x7ff40d196c58,
thr=thr@entry=0x7ff40d1951e8, n_ext=n_ext@entry=0,
dup_chk_only=dup_chk_only@entry=false)
    at ./storage/innobase/row/row0ins.cc:3397
#7  0x0000000000fd0c28 in row_ins_index_entry (thr=0x7ff40d1951e8,
entry=<optimized out>, index=<optimized out>) at
./storage/innobase/row/row0ins.cc:3513
#8  row_ins_index_entry_step (thr=0x7ff40d1951e8, node=0x7ff40cb56310)
at ./storage/innobase/row/row0ins.cc:3665
#9  row_ins (thr=0x7ff49c059f00, node=<optimized out>) at
./storage/innobase/row/row0ins.cc:3811
#10 row_ins_step (thr=thr@entry=0x7ff40d1951e8) at
./storage/innobase/row/row0ins.cc:4003
#11 0x0000000000fe357b in row_insert_for_mysql_using_ins_graph
(mysql_rec=mysql_rec@entry=0x7ff40cb4a7c0 "",
prebuilt=prebuilt@entry=0x7ff40cb555c8)
    at ./storage/innobase/row/row0mysql.cc:2279
#12 0x0000000000fe72d4 in row_insert_for_mysql
(mysql_rec=mysql_rec@entry=0x7ff40cb4a7c0 "",
prebuilt=prebuilt@entry=0x7ff40cb555c8)
    at ./storage/innobase/row/row0mysql.cc:2403
#13 0x0000000000ef7ac1 in ha_innobase::write_row (this=0x7ff40cb4a280,
record=<optimized out>) at ./storage/innobase/handler/ha_innodb.cc:8315
#14 0x00000000007ff122 in handler::ha_write_row (this=0x7ff40cb4a280,
buf=0x7ff40cb4a7c0 "") at ./sql/handler.cc:8437
#15 0x0000000000e3101d in Write_rows_log_event::write_row
(this=this@entry=0x7ff40cb0d410, rli=<optimized out>, overwrite=false)
at ./sql/log_event.cc:12650
#16 0x0000000000e31349 in Write_rows_log_event::do_exec_row
(this=0x7ff40cb0d410, rli=<optimized out>) at ./sql/log_event.cc:12850
#17 0x0000000000e1e256 in Rows_log_event::do_apply_row
(this=this@entry=0x7ff40cb0d410, rli=rli@entry=0x3e92dc0) at
./sql/log_event.cc:10206
#18 0x0000000000e2f336 in Rows_log_event::do_apply_event
(this=0x7ff40cb0d410, rli=0x3e92dc0) at ./sql/log_event.cc:11385
#19 0x0000000000e27b62 in Log_event::apply_event
(this=this@entry=0x7ff40cb0d410, rli=rli@entry=0x3e92dc0) at
./sql/log_event.cc:3411
#20 0x0000000000e6d251 in apply_event_and_update_pos
(ptr_ev=ptr_ev@entry=0x7ff49c05a8d0, thd=thd@entry=0x7ff40c000910,
rli=rli@entry=0x3e92dc0) at ./sql/rpl_slave.cc:4782
#21 0x0000000000e795c2 in exec_relay_log_event (rli=0x3e92dc0,
thd=0x7ff40c000910) at ./sql/rpl_slave.cc:5306
#22 handle_slave_sql (arg=arg@entry=0x3dd7760) at ./sql/rpl_slave.cc:7541
#23 0x0000000001228974 in pfs_spawn_thread (arg=0x7ff4819fce40) at
./storage/perfschema/pfs.cc:2190
#24 0x00007ffff7bc6e25 in start_thread () from /lib64/libpthread.so.0
#25 0x00007ffff5fa634d in clone () from /lib64/libc.so.6
(gdb) p m_trx->id
$5 = 28911602068
==================================

Pay attention to transaction id 28911602068 which corresponds to X-lock
in the table in (1).

I don't see any special things here, just usual Write_rows_log_event.
It's XA transaction id is the following:
XA START
X'5d966a009c509b3869702d31302d3230352d322d37322c7365727665722c503337323331',X'69702d31302d3230352d322d37322c7365727665722c5033373233312c00',4871251

Summing up:

The S-lock on the customer's host is caused by page split process, but
not foreign key checking as described in the bug report. So the initial
test case is useless for us.

The whole picture is the following:

1) XA 1 contains queries which cause page split which, in turn, causes
the supremum S-lock;
2) While  XA 1 is not committed and the supremum S-lock is not released
the transaction XA 2 starts and tries to modify the page S-locked by XA
1, what causes the supremum X-lock, XA 2 is pushed to waiting queue;
3) Lock wait timeout errors, the slave thread stops.

Revision history for this message

Vlad Lesin (vlad-lesin) wrote on 2018-01-11:

#9

Download full text (5.9 KiB)

The following is the draft of the stable mtr test case. The test case does not contain replication at all. Because to reproduce the case the replication is not important, what is important is the sequence of locking caused by the sequence of transactions and statements, which can reproduced whether on master or on slave.

So what the sequence should be?

1) Set S-lock on some record R1 (which can be caused by foreign checking in this case and on the customer's side).

2) Cause page split for the page which contains R1. In the current test right-split is caused, what means that the new page is created to the right of the old page. R1 must be located so that during split process it is moved to the new right page at the first position, i.e., just after infinum.
See:
---------------
rec_t*
btr_page_split_and_insert(...) {
...
} else if (btr_page_get_split_rec_to_right(cursor, &split_rec)) {
direction = FSP_UP;
hint_page_no = page_no + 1;

} else if (btr_page_get_split_rec_to_left(cursor, &split_rec)) {
...
left_block = block;
right_block = new_block;

  if (!dict_table_is_locking_disabled(cursor->index->table)) {
   lock_update_split_right(right_block, left_block);
  }
....
}
----------------

3) If the above condition is true, then R1 S-lock will be copied to the supremum of left-half page, which will cause gap lock.
See
---------------
void
lock_update_split_right(...)
{
...
/* Inherit the locks to the supremum of left page from the successor
of the infimum on right page */

lock_rec_inherit_to_gap(left_block, right_block,
PAGE_HEAP_NO_SUPREMUM, heap_no);

...
}
---------------

There are several questions which have not yet been covered:

1) Is it possible to repeat the case with non-XA transactions? What is about the same but on slave?

2) This test shows only right-split case, the same issue might also be for left-split case, it needs to be checked.

The test itself:

==============
--source include/have_innodb.inc

--eval SET GLOBAL TRANSACTION ISOLATION LEVEL READ COMMITTED;

CREATE TABLE t1 (t1_pk DECIMAL(20,0) PRIMARY KEY , t1_blob BLOB) ENGINE=InnoDB;

--echo # Initial filling
INSERT INTO t1 VALUES (10000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (20000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (30000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (40000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (50000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (60000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (70000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (80000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (90000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (100000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (110000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (120000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (130000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (140000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (150000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (160000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (170000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (180000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (190000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (200000, REPEAT("a", 1082));
INSERT INTO t1 VALUES (210000, REPEAT("a", 1082));
...

Percona Server moved to https://jira.percona.com/projects/PS

RBR Replication with concurrent XA in READ-COMMITTED takes supremum pseudo-records and breaks replication

Bug Description

Other bug subscribers

Remote bug watches

	Status	Importance	Assigned to
Percona Server moved to https://jira.percona.com/projects/PS	Status tracked in 5.7
5.5	New	High	Vlad Lesin
5.6	New	High	Vlad Lesin
5.7	In Progress	High	Vlad Lesin