MySQL Bugs: #47180: ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction.

Bug #47180	ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction.
Submitted:	7 Sep 2009 18:17	Modified:	21 Oct 2009 17:50
Reporter:	Nadilson Ferreira	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S1 (Critical)
Version:	5.0.27	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	lock wait timeout exceeded

Description:
Hi All,

I have the following problem in mysql 5.0.27 system. The problems is that the system is working properly and completely out-of-the-blue the system starts to wait for acquire the lock as described below:

---TRANSACTION 2 1248748690, ACTIVE 41 sec, process no 26628, OS thread id 2083957664 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 320
MySQL thread id 35505, query id 50405302 128.223.1.48 ovpn Updating
UPDATE VPN_GROUPS SET CALL_COST_SUM=45406.71 WHERE VPN_GROUP_GUID_PK='E2FE1048-CB7D-53C6-4C65-A66B3CE7EEEE'
------- TRX HAS BEEN WAITING 41 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 10 page no 806 n bits 160 index `PRIMARY` of table `ovpn/VPN_GROUPS` trx id 2 1248748690 lock_mode X locks rec but not gap waiting
Record lock, heap no 33 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
 0: len 30; hex 45324645313034382d434237442d353343362d344336352d413636423343; asc E2FE1048-CB7D-53C6-4C65-A66B3C;...(truncated); 1: len 6; hex 00024a6dd55f; asc   Jm _;; 2: len 7; hex 000004801a0151; asc       Q;; 3: len 8; hex 800012411f0c04b7; asc    A    ;; 4: len 30; hex 46364245453334362d363242382d383032382d363430322d363731353932; asc F6BEE346-62B8-8028-6402-671592;...(truncated); 5: len 11; hex 53312e3130363931323230; asc S1.10691220;; 6: len 11; hex 53312e3130363931323230; asc S1.10691220;; 7: len 10; hex 312e3130363931323230; asc 1.10691220;; 8: SQL NULL; 9: len 4; hex 80024612; asc   F ;; 10: len 8; hex 0000000080370641; asc      7 A;; 11: len 8; hex 14ae47e1ea22e640; asc   G  " @;;

As you guys can see in the next described info extracted from the system, there is no concurrence lock or any thing that would explain why the lock is not acquired by mysql. After 50 secs (innodb_lock_wait_timeout), the application receives a error:

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction.

This problem remains for a while and again out-of-the-blue everything comes back to normal... After sometime it happens again. 

Does anybody have any tips?
 

How to repeat:
We did not find one deterministic way to repeat the problem.

Some info:

[mysql@gestor6 ~]$ mysql --version
mysql  Ver 14.12 Distrib 5.0.27, for redhat-linux-gnu (i686) using readline 5.0

mysql> SHOW FULL PROCESSLIST;
.
.
.
| 35502 | ovpn | 128.223.1.48:41133   | ovpn | Sleep       |    21 |                                                                | NULL                                                                                                        |
| 35505 | ovpn | 128.223.1.48:41134   | ovpn | Query       |    21 | Updating                                                       | UPDATE VPN_GROUPS SET CALL_COST_SUM=45406.71 WHERE VPN_GROUP_GUID_PK='E2FE1048-CB7D-53C6-4C65-A66B3CE7EEEE' |
| 37054 | repl | gestor5:33337        | NULL | Binlog Dump | 40815 | Has sent all binlog to slave; waiting for binlog to be updated | NULL                                                                                                        |
.
.
.
| 69635 | root | localhost            | ovpn | Query       |     0 | NULL                                                           | SHOW FULL PROCESSLIST                                                                                       |
51 rows in set (0.00 sec)

Environment information

Attachment: info.txt (text/plain), 47.52 KiB.

Hi All,

I have just attached a file with some relevant information.

Thanks,
  NF

Many thanks for writing a bug report.

MySQL 5.0.27 is really old. Please try newer version here:

recommended are: 5.1.38 or 5.0.85

Hi Susanne,

Thanks for your answer. But we have the system running in production environment and it would be complicated to migrate to a newer version this quick. Also we don't have reassurance that this would fix the problem. Do you have any old bug that fixed similar problem and we could check in order to be more secure that this migration would pay for the efforts.

Thanks,
  NF

Please, send complete results of SHOW FULL PROCESSLIST, without ommissions, next time you'll see this problem.

Send also the results of:

show create table VPN_GROUPS\G

Hi Jonas,

Thank you for your support. The full output of the SHOW FULL PROCESSLIST is already
attached in the files section.

The SHOW CREATE TABLE you will find below:

mysql> SHOW CREATE TABLE VPN_GROUPS\G
*************************** 1. row ***************************
       Table: VPN_GROUPS
Create Table: CREATE TABLE `VPN_GROUPS` (
  `VPN_GROUP_GUID_PK` varchar(36) NOT NULL default '',
  `CREATION_TIME` datetime NOT NULL default '0000-00-00 00:00:00',
  `VPN_GUID_FK` varchar(36) default NULL,
  `VPN_GROUP_ID` varchar(128) NOT NULL default '',
  `VPN_GROUP_NAME` varchar(100) NOT NULL default '',
  `VPN_GROUP_DESCRIPTION` varchar(128) NOT NULL default '',
  `ACCOUNT_GUID_FK` varchar(36) default NULL,
  `INCORE_VPN_ID` int(19) default NULL,
  `CONSUMED` double default NULL,
  `CALL_COST_SUM` double NOT NULL default '0',
  PRIMARY KEY  (`VPN_GROUP_GUID_PK`),
  UNIQUE KEY `VPN_GROUP_ID` (`VPN_GROUP_ID`),
  KEY `IDX_FK_1VPN_GROUPS` (`VPN_GUID_FK`),
  KEY `IDX_FK_2VPN_GROUPS` (`ACCOUNT_GUID_FK`),
  CONSTRAINT `0_340` FOREIGN KEY (`VPN_GUID_FK`) REFERENCES `VPNS` (`VPN_GUID_PK`) ON
DELETE CASCADE,
  CONSTRAINT `0_343` FOREIGN KEY (`ACCOUNT_GUID_FK`) REFERENCES `ACCOUNTS`
(`ACCOUNT_GUID_PK`) ON DELETE SET NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

Thanks,
  NF

Sorry, I meant Valeriy not Jonas.

Thanks,
  NF

Indeed, I missed that part in the file. Please, sent the entire error log also (compressed if it is big).

SHOW FULL PROCESSLIST

Attachment: mysql_ SHOW_FULL_PROCESSLIST.txt (text/plain), 13.21 KiB.

SHOW INNODB STATUS

Attachment: mysql_ SHOW_INNODB_STATUS_G.txt (text/plain), 11.92 KiB.

Thank you for the feedback.

You have following record in the InnoDB status:

---TRANSACTION 2 1248748690, ACTIVE 41 sec, process no 26628, OS thread id 2083957664 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 320
MySQL thread id 35505, query id 50405302 128.223.1.48 ovpn Updating
UPDATE VPN_GROUPS SET CALL_COST_SUM=45406.71 WHERE VPN_GROUP_GUID_PK='E2FE1048-CB7D-53C6-4C65-A66B3CE7EEEE'
------- TRX HAS BEEN WAITING 41 SEC FOR THIS LOCK TO BE GRANTED:

While you have several unfinished transactions which hold locks:

---TRANSACTION 2 1248748689, ACTIVE 41 sec, process no 26628, OS thread id 2071985056
2 lock struct(s), heap size 320, undo log entries 1
MySQL thread id 35502, query id 50405280 128.223.1.48 ovpn
---TRANSACTION 2 1248745282, ACTIVE 61 sec, process no 26628, OS thread id 2079390624
4 lock struct(s), heap size 320, undo log entries 2
MySQL thread id 69386, query id 50388643 128.223.1.16 ovpn
...

Please check if you have some not committed transaction which uses table VPN_GROUPS running in parallel with UPDATE query. Please note if query is not running you will not have it in SHOW PROCESSLIST.

Hi,

How can I check which tables are these locks related to?
Is there any command or log option that I can enable in order to know which tables are still locked after the command execution is finished but the transaction is not yet closed?

Thanks,
  NF

Thank you for the feedback.

This only can be checked on application level, proxy or using general query log.

Hi,

I have one question concerning the mysql lock mechanism.

If I have two tables MOBILES and VPN_GROUPS and I need to UPDATE a mobiles row (change on field value in the MOBILE table), but I need to use the VPN_GROUPS in the UPDATE statement (as described in the example below) and WHERE cause, why are both, the MOBILE and the VPN_GROUPS rows locked?

UPDATE MOBILES, VPN_GROUPS SET IS_BLOCKED=100 WHERE MOBILES.GROUP_GUID_FK=VPN_GROUPS.VPN_GROUP_GUID_PK AND MOBILES.MSISDN='82000004';

Shouldn't solely the MOBILES row be locked?

Thanks,
 Nadilson

Thank you for the feedback.

> UPDATE MOBILES, VPN_GROUPS SET IS_BLOCKED=100 WHERE
MOBILES.GROUP_GUID_FK=VPN_GROUPS.VPN_GROUP_GUID_PK AND MOBILES.MSISDN='82000004';
> 
> Shouldn't solely the MOBILES row be locked?

Not, you request to UPDATE of 2 tables, so 2 tables would be locked.

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".