[MDEV-14829] Assertion `0' failed in Protocol::end_statement upon concurrent UPDATE Created: 2017-12-31  Updated: 2019-08-02  Resolved: 2018-02-23

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Update, Versioned Tables
Affects Version/s: 10.3
Fix Version/s: 10.3.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Eugene Kosov (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-14794 Limitations which the row end as a pa... Closed
Relates
relates to MDEV-18706 ER_LOCK_DEADLOCK on concurrent read a... Stalled

 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.

 Comments   
Comment by Eugene Kosov (Inactive) [ 2018-01-27 ]

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.

Comment by Eugene Kosov (Inactive) [ 2018-01-29 ]

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)

Comment by Eugene Kosov (Inactive) [ 2018-01-30 ]

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.

Comment by Eugene Kosov (Inactive) [ 2018-01-31 ]

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)

Generated at Thu Feb 08 08:16:36 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.