Bug #47300 innodb insert dead lock
Submitted: 14 Sep 2009 8:19 Modified: 21 Dec 2009 16:58
Reporter: jim chen Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Locking Severity:S2 (Serious)
Version:5.1.30 OS:Linux
Assigned to: CPU Architecture:Any
Tags: dead lock

[14 Sep 2009 8:19] jim chen
Description:
insert into an innodb table,sametime dead lock.

I create a memory table,and create delete,update,insert triggers on it,the trigger's function is save the memory table's data to the innodb table,when mysql restart,the server auto reload data from innodb to memory table.

there only one thread insert data to memory table,bug have 30+ connections query data,if insert into innodb lock(dead),the memory is lock.

show innodb status;
=====================================
090914  8:41:26 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4168, signal count 3929
Mutex spin waits 0, rounds 525823, OS waits 418
RW-shared spins 7108, OS waits 2960; RW-excl spins 10727, OS waits 647
------------
TRANSACTIONS
------------
Trx id counter 0 19830663
Purge done for trx's n:o < 0 19830606 undo n:o < 0 0
History list length 32
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 12172, OS thread id 1148336448
MySQL thread id 74774, query id 62734442 localhost root
show innodb status
---TRANSACTION 0 0, not started, process no 12172, OS thread id 1144609088
MySQL thread id 74768, query id 62734351 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 12172, OS thread id 1146206528
MySQL thread id 74758, query id 62670294 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 12172, OS thread id 1145141568
MySQL thread id 74757, query id 62717987 127.0.0.1 windin
---TRANSACTION 0 19830662, not started, process no 12172, OS thread id 1143544128
MySQL thread id 74756, query id 62733433 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 12172, OS thread id 1142745408
MySQL thread id 74752, query id 62717989 127.0.0.1 windin
---TRANSACTION 0 19830661, not started, process no 12172, OS thread id 1150200128
MySQL thread id 74750, query id 62734426 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 12172, OS thread id 1147537728
MySQL thread id 73462, query id 62727935 127.0.0.1 windin
---TRANSACTION 0 19830472, not started, process no 12172, OS thread id 1147271488
MySQL thread id 71560, query id 62734441 127.0.0.1 windin Opening tables
SHOW FULL COLUMNS FROM "livenewscommon"."tb_livenews_disk"
---TRANSACTION 0 19830659, not started, process no 12172, OS thread id 1148070208
MySQL thread id 71521, query id 62731409 127.0.0.1 windin
---TRANSACTION 0 19830642, not started, process no 12172, OS thread id 1148868928
MySQL thread id 68369, query id 62734402 127.0.0.1 windin
---TRANSACTION 0 19825868, not started, process no 12172, OS thread id 1143810368
MySQL thread id 68357, query id 62734113 127.0.0.1 windin
---TRANSACTION 0 19830649, ACTIVE 3898 sec, process no 12172, OS thread id 1148602688, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 368, 0 row lock(s), undo log entries 1
MySQL thread id 71966, query id 61844219 127.0.0.1 windin update
insert into tb_livenews_industry_disk (industrycode,newsid,sourceid,channel,publishdate,lan) values(new.industrycode,new.newsid,new.sourceid,new.channel,new.publishdate,new.lan)
--------
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
13314 OS file reads, 61609 OS file writes, 23136 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 33, seg size 35,
84 inserts, 84 merged recs, 64 merges
Hash table size 8850487, node heap has 260 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1 2450820029
Log flushed up to   1 2450820029
Last checkpoint at  1 2450820029
0 pending log writes, 0 pending chkp writes
7404 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 4787954888; in additional pool allocated 12373504
Dictionary memory allocated 256760
Buffer pool size   262144
Free buffers       247823
Database pages     14061
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 13511, created 550, written 55145
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 12172, id 1140881728, state: waiting for server activity
Number of rows inserted 91821, updated 348, deleted 119659, read 10809979
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

How to repeat:
server:CPU*8 memory 8G

/*==============================================================*/
/* Table: tb_livenews_section_mem                               */
/*==============================================================*/
create table tb_livenews_section_mem
(
   section              varchar(20) not null,
   newsid               int not null,
   sourceid             mediumint not null default 0,
   channel              smallint not null default 0,
   publishdate          timestamp not null default current_timestamp on update current_timestamp,
   lan                  smallint not null default 0,
   index using hash(section),
   index using hash(sourceid),
   index using hash(channel),
   primary key (section, newsid)
)
type = memory;
/*==============================================================*/
/* Index: ix_tb_livenews_section_mem_source                     */
/*==============================================================*/
create index ix_tb_livenews_section_mem_source using hash on tb_livenews_section_mem
(
   section,
   sourceid
);

/*==============================================================*/
/* Index: ix_tb_livenews_section_mem_channel                    */
/*==============================================================*/
create index ix_tb_livenews_section_mem_channel on tb_livenews_section_mem
(
   channel,
   section,
   sourceid
);

/*==============================================================*/
/* Table: tb_livenews_section_disk                              */
/*==============================================================*/
create table tb_livenews_section_disk
(
   section              varchar(20) not null,
   newsid               int not null,
   sourceid             mediumint not null default 0,
   channel              smallint not null default 0,
   publishdate          timestamp not null default current_timestamp,
   lan                  smallint not null default 0,
   primary key (section, newsid)
)
type = innodb;

/*-- tb_livenews_section_mem's trigger --*/
DROP TRIGGER /*!50032 IF EXISTS */ tr_livenews_section_mem_insert$$
DROP TRIGGER /*!50032 IF EXISTS */ tr_livenews_section_mem_update$$
DROP TRIGGER /*!50032 IF EXISTS */ tr_livenews_section_mem_delete$$
CREATE
    TRIGGER tr_livenews_section_mem_insert AFTER INSERT ON tb_livenews_section_mem 
    FOR EACH ROW BEGIN
        if (@disable_trigger is null) then
         insert into tb_livenews_section_disk (section,newsid,sourceid,channel,publishdate,lan) values(new.section,new.newsid,new.sourceid,new.channel,new.publishdate,new.lan);
        end if;
    END;
$$
CREATE
    TRIGGER tr_livenews_section_mem_update AFTER UPDATE ON tb_livenews_section_mem 
    FOR EACH ROW BEGIN
        if (@disable_trigger is null) then
           update tb_livenews_section_disk set section=new.section,newsid=new.newsid,sourceid=new.sourceid,
		channel=new.channel,publishdate=new.publishdate,lan=new.lan
		where section=old.section and newsid=old.newsid;
        end if;
    END;
$$
CREATE
    TRIGGER tr_livenews_section_mem_delete AFTER DELETE ON tb_livenews_section_mem 
    FOR EACH ROW BEGIN
        if (@disable_trigger is null) then
		delete from tb_livenews_section_disk where section=old.section and newsid=old.newsid;
        end if;
    END;
$$

how to do:
one thread insert into tb_livenews_section_mem
30+ threads select from tb_livenews_section_mem
select distinct newsid from tb_livenews_section_mem where section='same value' order by publishdate desc limit ?,?

one day or two days where dead lock
[14 Sep 2009 8:20] jim chen
the file is my.cnf

Attachment: netojns1.cnf (application/octet-stream, text), 5.12 KiB.

[14 Sep 2009 8:37] Valeriy Kravchuk
I do not see any information about deadlock in SHOW INNODB STATUS. Can you, please, get the results of SHOW INNODB STATUS next time when deadlock will happen?

Send also the results of:

show create table tb_livenews_section_disk\G
[14 Sep 2009 10:01] jim chen
table lock info

Attachment: mysqllockinfo.txt (text/plain), 6.42 KiB.

[14 Sep 2009 10:05] jim chen
I think there's no dead lock too,but execute the insert sql one hour, my service can't work.
[14 Sep 2009 20:09] Sveta Smirnova
Thank you for the feedback.

Please send us output of SHOW PROCESSLIST in "lock" time also.
[16 Sep 2009 2:30] jim chen
mysql> show full processlist;
+-------+-----------------+-------------------+--------------------+---------+-------+------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Id    | User            | Host              | db                 | Command | Time  | State                  | Info                                                                                                               |
+-------+-----------------+-------------------+--------------------+---------+-------+------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|     2 | event_scheduler | localhost         | NULL               | Daemon  | 11534 | Waiting on empty queue | NULL                                                                                                               |
| 12156 | windin          | 127.0.0.1:38443   | livenewsthird      | Sleep   |    67 |                        | NULL                                                                                                               |
| 14538 | windin          | 127.0.0.1:60348   | livenewssubject    | Sleep   |    76 |                        | NULL                                                                                                               |
| 17070 | windin          | 127.0.0.1:45110   | livenewsselectness | Query   |  1949 | update                 | insert into tb_livenews_industry_disk (industrycode,newsid,sourceid,channel,publishdate,lan) values(new.industrycode,new.newsid,new.sourceid,new.channel,new.publishdate,new.lan) |
| 19081 | windin          | 127.0.0.1:53630   | livenewsselectness | Sleep   |     0 |                        | NULL                                                                                                               |
| 19816 | windin          | 127.0.0.1:52169   | livenewsimportance | Sleep   |    12 |                        | NULL                                                                                                               |
| 19826 | windin          | 127.0.0.1:54771   | livenewscommon     | Sleep   |   107 |                        | NULL                                                                                                               |
| 19832 | windin          | 127.0.0.1:54978   | livenewscommon     | Sleep   |     2 |                        | NULL                                                                                                               |
| 19833 | windin          | 127.0.0.1:54979   | livenewscommon     | Sleep   |     0 |                        | NULL                                                                                                               |
| 19834 | windin          | 127.0.0.1:55148   | livenewsthird      | Sleep   |     0 |                        | NULL                                                                                                               |
| 19835 | windin          | 127.0.0.1:55154   | livenewsselectness | Sleep   |    74 |                        | NULL                                                                                                               |
| 19844 | windin          | 10.100.1.72:34170 | NULL               | Query   |     0 | NULL                   | show full processlist                                                                                                               |
| 19845 | windin          | 127.0.0.1:49152   | livenewscommon     | Sleep   |   107 |                        | NULL                                                                                                               |
| 19846 | windin          | 127.0.0.1:49153   | livenewscommon     | Sleep   |   107 |                        | NULL                                                                                                               |
| 19847 | windin          | 127.0.0.1:49155   | livenewscommon     | Sleep   |   107 |                        | NULL                                                                                                               |
| 19848 | windin          | 127.0.0.1:49156   | livenewscommon     | Sleep   |     0 |                        | NULL                                                                                                               |
| 19849 | windin          | 127.0.0.1:49159   | livenewscommon     | Sleep   |     3 |                        | NULL                                                                                                               |
| 19850 | windin          | 127.0.0.1:49217   | livenewsthird      | Sleep   |     2 |                        | NULL                                                                                                               |
| 19851 | windin          | 127.0.0.1:49227   | livenewssubject    | Sleep   |     0 |                        | NULL                                                                                                               |
| 19852 | windin          | 127.0.0.1:49228   | livenewsselectness | Sleep   |     8 |                        | NULL                                                                                                               |
+-------+-----------------+-------------------+--------------------+---------+-------+------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
20 rows in set (0.01 sec)
[16 Sep 2009 2:31] jim chen
=====================================
090916 10:09:08 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 5 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 757, signal count 749
Mutex spin waits 0, rounds 3327, OS waits 78
RW-shared spins 1233, OS waits 615; RW-excl spins 62, OS waits 62
------------
TRANSACTIONS
------------
Trx id counter 0 20200641
Purge done for trx's n:o < 0 20199313 undo n:o < 0 0
History list length 3
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 31919, OS thread id 1147271488
MySQL thread id 19858, query id 8394719 localhost root
show innodb status
---TRANSACTION 0 0, not started, process no 31919, OS thread id 1150998848
MySQL thread id 19844, query id 8382896 10.100.1.72 windin
---TRANSACTION 0 0, not started, process no 31919, OS thread id 1141946688
MySQL thread id 19854, query id 8391879 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 31919, OS thread id 1147537728
MySQL thread id 19852, query id 8388586 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 31919, OS thread id 1148336448
MySQL thread id 19851, query id 8394434 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 31919, OS thread id 1142479168
MySQL thread id 19850, query id 8393421 127.0.0.1 windin
---TRANSACTION 0 20200639, not started, process no 31919, OS thread id 1142212928
MySQL thread id 19835, query id 8393799 127.0.0.1 windin
---TRANSACTION 0 0, not started, process no 31919, OS thread id 1144875328
MySQL thread id 19834, query id 8384065 127.0.0.1 windin
---TRANSACTION 0 20200640, not started, process no 31919, OS thread id 1145940288
MySQL thread id 19816, query id 8364013 127.0.0.1 windin
---TRANSACTION 0 20200636, not started, process no 31919, OS thread id 1146472768
MySQL thread id 19081, query id 8394708 127.0.0.1 windin Opening tables
SHOW FULL COLUMNS FROM "livenewsselectness"."tb_livenews_disk"
---TRANSACTION 0 20200323, not started, process no 31919, OS thread id 1145674048
MySQL thread id 14538, query id 8328076 127.0.0.1 windin
---TRANSACTION 0 20192792, not started, process no 31919, OS thread id 1146206528
MySQL thread id 12156, query id 8394668 127.0.0.1 windin
---TRANSACTION 0 20200627, ACTIVE 2049 sec, process no 31919, OS thread id 1144609088, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
1 lock struct(s), heap size 368, 0 row lock(s), undo log entries 1
MySQL thread id 17070, query id 7944922 127.0.0.1 windin update
insert into tb_livenews_industry_disk (industrycode,newsid,sourceid,channel,publishdate,lan) values(new.industrycode,new.newsid,new.sourceid,new.channel,new.publishdate,new.lan)
--------
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
11562 OS file reads, 21203 OS file writes, 7317 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 33, seg size 35,
99 inserts, 99 merged recs, 74 merges
Hash table size 8850487, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1 2526135212
Log flushed up to   1 2526135212
Last checkpoint at  1 2526135212
0 pending log writes, 0 pending chkp writes
2566 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 4787954888; in additional pool allocated 12152832
Dictionary memory allocated 256760
Buffer pool size   262144
Free buffers       250392
Database pages     11750
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 11614, created 136, written 18574
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 31919, id 1140881728, state: waiting for server activity
Number of rows inserted 24000, updated 10, deleted 3093, read 2605502
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
[16 Sep 2009 9:15] jim chen
the processlist when lock

Attachment: processlist.txt (text/plain), 18.22 KiB.

[16 Sep 2009 9:15] jim chen
innodb status when lock

Attachment: innodbstatus.txt (text/plain), 4.49 KiB.

[21 Nov 2009 16:58] Valeriy Kravchuk
Please, send the results of:

show create table tb_livenews_section_disk\G

Do you have any triggers on this table or triggers that modifies this table?

In any case, there is no deadlock. I see INSERT into this table, likely - from trigger, and a lot of blocked SELECTs from another table. We have to find out how these table are related.
[22 Dec 2009 0:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".