系统问题经常停顿,报1305 timeout 错误信息

mysql 版本 : 5.0.27-standard-log
错误信息: 1305 Lock wait timeout exceeded; try restarting transaction

通过 show innodb status 有如下内容,请看看到底什么原因呢 ?

=====================================
070725 9:22:26 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 2 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1235, signal count 1235
Mutex spin waits 1914, rounds 21169, OS waits 35
RW-shared spins 1110, OS waits 555; RW-excl spins 646, OS waits 636
------------------------
LATEST DETECTED DEADLOCK
------------------------
070724 16:23:22
*** (1) TRANSACTION:
TRANSACTION 0 78344589, ACTIVE 26 sec, process no 20023, OS thread id 2716969904 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 320
MySQL thread id 46, query id 106464 192.168.2.31 foxhis updating
delete from selected_account where pc_id = NAME_CONST('var_pc_id',_latin1'0005')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 10779 n bits 80 index `index1` of table `smart/selected_account` trx id 0 78344589 lock_mode X waiting
Record lock, heap no 9 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
0: len 1; hex 32; asc 2;; 1: len 4; hex 30303031; asc 0001;; 2: len 4; hex 80000002; asc ;; 3: len 10; hex 46373037323330303034; asc F707230004;; 4: len 4; hex 80000000; asc ;; 5: len 6; hex 000004ab6fe1; asc o ;; 6: len 7; hex 8000000f510110; asc Q ;;

*** (2) TRANSACTION:
TRANSACTION 0 78344161, ACTIVE 35 sec, process no 20023, OS thread id 2706172848 starting index read, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
73 lock struct(s), heap size 5504, undo log entries 111
MySQL thread id 41, query id 108756 192.168.2.32 foxhis updating
delete from selected_account where type ='2' and pc_id ='0001' and ( mdi_id =2 or mdi_id =- 2 )
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 10779 n bits 80 index `index1` of table `smart/selected_account` trx id 0 78344161 lock_mode X locks rec but not gap
Record lock, heap no 9 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
0: len 1; hex 32; asc 2;; 1: len 4; hex 30303031; asc 0001;; 2: len 4; hex 80000002; asc ;; 3: len 10; hex 46373037323330303034; asc F707230004;; 4: len 4; hex 80000000; asc ;; 5: len 6; hex 000004ab6fe1; asc o ;; 6: len 7; hex 8000000f510110; asc Q ;;

Record lock, heap no 10 PHYSICAL RECORD: n_fields 7; compact format; info bits 32
0: len 1; hex 32; asc 2;; 1: len 4; hex 30303031; asc 0001;; 2: len 4; hex 80000004; asc ;; 3: len 10; hex 46373037323330303034; asc F707230004;; 4: len 4; hex 80000000; asc ;; 5: len 6; hex 000004ab6fe1; asc o ;; 6: len 7; hex 000000238f2139; asc # !9;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 10779 n bits 80 index `index1` of table `smart/selected_account` trx id 0 78344161 lock_mode X waiting
Record lock, heap no 9 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
0: len 1; hex 32; asc 2;; 1: len 4; hex 30303031; asc 0001;; 2: len 4; hex 80000002; asc ;; 3: len 10; hex 46373037323330303034; asc F707230004;; 4: len 4; hex 80000000; asc ;; 5: len 6; hex 000004ab6fe1; asc o ;; 6: len 7; hex 8000000f510110; asc Q ;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 0 78466505
Purge done for trx's n:o < 0 78465710 undo n:o < 0 0
History list length 5
Total number of lock structs in row lock hash table 22
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 78466504, not started, process no 20023, OS thread id 2717170608
MySQL thread id 1300, query id 1159522 192.168.2.37 foxhis
---TRANSACTION 0 78463440, not started, process no 20023, OS thread id 2706172848
MySQL thread id 1291, query id 1145545 192.168.2.39 foxhis
---TRANSACTION 0 0, not started, process no 20023, OS thread id 2652896176
MySQL thread id 1281, query id 1109713 192.168.2.43 foxhis
---TRANSACTION 0 78463299, not started, process no 20023, OS thread id 2717772720
MySQL thread id 1264, query id 1144288 192.168.2.45 foxhis
---TRANSACTION 0 78463395, not started, process no 20023, OS thread id 2716969904
MySQL thread id 1253, query id 1150796 192.168.2.32 foxhis
---TRANSACTION 0 0, not started, process no 20023, OS thread id 2652695472
MySQL thread id 1229, query id 912349 192.168.2.44 foxhis
---TRANSACTION 0 78466487, ACTIVE 14 sec, process no 20023, OS thread id 2704276400 starting index read
mysql tables in use 3, locked 3
LOCK WAIT 2 lock struct(s), heap size 320
MySQL thread id 1307, query id 1158522 192.168.2.31 foxhis Sending data
call p_gds_after_login ('02', 'FOX', '1', 0)
------- TRX HAS BEEN WAITING 14 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 9031 n bits 72 index `bdate` of table `smart/sysdata` trx id 0 78466487 lock mode S waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 36; compact format; info bits 0
0: len 8; hex 80001241145096c0; asc A P ;; 1: len 6; hex 000004ad4913; asc I ;; 2: len 7; hex 0000002342159b; asc #B ;; 3: len 8; hex 80001241145096c0; asc A P ;; 4: len 1; hex 54; asc T;; 5: len 1; hex 54; asc T;; 6: len 8; hex 8000124114415480; asc A AT ;; 7: len 8; hex 8000124114415480; asc A AT ;; 8: len 1; hex 37; asc 7;; 9: len 3; hex 323033; asc 203;; 10: len 3; hex 363033; asc 603;; 11: len 4; hex 80000000; asc ;; 12: len 4; hex 80000000; asc ;; 13: len 4; hex 80000000; asc ;; 14: len 4; hex 800c3500; asc 5 ;; 15: len 4; hex 800e7ef0; asc ~ ;; 16: len 4; hex 805b8d99; asc [ ;; 17: len 4; hex 80000000; asc ;; 18: len 4; hex 80000000; asc ;; 19: len 4; hex 80000000; asc ;; 20: len 5; hex 802a277931; asc *'y1;; 21: len 5; hex 802a277931; asc *'y1;; 22: len 5; hex 802a277931; asc *'y1;; 23: len 5; hex 802a27793a; asc *'y:;; 24: len 5; hex 802a277931; asc *'y1;; 25: len 5; hex 802a277939; asc *'y9;; 26: len 5; hex 802a277931; asc *'y1;; 27: len 4; hex 80000000; asc ;; 28: len 4; hex 80000000; asc ;; 29: len 4; hex 80000000; asc ;; 30: len 4; hex 80000000; asc ;; 31: len 4; hex 80000000; asc ;; 32: len 5; hex 802a277931; asc *'y1;; 33: len 5; hex 802a277947; asc *'yG;; 34: len 5; hex 802a277931; asc *'y1;; 35: len 5; hex 802a277931; asc *'y1;;

------------------
---TRANSACTION 0 78466127, ACTIVE 17 sec, process no 20023, OS thread id 2652494768 starting index read
mysql tables in use 3, locked 3
LOCK WAIT 35 lock struct(s), heap size 2496, undo log entries 3
MySQL thread id 1309, query id 1159518 192.168.2.39 foxhis Sending data
call p_gds_after_login ('02', 'FOX', '1', 0)
Trx read view will not see trx with id >= 0 78466128, sees < 0 78465259
------- TRX HAS BEEN WAITING 11 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 9031 n bits 72 index `bdate` of table `smart/sysdata` trx id 0 78466127 lock mode S waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 36; compact format; info bits 0
0: len 8; hex 80001241145096c0; asc A P ;; 1: len 6; hex 000004ad4913; asc I ;; 2: len 7; hex 0000002342159b; asc #B ;; 3: len 8; hex 80001241145096c0; asc A P ;; 4: len 1; hex 54; asc T;; 5: len 1; hex 54; asc T;; 6: len 8; hex 8000124114415480; asc A AT ;; 7: len 8; hex 8000124114415480; asc A AT ;; 8: len 1; hex 37; asc 7;; 9: len 3; hex 323033; asc 203;; 10: len 3; hex 363033; asc 603;; 11: len 4; hex 80000000; asc ;; 12: len 4; hex 80000000; asc ;; 13: len 4; hex 80000000; asc ;; 14: len 4; hex 800c3500; asc 5 ;; 15: len 4; hex 800e7ef0; asc ~ ;; 16: len 4; hex 805b8d99; asc [ ;; 17: len 4; hex 80000000; asc ;; 18: len 4; hex 80000000; asc ;; 19: len 4; hex 80000000; asc ;; 20: len 5; hex 802a277931; asc *'y1;; 21: len 5; hex 802a277931; asc *'y1;; 22: len 5; hex 802a277931; asc *'y1;; 23: len 5; hex 802a27793a; asc *'y:;; 24: len 5; hex 802a277931; asc *'y1;; 25: len 5; hex 802a277939; asc *'y9;; 26: len 5; hex 802a277931; asc *'y1;; 27: len 4; hex 80000000; asc ;; 28: len 4; hex 80000000; asc ;; 29: len 4; hex 80000000; asc ;; 30: len 4; hex 80000000; asc ;; 31: len 4; hex 80000000; asc ;; 32: len 5; hex 802a277931; asc *'y1;; 33: len 5; hex 802a277947; asc *'yG;; 34: len 5; hex 802a277931; asc *'y1;; 35: len 5; hex 802a277931; asc *'y1;;

------------------
---TRANSACTION 0 78465299, ACTIVE 23 sec, process no 20023, OS thread id 2716769200
2 lock struct(s), heap size 320, undo log entries 2
MySQL thread id 1203, query id 1159527 192.168.2.39 root
/*
call p_gds_master_delete ('F707230004', 'FOX', 'F');
select @@autocommit;
show status;
show variables;
*/
show innodb status
Trx read view will not see trx with id >= 0 78465300, sees < 0 78465259
---TRANSACTION 0 78465259, ACTIVE 31 sec, process no 20023, OS thread id 2716568496
MySQL thread id 1302, query id 1156047 192.168.2.32 foxhis
Trx read view will not see trx with id >= 0 78465260, sees < 0 78465260
--------
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
30952 OS file reads, 9299 OS file writes, 5947 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 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 34679, used cells 510, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 761429355
Log flushed up to 0 761429355
Last checkpoint at 0 761429355
0 pending log writes, 0 pending chkp writes
4611 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 25270510; in additional pool allocated 1048576
Buffer pool size 512
Free buffers 0
Database pages 510
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 35056, created 670, written 5400
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
4 read views open inside InnoDB
Main thread process no. 20023, id 2996902832, state: waiting for server activity
Number of rows inserted 28545, updated 2890, deleted 4881, read 2416550
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Taxonomy upgrade extras:

版本和原始的错误信息贴上来。
另外,msn隐身的话我无法回复消息.....

MySQL方案、培训、支持
MySQL 用户组

mysql 版本 : 5.0.27-standard-log
错误信息: 1305 Lock wait timeout exceeded; try restarting transaction

这个错误代码是1205才对吧。。。。。
你的事务应用的很不合理,出现了大量的死锁并且超时,导致这个问题的。
1、优化事务,尽量缩短事务时间
2、加大innodb的锁超时
3、全局优化,参考本站的优化文章或者可以考虑商业支持 :)

MySQL方案、培训、支持
MySQL 用户组

该问题已经解决了!

重点是两个:
1. 事务提交要完整;
2. savepoint 释放要完整;

如果我在北京,肯定请客了,一起出去耍耍哦。
不知道杭州搞 MYSQL C/S 开发的多不多 ??

-------------------------:)
无可奈何花落去,
似曾相识燕归来。
--------------------------:)
学习 MYSQL

hi:
最近项目mysql的慢查询日志文件中出现insert的慢查询语句,
除了索引可能引起insert为慢查询之外,
还有哪些原因可能会导致insert出现在慢查询日志文件中,谢谢!(注:key_buffer_size = 32M,使用不到3k,因此应该排除维护索引而引起的慢查询)

Buffer used 3.00k of 32.00M %Used: 0.01
Current 5.84M %Usage: 18.24
Write hit 46.59%
Read hit 99.58%

也可能是insert的时候,系统负载高,所以慢,或者可能是因为locked了,需要查看下locked_time

你好,首先感谢您的回复!

# Query_time: 1.020052 Lock_time: 0.000040 Rows_sent: 0 Rows_examined: 0

背景:
确实有锁的问题,目前是用压力机500个并发压此应用,此insert的操作即是一个事务,此外无其他操作
并且对此表无select和update,delete

问题:
1) Lock_time: 0.000040 这个锁的时间很短,这个锁是导致慢查询时间在Query_time: 1.020052 的原因?
2)如果确实是锁导致的慢查询,如何解决此慢查询?目前只insert对此表操作,sql上我想应该是没有太多优化,负载是必须要到这么高的程度,请问有何高见?

1. show global status;
2. show global variables;
3. show processlist;
4. show engine innodb status\G
5. 服务器硬件配置
6. 业务高峰期时,在系统上执行 vmstat 3 100 的结果

请先提供上述几个信息再做观