MySQL Bugs: #39358: Concurrency locks causes deadlocks

Bug #39358	Concurrency locks causes deadlocks
Submitted:	10 Sep 2008 5:38	Modified:	4 Oct 2008 6:53
Reporter:	Julien B	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S3 (Non-critical)
Version:	5.0.51-log	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	Lock deadlock waiting

Description:
Hello,

I have an application that insert some records into an innodb table that we will call "collect". There are many processes that insert those records at the same time.

I have a cron batch job that runs an "insert ... select... from collect".
This statement locks collect table during the execution.
Sometimes, this query freezes and sometimes this query gives me a deadlock error.
I have tried to put a lock tables before the insert...select statement but it changes nothing.

I think there is a problem because if i put a lock tables before the insert select i don t understand why it causes deadlocks.
I think the insert...select statement should not freeze.

Thanks

Julien

How to repeat:
When processes insert data into Collect Table, the folowing statement is freezing (or cause deadlock sometimes):

Lock Collect write,destination write;
insert destination select ... from Collect

Thank you for a problem report. Please, send SHOW INNODB STATUS results with the information about a deadlock.

=====================================

080910  9:02:31 INNODB MONITOR OUTPUT

=====================================

Per second averages calculated from the last 2 seconds

----------

SEMAPHORES

----------

OS WAIT ARRAY INFO: reservation count 3952106, signal count 3707754

Mutex spin waits 0, rounds 1661059857, OS waits 2567939

RW-shared spins 1673794, OS waits 136269; RW-excl spins 11041065, OS
waits 142874

------------------------

LATEST DETECTED DEADLOCK

------------------------

080907 15:33:33

*** (1) TRANSACTION:

TRANSACTION 0 616128355, ACTIVE 41 sec, process no 12724, OS thread id
1162983744 inserting

mysql tables in use 1, locked 1

LOCK WAIT 7 lock struct(s), heap size 1216, undo log entries 1

MySQL thread id 4831975, query id 306026154 localhost bdd_test update

insert into collect (id_pub,id_site,date_time,typ) values
('7','4610',unix_timestamp(),"visu")

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 243 page no 1905 n bits 80 index `index_test_2` of
table `bdd_test/collect` trx id 0 616128355 lock_mode X locks gap before
rec insert intention waiting

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

 0: len 1; hex 02; asc  ;; 1: len 4; hex 00000001; asc     ;; 2: len 6;
hex 00000a096db6; asc     m ;;

*** (2) TRANSACTION:

TRANSACTION 0 616120362, ACTIVE 147 sec, process no 12724, OS thread id
1174165824 fetching rows, thread declared inside InnoDB 475

mysql tables in use 5, locked 5

2542 lock struct(s), heap size 374768, undo log entries 888

MySQL thread id 4830576, query id 306012134 localhost bdd_test Sending data

insert into destination (       
date,id_site,id_pub,cron_nb_visualisations,cron_nb_clics        )   
select        '1220738400',    id_site,    id_pub,    (select count(*)
from collect where
unix_timestamp(date(from_unixtime(date_time)))='1220738400' and
collect.id_site is not null and typ="visu" and
collect.id_pub=pubs.id_pub and collect.id_site=sites.id_site),   
(select count(*) from collect where
unix_timestamp(date(from_unixtime(date_time)))='1220738400' and
collect.id_site is not null and typ="clic" and
collect.id_pub=pubs.id_pub and collect.id_site=sites.id_site)    from
pubs,sites

*** (2) HOLDS THE LOCK(S):

RECORD LOCKS space id 243 page no 1905 n bits 80 index `index_test_2` of
table `bdd_test/collect` trx id 0 616120362 lock mode S

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 3; compact format; info
bits 0

 0: len 1; hex 02; asc  ;; 1: len 4; hex 00000001; asc     ;; 2: len 6;
hex 00000a096db6; asc     m ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 243 page no 10250 n bits 608 index `index_test_1`
of table `bdd_test/collect` trx id 0 616120362 lock mode S waiting

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

 0: len 1; hex 01; asc  ;; 1: len 4; hex 00000007; asc     ;; 2: len 4;
hex 00001202; asc     ;; 3: len 6; hex 00000a41b842; asc    A B;;

*** WE ROLL BACK TRANSACTION (1)

------------

TRANSACTIONS

------------

Trx id counter 0 645183641

Purge done for trx's n:o < 0 645182418 undo n:o < 0 0

History list length 0

Total number of lock structs in row lock hash table 0

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 0 0, not started, process no 12724, OS thread id 1189607744

MySQL thread id 6540860, query id 417087125 localhost root

show innodb status

--------

FILE I/O

--------

I/O thread 0 state: waiting for i/o request (insert buffer thread)

I/O thread 1 state: waiting for i/o request (log thread)

I/O thread 2 state: waiting for i/o request (read thread)

I/O thread 3 state: waiting for i/o request (write thread)

Pending normal aio reads: 0, aio writes: 0,

 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0

Pending flushes (fsync) log: 0; buffer pool: 0

14486 OS file reads, 30997781 OS file writes, 28698905 OS fsyncs

0.00 reads/s, 0 avg bytes/read, 41.98 writes/s, 41.98 fsyncs/s

-------------------------------------

INSERT BUFFER AND ADAPTIVE HASH INDEX

-------------------------------------

Ibuf: size 1, free list len 54, seg size 56,

1255 inserts, 1255 merged recs, 401 merges

Hash table size 9786619, used cells 2603954, node heap has 4466 buffer(s)

499.25 hash searches/s, 81.46 non-hash searches/s

---

LOG

---

Log sequence number 22 842179571

Log flushed up to   22 842179571

Last checkpoint at  22 840216103

0 pending log writes, 0 pending chkp writes

28244580 log i/o's done, 41.48 log i/o's/second

----------------------

BUFFER POOL AND MEMORY

----------------------

Total memory allocated 5503132090; in additional pool allocated 1020416

Buffer pool size   301824

Free buffers       196192

Database pages     101166

Modified db pages  965

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages read 24219, created 101749, written 4979339

0.00 reads/s, 0.00 creates/s, 0.00 writes/s

Buffer pool hit rate 1000 / 1000

--------------

ROW OPERATIONS

--------------

0 queries inside InnoDB, 0 queries in queue

1 read views open inside InnoDB

Main thread process no. 12724, id 1157658944, state: sleeping

Number of rows inserted 49020471, updated 7587642, deleted 45178026,
read 212211784941

41.48 inserts/s, 0.00 updates/s, 0.00 deletes/s, 12094.95 reads/s

----------------------------

END OF INNODB MONITOR OUTPUT

============================

Please, send the results of:

show global variables like 'innodb_table%';

From what I see you have a usual deadlock situation.

innodb_table_locks  	ON

Please set innodb_table_locks to OFF and let us know if this will solve your problem.

I don t think this is a good idea.
We need innodb locking and we can not put this variable to OFF.
Our application wont work properly if there is no locking...
Do you have any idea of the source of this problem ?

We have this problem on 5.0.45-log too

Thank you for the feedback.

You have next in the InnoDB status output:

LATEST DETECTED DEADLOCK

------------------------

080907 15:33:33

*** (1) TRANSACTION:

...

insert into collect (id_pub,id_site,date_time,typ) values
('7','4610',unix_timestamp(),"visu")

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:

...

*** (2) TRANSACTION:

...

insert into destination (       
date,id_site,id_pub,cron_nb_visualisations,cron_nb_clics        )   
select        '1220738400',    id_site,    id_pub,    (select count(*)
from collect where
unix_timestamp(date(from_unixtime(date_time)))='1220738400' and
collect.id_site is not null and typ="visu" and
collect.id_pub=pubs.id_pub and collect.id_site=sites.id_site),   
(select count(*) from collect where
unix_timestamp(date(from_unixtime(date_time)))='1220738400' and
collect.id_site is not null and typ="clic" and
collect.id_pub=pubs.id_pub and collect.id_site=sites.id_site)    from
pubs,sites

*** (2) HOLDS THE LOCK(S):

So I also think this is usual deadlock: transaction 2 holds read lock of table collect and doesn't allow to modify it. Please read about how to cope with deadlocks at http://dev.mysql.com/doc/refman/5.0/en/innodb-deadlocks.html

I dont agree with you: There is 2 points:

1- Why this causes a deadlock ? When a table is locked write, other access should wait instead of deadlock ?

2- Why sometimes the lock causes an infinite wait ?

Thanks

Julien