[MDEV-14018] problem of lock on concurent insert (from spider i guees) Created: 2017-10-06  Updated: 2023-05-23

Status: Confirmed
Project: MariaDB Server
Component/s: Data Manipulation - Insert, Storage Engine - Spider
Affects Version/s: 10.2.8
Fix Version/s: 10.2

Type: Bug Priority: Major
Reporter: Aurélien LEQUOY Assignee: Yuchen Pei
Resolution: Unresolved Votes: 1
Labels: None

Attachments: HTML File 1     HTML File 2     HTML File 3    
Issue Links:
Duplicate
is duplicated by MDEV-13984 mysqld crashed in tokudb/PerconaFT/ft... Open
Relates
relates to MDEV-14019 Spider + binlog_format = ROW => CRASH Closed

 Description   

On concurent insert maybe (3 ~ 4) I got global read lock, look like because spider may consider MyRocksDB like non transactional engine.

+-----------+-------------------------+---------------+---------------------+--------------+-------------------------+
 
| THREAD_ID | LOCK_MODE               | LOCK_DURATION | LOCK_TYPE           | TABLE_SCHEMA | TABLE_NAME              |
 
+-----------+-------------------------+---------------+---------------------+--------------+-------------------------+
 
|      6828 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6831 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6848 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6847 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6869 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6870 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6885 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6895 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6886 | MDL_INTENTION_EXCLUSIVE | NULL          | Global read lock    |              |                         |
 
|      6895 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_int__25    |
 
|      6885 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_int        |
 
|      3693 | MDL_SHARED_HIGH_PRIO    | NULL          | Table metadata lock | pmacontrol   | status_value_double__18 |
 
|      6828 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_double     |
 
|      6831 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_double     |
 
|      6848 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_double     |
 
|      6847 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_double     |
 
|      6869 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_double     |
 
|      6870 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_double     |
 
|      6886 | MDL_SHARED_WRITE        | NULL          | Table metadata lock | pmacontrol   | status_value_double     |
 
+-----------+-------------------------+---------------+---------------------+--------------+-------------------------+

on processlist we can see : (the oldest transaction)

show table status from `pmacontrol` like 'status_value_double__18';

Nothing about a lock in RocksDB (tried to see TokuDB and InnoDB too)

One sting strange I can execute this query without problem :

show table status from `pmacontrol` like 'status_value_double__18';

but not a select on table : status_value_double__18

in same time i saw on error log : 

sept. 21 16:04:51 aurelien-rdc mysqld[20310]: 2017-09-21 16:04:51 140320728037568 [Note] /usr/sbin/mysqld (mysqld 10.2.8-MariaDB-10.2.8+maria~xenial) starting as process 20310 … 
sept. 21 16:04:51 aurelien-rdc mysqld[20310]: 2017-09-21 16:04:51 140320728037568 [ERROR] mysqld: Can't lock aria control file '/var/lib/mysql/aria_log_control' for exclusive use, error: 11. Will retry for 30 sec lines 1-18/18 (END)

A ticket for Kentoku I guess =)

 Comments   
Comment by Elena Stepanova [ 2017-10-06 ]

The error in the log file typically means that there is another instance running on the same datadir. Whether it causes the reported problem, or is a side-effect of the reported problem, or (unlikely) unrelated, remains to be seen.

Comment by Aurélien LEQUOY [ 2017-10-07 ]

maybe the log not revealent, but this problem happen in 100% of my cases

Comment by Andrii Nikitin (Inactive) [ 2017-10-19 ]

I think I can reproduce the problem by running this script for few minutes :
https://github.com/AndriiNikitin/bugs/blob/master/MDEV-14018.sh

The script will set up new server instance on port 3307 with some scripts and datadir in current directory (no root access is needed).
So, it requires 10.2.9 binaries installed including spider engine. 

Uptime: 136  Threads: 23  Questions: 469664  Slow queries: 0  Opens: 349631  Flush tables: 2623  Open tables: 114  Queries per second avg: 3453.411
 
1	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
3	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
2	system user		NULL	Daemon	NULL	InnoDB purge coordinator	NULL	0.000
 
4	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
5	system user		NULL	Daemon	NULL	InnoDB shutdown handler	NULL	0.000
 
47723	root	localhost	test	Query	0	query end	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
47728	root	localhost	test	Query	0	query end	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
47731	root	localhost	test	Query	0	query end	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
47743	root	localhost:56302	test	Query	0	init	commit	0.000
 
47745	root	localhost	test	Query	0	query end	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
47746	root	localhost	test	Query	0	Waiting for table flush	flush tables	0.000
 
47748	root	localhost:56305	test	Query	0	init	commit	0.000
 
47749	root	localhost:56304	test	Query	0	init	commit	0.000
 
47747	root	localhost:56306	test	Query	0	init	commit	0.000
 
47751	root	localhost	test	Query	0	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
47752	root	localhost	test	Query	0	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
47758	root	localhost	test	Query	0	init	show processlist	0.000
 
Com_insert	12073
 
Com_insert_select	12401
 
Handler_commit	35049
 
Uptime: 146  Threads: 23  Questions: 474926  Slow queries: 0  Opens: 353623  Flush tables: 2652  Open tables: 0  Queries per second avg: 3252.917
 
1	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
3	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
2	system user		NULL	Daemon	NULL	InnoDB purge coordinator	NULL	0.000
 
4	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
5	system user		NULL	Daemon	NULL	InnoDB shutdown handler	NULL	0.000
 
48372	root	localhost	test	Query	8	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48384	root	localhost	test	Query	8	Opening tables	show table status	0.000
 
48385	root	localhost	test	Query	8	Unlocking tables	show table status	0.000
 
48387	root	localhost:56608	test	Sleep	8		NULL	0.000
 
48388	root	localhost	test	Query	8	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48390	root	localhost	test	Query	8	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48389	root	localhost	test	Query	8	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48391	root	localhost	test	Killed	8	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48395	root	localhost	test	Query	7	Waiting for table flush	flush tables	0.000
 
48405	root	localhost	test	Query	1	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48407	root	localhost	test	Query	0	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48409	root	localhost	test	Query	0	init	show processlist	0.000
 
Com_insert	12195
 
Com_insert_select	12539
 
Handler_commit	35421
 
Uptime: 156  Threads: 23  Questions: 474971  Slow queries: 0  Opens: 353623  Flush tables: 2653  Open tables: 0  Queries per second avg: 3044.685
 
1	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
3	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
2	system user		NULL	Daemon	NULL	InnoDB purge coordinator	NULL	0.000
 
4	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
5	system user		NULL	Daemon	NULL	InnoDB shutdown handler	NULL	0.000
 
48372	root	localhost	test	Query	18	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48384	root	localhost	test	Query	18	Opening tables	show table status	0.000
 
48385	root	localhost	test	Query	18	Unlocking tables	show table status	0.000
 
48387	root	localhost:56608	test	Sleep	18		NULL	0.000
 
48388	root	localhost	test	Killed	18	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48390	root	localhost	test	Query	18	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48389	root	localhost	test	Query	18	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48391	root	localhost	test	Killed	18	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48405	root	localhost	test	Query	11	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48407	root	localhost	test	Query	10	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48413	root	localhost	test	Query	7	Waiting for table flush	flush tables	0.000
 
48421	root	localhost	test	Query	1	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48424	root	localhost	test	Query	0	init	show processlist	0.000
 
Com_insert	12195
 
Com_insert_select	12542
 
Handler_commit	35421
 
Uptime: 166  Threads: 23  Questions: 475033  Slow queries: 0  Opens: 353623  Flush tables: 2654  Open tables: 0  Queries per second avg: 2861.644
 
1	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
3	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
2	system user		NULL	Daemon	NULL	InnoDB purge coordinator	NULL	0.000
 
4	system user		NULL	Daemon	NULL	InnoDB purge worker	NULL	0.000
 
5	system user		NULL	Daemon	NULL	InnoDB shutdown handler	NULL	0.000
 
48372	root	localhost	test	Query	28	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48384	root	localhost	test	Query	28	Opening tables	show table status	0.000
 
48385	root	localhost	test	Query	28	Unlocking tables	show table status	0.000
 
48388	root	localhost	test	Killed	28	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48390	root	localhost	test	Query	28	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48389	root	localhost	test	Query	28	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48391	root	localhost	test	Killed	28	Opening tables	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48407	root	localhost	test	Query	20	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48427	root	localhost	test	Query	8	Waiting for table flush	flush tables	0.000
 
48439	root	localhost	test	Query	2	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48441	root	localhost	test	Query	1	Waiting for table flush	insert into mytable select floor(rand()*42),floor(rand()*42),now(),floor(rand()*10000)	0.000
 
48444	root	localhost	test	Query	0	init	show processlist	0.000
 
Com_insert	12195
 
Com_insert_select	12549
 
Handler_commit	35421

The error log doesn't contain anything interesting which corresponds with Uptime above:

2017-10-19 10:48:20 139742131349696 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.2.9-MariaDB-10.2.9+maria~xenial'  socket: '/home/a/e1/m1-system2/dt/my.sock'  port: 3307  mariadb.org binary distribution
 
2017-10-19 10:48:26 139742063077120 [Note] Detected table cache mutex contention at instance 1: 21% waits. Additional table cache instance activated. Number of instances after activation: 2.
 
2017-10-19 10:48:31 139741685212928 [Note] Detected table cache mutex contention at instance 1: 46% waits. Additional table cache instance activated. Number of instances after activation: 3.
 
2017-10-19 10:51:13 139741327542016 [Note] /usr/sbin/mysqld (unknown): Normal shutdown

I am also attaching stack traces in files 1 2 3 captured during outputs above

Comment by Aurélien LEQUOY [ 2017-12-04 ]

it's fixed in 10.2.11 ?

Comment by Sergei Golubchik [ 2017-12-05 ]

unlikely. it's not closed in Jira yet

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