[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

Elena Stepanova created issue - 2017-12-31 11:53

Elena Stepanova made changes - 2018-01-22 23:24

Field	Original Value	New Value
Component/s		Data Manipulation - Update [ 10805 ]
Component/s		System versioning [ 14303 ]
Fix Version/s		10.3 [ 22126 ]
Affects Version/s		10.3 [ 22126 ]
Affects Version/s	N/A [ 14700 ]
Description	https://api.travis-ci.org/v3/job/323242566/log.txt {noformat:title=bb-10.3-temporal a3a15126f260e26b715ae9a790135df1822b74d8} Version: '10.3.3-MariaDB-debug-log' socket: '/home/travis/logs/vardir1_5/mysql.sock' port: 19300 Source distribution 2017-12-30 22:34:56 16 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger7732`: Operation interrupted 2017-12-30 22:34:56 18 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger7736`: Operation interrupted 2017-12-30 22:35:00 14 [Warning] InnoDB: Unable to delete statistics for table test.trigger7729: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7729'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7729'; 2017-12-30 22:35:30 17 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger17734`: Operation interrupted 2017-12-30 22:35:31 18 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger7736`: Operation interrupted 2017-12-30 22:35:31 15 [Warning] InnoDB: Unable to delete statistics for table transforms.trigger27730: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'transforms' AND table_name = 'trigger27730'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'transforms' AND table_name = 'trigger27730'; 2017-12-30 22:35:33 16 [Warning] InnoDB: Unable to delete statistics for table test.trigger7732: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7732'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7732'; 2017-12-30 22:35:33 14 [Warning] InnoDB: Unable to delete statistics for table transforms.delete_returning_7729: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'transforms' AND table_name = 'delete_returning_7729'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'transforms' AND table_name = 'delete_returning_7729'; 2017-12-30 22:35:33 17 [Warning] InnoDB: Unable to delete statistics for table test.trigger7734: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7734'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7734'; 2017-12-30 22:35:33 14 [Warning] InnoDB: Unable to delete statistics for table transforms.insert_select_7729: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'transforms' AND table_name = 'insert_select_7729'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'transforms' AND table_name = 'insert_select_7729'; 2017-12-30 22:36:04 15 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger7730`: Operation interrupted 2017-12-30 22:36:04 18 [Warning] InnoDB: Unable to delete statistics for table test.trigger7736: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7736'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7736'; 2017-12-30 22:36:05 17 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger7734`: Operation interrupted 2017-12-30 22:36:38 15 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger7730`: Operation interrupted 2017-12-30 22:36:38 19 [Warning] InnoDB: Unable to delete statistics for table test.trigger7738: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7738'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7738'; 2017-12-30 22:36:40 18 [Warning] InnoDB: Unable to delete statistics for table test.trigger17736: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger17736'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger17736'; 2017-12-30 22:37:12 15 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger17730`: Operation interrupted 2017-12-30 22:37:13 15 [Warning] Sort aborted, host: localhost, user: rqg, thread: 15, query: DELETE LOW_PRIORITY FROM `table10_key_pk_parts_2_int_autoinc` WHERE `pk` BETWEEN 1 AND 8 ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 1 /* QNO 1686 CON_ID 15 / 2017-12-30 22:37:43 19 [ERROR] InnoDB: Cannot save table statistics for table `test`.`trigger7738`: Operation interrupted 2017-12-30 22:38:14 17 [ERROR] InnoDB: Cannot save table statistics for table `transforms`.`insert_select_7734`: Operation interrupted 2017-12-30 22:38:14 17 [Warning] InnoDB: Unable to delete statistics for table transforms.insert_select_7734: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'transforms' AND table_name = 'insert_select_7734'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'transforms' AND table_name = 'insert_select_7734'; 2017-12-30 22:38:17 19 [Warning] InnoDB: Unable to delete statistics for table transforms.trigger27738: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'transforms' AND table_name = 'trigger27738'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'transforms' AND table_name = 'trigger27738'; 2017-12-30 22:38:18 19 [Warning] InnoDB: Unable to delete statistics for table test.trigger17738: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger17738'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger17738'; 2017-12-30 22:38:50 16 [ERROR] InnoDB: Cannot save table statistics for table `transforms`.`insert_select_7732`: Operation interrupted 2017-12-30 22:38:51 19 [Warning] InnoDB: Unable to delete statistics for table test.trigger7738: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7738'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7738'; 2017-12-30 22:38:53 14 [Warning] InnoDB: Unable to delete statistics for table test.trigger7729: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7729'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7729'; 2017-12-30 22:38:54 15 [ERROR] mysqld: Deadlock found when trying to get lock; try restarting transaction 2017-12-30 22:38:54 15 [Warning] Sort aborted, host: localhost, user: rqg, thread: 15, query: / GenTest::Transform::ExecuteAsCTE / DELETE LOW_PRIORITY QUICK IGNORE FROM `table1_key_pk_parts_2_int_autoinc` WHERE `col_char_12_key` IN( WITH cte2 AS ( SELECT `col_char_12_key` FROM `table10_int_autoinc` WHERE `pk` = 5 ) SELECT FROM cte2 ) ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 1 /* QNO 2637 CON_ID 15 / / TRANSFORM_OUTCOME_UNORDERED_MATCH / / QNO 2651 CON_ID 15 / 2017-12-30 22:38:54 17 [Warning] InnoDB: Unable to delete statistics for table test.trigger17734: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger17734'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger17734'; 2017-12-30 22:38:55 17 [Warning] InnoDB: Unable to delete statistics for table test.trigger7734: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger7734'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger7734'; 2017-12-30 22:38:55 15 [Warning] InnoDB: Unable to delete statistics for table test.trigger17730: Lock wait. They can be deleted later using DELETE FROM mysql.innodb_index_stats WHERE database_name = 'test' AND table_name = 'trigger17730'; DELETE FROM mysql.innodb_table_stats WHERE database_name = 'test' AND table_name = 'trigger17730'; mysqld: /home/travis/src/sql/protocol.cc:587: void Protocol::end_statement(): Assertion `0' failed. 171230 22:38:55 [ERROR] mysqld got signal 6 ; Query (0x7f834c015c48): CREATE TABLE transforms.insert_select_7729 SELECT ( SELECT `pk` FROM `table2_int_autoinc` WHERE `pk` = 9 ) FROM `view_table2_int_autoinc` AS X LEFT JOIN `view_table100_key_pk_parts_2_int_autoinc` AS Y USING ( `col_char_12` ) WHERE X.`col_char_12_key` < 226 LIMIT 7 / QNO 2791 CON_ID 14 / / QNO 2812 CON_ID 14 */ Connection ID (thread ID): 14 Status: NOT_KILLED {noformat} {noformat} #3 <signal handler called> #4 0x00007f839f6f7035 in raise () from /lib/x86_64-linux-gnu/libc.so.6 #5 0x00007f839f6fa79b in abort () from /lib/x86_64-linux-gnu/libc.so.6 #6 0x00007f839f6efe1e in ?? () from /lib/x86_64-linux-gnu/libc.so.6 #7 0x00007f839f6efec2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x00000000006caede in Protocol::end_statement (this=0x7f834c001210) at /home/travis/src/sql/protocol.cc:587 #9 0x00000000007a885b in dispatch_command (command=COM_QUERY, thd=0x7f834c000c70, packet=0x7f834c00b2c1 "CREATE TABLE transforms.insert_select_7729 SELECT ( SELECT `pk` FROM `table2_int_autoinc` WHERE `pk` = 9 ) FROM `view_table2_int_autoinc` AS X LEFT JOIN `view_table100_key_pk_parts_2_int_autoinc` AS Y"..., packet_length=317, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:2380 #10 0x00000000007a565d in do_command (thd=0x7f834c000c70) at /home/travis/src/sql/sql_parse.cc:1370 #11 0x000000000090b7cf in do_handle_one_connection (connect=0x42e2cd0) at /home/travis/src/sql/sql_connect.cc:1420 #12 0x000000000090b551 in handle_one_connection (arg=0x42e2cd0) at /home/travis/src/sql/sql_connect.cc:1326 #13 0x00007f83a029be9a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 #14 0x00007f839f7b72ed in clone () from /lib/x86_64-linux-gnu/libc.so.6 #15 0x0000000000000000 in ?? () {noformat} {noformat:title=experimental 68ba6a4048fa9f40da10679a5702bdf419f76855} perl /home/travis/rqg/runall-new.pl --duration=350 --threads=6 --reporters=Backtrace,ErrorLog,Deadlock --validators=TransformerNoComparator --transformers=ConvertSubqueriesToViews,ConvertTablesToDerived,Count,DisableOptimizations,Distinct,EnableOptimizations,ExecuteAsCTE,ExecuteAsDeleteReturning,ExecuteAsDerived,ExecuteAsExcept,ExecuteAsExecuteImmediate,ExecuteAsInsertSelect,ExecuteAsIntersect,ExecuteAsSelectItem,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsView,ExecuteAsWhereSubquery,Having,InlineSubqueries,InlineVirtualColumns,LimitRowsExamined,OrderBy,StraightJoin,ExecuteAsPreparedTwice,ExecuteAsTrigger,ExecuteAsSPTwice,ExecuteAsFunctionTwice --redefine=conf/mariadb/general-workarounds.yy --mysqld=--log_output=FILE --mysqld=--log_bin_trust_function_creators=1 --mysqld=--log-bin --mysqld=--max-statement-time=30 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --views --redefine=conf/mariadb/versioning.yy --basedir=/home/travis/server --grammar=conf/engines/engine_stress.yy --gendata=conf/engines/engine_stress.zz --mysqld=--system-versioning-force --vardir=/home/travis/logs/vardir1_5 {noformat}	{code:sql} --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; {code} {noformat:title=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 {noformat} No visible effect on non-debug build.
Summary	[Draft] Assertion `0' failed in Protocol::end_statement	Assertion `0' failed in Protocol::end_statement upon concurrent UPDATE

Elena Stepanova made changes - 2018-01-22 23:25

Assignee

Elena Stepanova [ elenst ]

Alexander Krizhanovsky [ krizhanovsky ]

Eugene Kosov (Inactive) made changes - 2018-01-23 08:09

Assignee

Alexander Krizhanovsky [ krizhanovsky ]

Eugene Kosov [ kevg ]

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)

Aleksey Midenkov made changes - 2018-02-14 14:45

Link

This issue is duplicated by ~~MDEV-14794~~ [ ~~MDEV-14794~~ ]

Sergei Golubchik made changes - 2018-02-21 16:41

Assignee

Eugene Kosov [ kevg ]

Sergei Golubchik [ serg ]

Sergei Golubchik made changes - 2018-02-21 16:42

Status

Open [ 1 ]

In Progress [ 3 ]

Sergei Golubchik made changes - 2018-02-21 16:42

Status

In Progress [ 3 ]

In Review [ 10002 ]

Sergei Golubchik made changes - 2018-02-23 19:53

Fix Version/s		10.3.5 [ 22905 ]
Fix Version/s	10.3 [ 22126 ]
Assignee	Sergei Golubchik [ serg ]	Eugene Kosov [ kevg ]
Resolution		Fixed [ 1 ]
Status	In Review [ 10002 ]	Closed [ 6 ]

Aleksey Midenkov made changes - 2019-08-02 09:52

Link

This issue relates to MDEV-18706 [ MDEV-18706 ]

Sergei Golubchik made changes - 2021-12-06 21:46

Workflow

MariaDB v3 [ 84679 ]

MariaDB v4 [ 153481 ]

People

Assignee:: Eugene Kosov (Inactive)

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2017-12-31 11:53

Updated:: 2019-08-02 09:52

Resolved:: 2018-02-23 19:53

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration