[MDEV-14829] Assertion `0' failed in Protocol::end_statement upon concurrent UPDATE - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.3(EOL)
Fix Version/s: 10.3.5
Component/s: Data Manipulation - Update, Versioned Tables
Labels:
None

Description

--source include/have_innodb.inc

CREATE OR REPLACE TABLE t1 (pk INT, a CHAR(3), b CHAR(3), PRIMARY KEY(pk))

  ENGINE=InnoDB WITH SYSTEM VERSIONING CHARACTER SET ucs2;

INSERT INTO t1 (pk) VALUES (1);

--connect (con1,localhost,root,,test)

--send

  UPDATE t1 SET a = 'bar';

--connection default

UPDATE t1 SET b = 'foo';

--connection con1

--reap

# Cleanup

--disconnect con1

--connection default

DROP TABLE t1;

10.3 ec32c050726
mysqld: /data/src/10.3/sql/protocol.cc:587: void Protocol::end_statement(): Assertion `0' failed.
180123 1:21:57 [ERROR] mysqld got signal 6 ;

#7 0x00007f29141b0ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8 0x000055a48947503c in Protocol::end_statement (this=0x7f28b00010e0) at /data/src/10.3/sql/protocol.cc:587
#9 0x000055a4895526a6 in dispatch_command (command=COM_QUERY, thd=0x7f28b0000b00, packet=0x7f28b000b141 "UPDATE t1 SET a = 'bar'", packet_length=23, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:2381
#10 0x000055a48954f523 in do_command (thd=0x7f28b0000b00) at /data/src/10.3/sql/sql_parse.cc:1370
#11 0x000055a4896b6768 in do_handle_one_connection (connect=0x55a48c3408c0) at /data/src/10.3/sql/sql_connect.cc:1401
#12 0x000055a4896b64f5 in handle_one_connection (arg=0x55a48c3408c0) at /data/src/10.3/sql/sql_connect.cc:1307
#13 0x000055a489b540b8 in pfs_spawn_thread (arg=0x55a48c3496a0) at /data/src/10.3/storage/perfschema/pfs.cc:1862
#14 0x00007f2915e87494 in start_thread (arg=0x7f290455f700) at pthread_create.c:333
#15 0x00007f291426d93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

No visible effect on non-debug build.

Attachments

Issue Links

is duplicated by

MDEV-14794 Limitations which the row end as a part of PK imposes due to CURRENT_TIMESTAMP behavior and otherwise

Closed

relates to

MDEV-18706 ER_LOCK_DEADLOCK on concurrent read and insert into already locked gap

In Review

Activity

Ascending order - Click to sort in descending order

Eugene Kosov (Inactive) added a comment - 2018-01-27 18:58

Reproducible also with `myisam` and `--repeat=100`.

After fixing incorrect error handling we see this: `1062: Duplicate entry '1-2018-01-27 21:30:30.184977' for key 'PRIMARY'` That's a design limitation of system-versioning implementation.

Eugene Kosov (Inactive) added a comment - 2018-01-27 18:58 Reproducible also with `myisam` and `--repeat=100`. After fixing incorrect error handling we see this: `1062: Duplicate entry '1-2018-01-27 21:30:30.184977' for key 'PRIMARY'` That's a design limitation of system-versioning implementation.

Eugene Kosov (Inactive) added a comment - 2018-01-29 13:33

Deadlock from InnoDB:

2018-01-28 23:08:24 9 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.

2018-01-28 23:08:24 9 [Note] InnoDB:

*** (1) TRANSACTION:

TRANSACTION 1287, ACTIVE 0 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 4 lock struct(s), heap size 1160, 1 row lock(s)

MySQL thread id 10, OS thread handle 140425503827712, query id 23 localhost root Searching rows for update

update t1 set a = 'bar'

2018-01-28 23:08:24 9 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1287 lock_mode X waiting

Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0

 0: len 4; hex 80000000; asc     ;;

 1: len 7; hex 7fffffff0f423f; asc      B?;;

 2: len 6; hex 000000000506; asc       ;;

 3: len 7; hex 04000001380317; asc     8  ;;

 4: SQL NULL;

 5: len 6; hex 0066006f006f; asc  f o o;;

 6: len 7; hex 5a6e2db80d7105; asc Zn-  q ;;

2018-01-28 23:08:24 9 [Note] InnoDB: *** (2) TRANSACTION:

TRANSACTION 1286, ACTIVE 0 sec inserting

mysql tables in use 1, locked 1

3 lock struct(s), heap size 1160, 3 row lock(s), undo log entries 1

MySQL thread id 9, OS thread handle 140425504130816, query id 22 localhost root Updating

update t1 set b = 'foo'

2018-01-28 23:08:24 9 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X

Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0

 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0

 0: len 4; hex 80000000; asc     ;;

 1: len 7; hex 7fffffff0f423f; asc      B?;;

 2: len 6; hex 000000000506; asc       ;;

 3: len 7; hex 04000001380317; asc     8  ;;

 4: SQL NULL;

 5: len 6; hex 0066006f006f; asc  f o o;;

 6: len 7; hex 5a6e2db80d7105; asc Zn-  q ;;

2018-01-28 23:08:24 9 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X locks gap before rec insert intention waiting

Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0

 0: len 4; hex 80000000; asc     ;;

 1: len 7; hex 7fffffff0f423f; asc      B?;;

 2: len 6; hex 000000000506; asc       ;;

 3: len 7; hex 04000001380317; asc     8  ;;

 4: SQL NULL;

 5: len 6; hex 0066006f006f; asc  f o o;;

 6: len 7; hex 5a6e2db80d7105; asc Zn-  q ;;

2018-01-28 23:08:24 9 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

Eugene Kosov (Inactive) added a comment - 2018-01-29 13:33 Deadlock from InnoDB: 2018-01-28 23:08:24 9 [Note] InnoDB: Transactions deadlock detected, dumping detailed information. 2018-01-28 23:08:24 9 [Note] InnoDB: *** (1) TRANSACTION: TRANSACTION 1287, ACTIVE 0 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1160, 1 row lock(s) MySQL thread id 10, OS thread handle 140425503827712, query id 23 localhost root Searching rows for update update t1 set a = 'bar' 2018-01-28 23:08:24 9 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1287 lock_mode X waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0 0: len 4; hex 80000000; asc ;; 1: len 7; hex 7fffffff0f423f; asc B?;; 2: len 6; hex 000000000506; asc ;; 3: len 7; hex 04000001380317; asc 8 ;; 4: SQL NULL; 5: len 6; hex 0066006f006f; asc f o o;; 6: len 7; hex 5a6e2db80d7105; asc Zn- q ;; 2018-01-28 23:08:24 9 [Note] InnoDB: *** (2) TRANSACTION: TRANSACTION 1286, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 3 lock struct(s), heap size 1160, 3 row lock(s), undo log entries 1 MySQL thread id 9, OS thread handle 140425504130816, query id 22 localhost root Updating update t1 set b = 'foo' 2018-01-28 23:08:24 9 [Note] InnoDB: *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0 0: len 8; hex 73757072656d756d; asc supremum;; Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0 0: len 4; hex 80000000; asc ;; 1: len 7; hex 7fffffff0f423f; asc B?;; 2: len 6; hex 000000000506; asc ;; 3: len 7; hex 04000001380317; asc 8 ;; 4: SQL NULL; 5: len 6; hex 0066006f006f; asc f o o;; 6: len 7; hex 5a6e2db80d7105; asc Zn- q ;; 2018-01-28 23:08:24 9 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0 0: len 4; hex 80000000; asc ;; 1: len 7; hex 7fffffff0f423f; asc B?;; 2: len 6; hex 000000000506; asc ;; 3: len 7; hex 04000001380317; asc 8 ;; 4: SQL NULL; 5: len 6; hex 0066006f006f; asc f o o;; 6: len 7; hex 5a6e2db80d7105; asc Zn- q ;; 2018-01-28 23:08:24 9 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

Eugene Kosov (Inactive) added a comment - 2018-01-30 09:35

Deadlock is caused by InnoDB gap lock. It's ok for UPDATE without WHERE.

First case from https://jira.mariadb.org/browse/MDEV-14794 related to this issue: inserting historical rows with zero or even negative lifetime should be prohibited.

Eugene Kosov (Inactive) added a comment - 2018-01-30 09:35 Deadlock is caused by InnoDB gap lock. It's ok for UPDATE without WHERE. First case from https://jira.mariadb.org/browse/MDEV-14794 related to this issue: inserting historical rows with zero or even negative lifetime should be prohibited.

Eugene Kosov (Inactive) added a comment - 2018-01-31 13:10

Updating the same row from different connections:

create or replace table t1 (

  pk int,

  a char(3),

  b char(3),

  primary key(pk))

engine=innodb with system versioning character set ucs2;

insert into t1 (pk) values (0);

--connect (con1,localhost,root,,test)

--send

update t1 set a = 'bar' where pk=0;

--connection default

update t1 set b = 'foo' where pk=0;

--connection con1

--reap

--disconnect con1

--connection default

Versioned UPDATE is UPDATE + INSERT https://github.com/MariaDB/server/blob/10.3/sql/sql_update.cc#L917

2018-01-31 15:26:57 10 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.

2018-01-31 15:26:57 10 [Note] InnoDB:

*** (1) TRANSACTION:

TRANSACTION 1287, ACTIVE 0 sec starting index read

mysql tables in use 1, locked 1

LOCK WAIT 4 lock struct(s), heap size 1160, 1 row lock(s)

MySQL thread id 9, OS thread handle 140542940653312, query id 23 localhost root Searching rows for update

update t1 set b = 'foo' where pk=0

2018-01-31 15:26:57 10 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1287 lock_mode X waiting

Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0

 0: len 4; hex 80000000; asc     ;;

 1: len 7; hex 7fffffff0f423f; asc      B?;;

 2: len 6; hex 000000000506; asc       ;;

 3: len 7; hex 04000001380317; asc     8  ;;

 4: len 6; hex 006200610072; asc  b a r;;

 5: SQL NULL;

 6: len 7; hex 5a71b61100453e; asc Zq   E>;;

2018-01-31 15:26:57 10 [Note] InnoDB: *** (2) TRANSACTION:

TRANSACTION 1286, ACTIVE 0 sec inserting

mysql tables in use 1, locked 1

3 lock struct(s), heap size 1160, 3 row lock(s), undo log entries 1

MySQL thread id 10, OS thread handle 140542940350208, query id 22 localhost root Updating

update t1 set a = 'bar' where pk=0

2018-01-31 15:26:57 10 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X

Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0

 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0

 0: len 4; hex 80000000; asc     ;;

 1: len 7; hex 7fffffff0f423f; asc      B?;;

 2: len 6; hex 000000000506; asc       ;;

 3: len 7; hex 04000001380317; asc     8  ;;

 4: len 6; hex 006200610072; asc  b a r;;

 5: SQL NULL;

 6: len 7; hex 5a71b61100453e; asc Zq   E>;;

2018-01-31 15:26:57 10 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X locks gap before rec insert intention waiting

Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0

 0: len 4; hex 80000000; asc     ;;

 1: len 7; hex 7fffffff0f423f; asc      B?;;

 2: len 6; hex 000000000506; asc       ;;

 3: len 7; hex 04000001380317; asc     8  ;;

 4: len 6; hex 006200610072; asc  b a r;;

 5: SQL NULL;

 6: len 7; hex 5a71b61100453e; asc Zq   E>;;

2018-01-31 15:26:57 10 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

Eugene Kosov (Inactive) added a comment - 2018-01-31 13:10 Updating the same row from different connections: create or replace table t1 ( pk int , a char (3), b char (3), primary key (pk)) engine=innodb with system versioning character set ucs2; insert into t1 (pk) values (0); --connect (con1,localhost,root,,test) --send update t1 set a = 'bar' where pk=0; --connection default update t1 set b = 'foo' where pk=0; --connection con1 --reap --disconnect con1 --connection default Versioned UPDATE is UPDATE + INSERT https://github.com/MariaDB/server/blob/10.3/sql/sql_update.cc#L917 2018-01-31 15:26:57 10 [Note] InnoDB: Transactions deadlock detected, dumping detailed information. 2018-01-31 15:26:57 10 [Note] InnoDB: *** (1) TRANSACTION: TRANSACTION 1287, ACTIVE 0 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1160, 1 row lock(s) MySQL thread id 9, OS thread handle 140542940653312, query id 23 localhost root Searching rows for update update t1 set b = 'foo' where pk=0 2018-01-31 15:26:57 10 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1287 lock_mode X waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0 0: len 4; hex 80000000; asc ;; 1: len 7; hex 7fffffff0f423f; asc B?;; 2: len 6; hex 000000000506; asc ;; 3: len 7; hex 04000001380317; asc 8 ;; 4: len 6; hex 006200610072; asc b a r;; 5: SQL NULL; 6: len 7; hex 5a71b61100453e; asc Zq E>;; 2018-01-31 15:26:57 10 [Note] InnoDB: *** (2) TRANSACTION: TRANSACTION 1286, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 3 lock struct(s), heap size 1160, 3 row lock(s), undo log entries 1 MySQL thread id 10, OS thread handle 140542940350208, query id 22 localhost root Updating update t1 set a = 'bar' where pk=0 2018-01-31 15:26:57 10 [Note] InnoDB: *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0 0: len 8; hex 73757072656d756d; asc supremum;; Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0 0: len 4; hex 80000000; asc ;; 1: len 7; hex 7fffffff0f423f; asc B?;; 2: len 6; hex 000000000506; asc ;; 3: len 7; hex 04000001380317; asc 8 ;; 4: len 6; hex 006200610072; asc b a r;; 5: SQL NULL; 6: len 7; hex 5a71b61100453e; asc Zq E>;; 2018-01-31 15:26:57 10 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 5 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 1286 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0 0: len 4; hex 80000000; asc ;; 1: len 7; hex 7fffffff0f423f; asc B?;; 2: len 6; hex 000000000506; asc ;; 3: len 7; hex 04000001380317; asc 8 ;; 4: len 6; hex 006200610072; asc b a r;; 5: SQL NULL; 6: len 7; hex 5a71b61100453e; asc Zq E>;; 2018-01-31 15:26:57 10 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

MariaDB Server

Assertion `0' failed in Protocol::end_statement upon concurrent UPDATE

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration