11

I have had this on going issue for years and never been able to get to the bottom of it. I have no idea what could be causing these locks.

The error is: Lock wait timeout exceeded; try restarting transaction SQLState: 41000 VendorError: 1205

The SQL statement is a single insert statement running within a transaction. All inserts are of this form, so no bulk inserts nor mix mode inserts etc.

INSERT INTO attachment( id, entityid, entitytype , addeduserid , deleteduserid , fullpath , filename, status, creationdate, lastupdated, deletiondate, hasfile,notes,history,type,mimeinfo,archivedby,archivedon, referencedate,changedby,changedon ) values (0,0,2,360,null,NULL,NULL,1,'2013-02-20 08:45:31','2013-02-20 08:45:31',NULL,0,NULL,'20/02/2013 08:45:UserA:File uploaded internally. <br>',0,NULL,null,NULL,NULL,null,NULL);

System Configuration: Mysql version: 'Server version: 5.1.61 Source distribution' (on Redhat)

Storage: INNODB

INNODB related configuration (partially edited from my.cnf):

innodb_file_per_table=1
innodb_buffer_pool_size=3G
innodb_additional_mem_pool_size=20M
innodb_log_file_size=512M
innodb_log_files_in_group=2
innodb_log_buffer_size=16M
innodb_support_xa=1
innodb_doublewrite=1
innodb_thread_concurrency=0
innodb_flush_log_at_trx_commit=2
innodb_autoinc_lock_mode=2**
innodb_rollback_on_timeout=1
innodb_locks_unsafe_for_binlog=1**
thread_cache_size=8
query_cache_size=256M
query_cache_limit=4M
table_cache=2048
table_definition_cache=1024
tmp_table_size=512M
max_heap_table_size=512M
transaction-isolation=READ-COMMITTED**
innodb_table_locks=0**
innodb_lock_wait_timeout=50**

** these have been specifically added in relation to this issue.

Generally:

The system (i.e. have 6 application instances each with the same database structure all running on a single mysql instance) can run fine for days and then can have a run where Lock Waits start to occur and will normally get them appearing in groups over the period of the day. Each individual error will occur repeatedly because once it fails, I will try again, and normally the reattempt will fail. I have configured to retry 4 times. Often the Locks will occur on only a couple of different tables.

Todays specific instance of the issue:

This morning on the attachment table, there had not been an insert on the table since last night. There had also been no updates on the table since the previous night. If the locks are not related to other users doing updates and inserts, then could certain select statements causing locks? I have tried to ensure all select statements use attachment_general_index?

Due to the fact that I am mainly getting this on a couple different tables - here is the structure of this table.

CREATE TABLE `attachment` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`entityid` int(10) unsigned DEFAULT NULL,
`entitytype` tinyint(3) unsigned NOT NULL DEFAULT '0',
`addeduserid` int(10) unsigned NOT NULL,
`deleteduserid` int(10) unsigned DEFAULT NULL,
`fullpath` varchar(255) DEFAULT NULL,
`filename` varchar(255) DEFAULT NULL,
`status` tinyint(3) unsigned NOT NULL DEFAULT '0',
`creationdate` varchar(40) DEFAULT NULL,
`lastupdated` varchar(40) DEFAULT NULL,
`deletiondate` varchar(40) DEFAULT NULL,
`hasfile` tinyint(3) unsigned NOT NULL DEFAULT '0',
`notes` text,
`history` text,
`type` tinyint(3) unsigned DEFAULT '0',
`lastupdatedby` int(10) DEFAULT '0',
`lastupdatedinfo` varchar(255) DEFAULT NULL,
`mimeinfo` varchar(255) DEFAULT NULL,
`archivedby` int(10) unsigned DEFAULT NULL,
`archivedon` varchar(40) DEFAULT NULL,
`referencedate` varchar(40) DEFAULT NULL,
`changedby` int(10) unsigned DEFAULT NULL,
`changedon` varchar(40) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `attachment_addeduserid_fkey` (`addeduserid`),
KEY `attachment_deleteduserid_fkey` (`deleteduserid`),
KEY `attachment_archivedby_fkey` (`archivedby`),
KEY `attachment_changedby_fkey` (`changedby`),
KEY `attachment_general_index` (`entitytype`,`entityid`,`status`,`type`),
CONSTRAINT `attachment_ibfk_1` FOREIGN KEY (`addeduserid`) REFERENCES `user` (`id`),
CONSTRAINT `attachment_ibfk_2` FOREIGN KEY (`deleteduserid`) REFERENCES `user` (`id`),
CONSTRAINT `attachment_ibfk_3` FOREIGN KEY (`archivedby`) REFERENCES `user` (`id`),
CONSTRAINT `attachment_ibfk_4` FOREIGN KEY (`changedby`) REFERENCES `user` (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=3619 DEFAULT CHARSET=latin1$$

I have attached a recent SHOW INNODB STATUS, this is from today and there has not been a lock wait since yesterday. I do not understand all of this output, but the main thing is that the locks never seem to appear here. I assume cause they are not classified as deadlocks?

https://docs.google.com/document/d/1Hslf2B594n8ofAUYxN54Gh8FrSCIFNGGMtthVI_Lv4k/pub

Is it only the dead locks area that is interesting for this issue? If there are other areas I will try to collect when it occurs and can provide.

Any help would be appreciated.

Nick

  • What does `SHOW INNODB STATUS` say? – Danack Feb 20 '13 at 12:49
  • Also, what else in the transaction that errors out? I'm guessing at least one other insert because that can easily lead to: http://www.xaprb.com/blog/2006/08/03/a-little-known-way-to-cause-a-database-deadlock/ – Danack Feb 20 '13 at 12:52
  • @Danack , please see link above to some output to SHOW INNODB STATUS. For the failed transaction, generally there is not a large number of actions but generally never two inserts into the same table within the same transaction. Regarding the xaprb link (which I read a long time ago) - but due to the nature of the situation I did not think it applied? And thanks for the interest! –  Feb 20 '13 at 15:23
  • Another idea. You should turn your slow query log on, and try to match up ER_LOCK_WAIT_TIMEOUT errors with slow queries that were occurring at the same time. That may help if the cause isn't actually a transaction deadlock, but instead just a slow query that is not in a transaction but still has a lock on something. – Danack Feb 23 '13 at 00:13
  • I've just ran into this when I using START TRANSACTION and doing a ton of inserts. At some point the lock_timeout kicked in and it would throw the error when COMMITTING. – methodin Dec 04 '13 at 16:46

2 Answers2

10

I would like to share my "Eureka" moment with those of you who are scratching your heads over transaction timeouts and have found that none of the suggested server configuration changes help.

I was floundering to the point where I was seriously considering re-writing some of my application just so I could accommodate transaction timeouts (a collective groan is heard 'round the world).

I am paranoid about losing anything from my business transactions so I run a cron job that does a full mysqldump every 10 minutes (this is on top of double replication) throughout the day.

What I discovered was mysqldump hogs the server, locks the tables, and pretty much forbids anything else from using the database while it's doing it's thing. My Eureka moment came when I discovered that the transaction failures coincided with the mysqldump run times.

Long story short there are 3 command line options that will prevent mysqldump from killing your server. These are

  1. --single-transaction
  2. --quick
  3. --lock-tables=false

Many thanks to CA3LE @ How can I slow down a MySQL dump as to not affect current load on the server? for enlightening me.

Community
  • 1
  • 1
jjs
  • 101
  • 1
  • 3
3

(This should probably be a comment, but I have way too much text, and need the formatting).

I think it's a very similar issue to the one described at where:

  1. One transaction has a lock at the end of a table.
  2. A second transaction has a lock over most of the table.
  3. The first transaction tries to update/insert into the lock held by the second transaction. This fails so the one of the transactions is chosen to die.

Thanks for posting the show status. You're right that the deadlock shown doesn't seem to be related to the table you were asking about, but it does seem to be the same as the one at Xaprb.

Is it only the dead locks area that is interesting for this issue?

Yes, the exact parts are:

Transaction 1

UPDATE operative SET  lastupdated='2013-02-19 17:12:44'=N<EDITED> RECORD LOCKS space id 1789 page no 3622 n bits 112  index `PRIMARY` of table `<EDITED> `.`operative` trx id 0 233901602  lock_mode X locks rec but not gap waiting

*** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 1789 page no 3622 n bits 112 index `PRIMARY` of table `<EDITED> `.`operative`  trx id 0 233901602 lock_mode X locks rec but not gap waiting


Transaction 2

INSERT INTO opdate(operativeId,opdate,updatingUser,dategroup,type,notes,lastupdated) values (....) RECORD LOCKS space id 1789 page no 3622 n bits 112 index `PRIMARY` of table `<EDITED> `.`operative`  trx id 0 233901603 lock mode S locks rec but not gap


*** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 830 page no 112 n bits 808  index `opdate_unique` of table `<EDITED> `.`opdate` trx id 0 233901603 lock mode S waiting Record lock, heap no 739 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

This feels very similar to problem listed at xaprb. i.e.

  1. Transaction 2 has done an insert into a table, and now holds a lock on the primary key.
  2. Transaction 1 is doing a table scan to do the update and is waiting for the lock on that primary key.
  3. Transaction 2 is trying to do another insert, and needs to get a lock but is prevented from doing so because Transaction 1 already has it (I'm actually guessing there as you obfuscated the table name).

I'd suggest fixing this deadlock first as well as trying to fix the problem you were asking about.

Actually, I think your problem may not appear in the INNODB status. You're getting error code 1205 - which is ER_LOCK_WAIT_TIMEOUT, not error 1213 ER_LOCK_DEADLOCK. So although you effectively have a deadlock, it's not being classed as such.

I think if you can do a SHOW ENGINE INNODB STATUS while the problem is occurring, you should be able to see the locks on the stalled transactions there, even if they aren't showing up as the latest deadlock.

sehe
  • 374,641
  • 47
  • 450
  • 633
Danack
  • 24,939
  • 16
  • 90
  • 122
  • Because I can often get repeated lock waits each after 50 seconds time out, I should be able to get a copy when it occurs. But for example I have had none today - so will monitor closely. The main difference when compared with xaprb is that there is no record of any other data updates (i.e. based on insert and update time stamps) so this transaction with the lock wait is the only transaction updating the table. And if any updates are getting done it is always using the Primary key (i.e. they are single row updates). So the only other possible actions on the table would be queries.Thanks again –  Feb 21 '13 at 18:48
  • @sehe Your edit makes it impossible to read all of the text without horizontal scrolling. Is that what you intended? – Danack Jan 29 '17 at 12:02
  • @Danack not directly. I edited because the previous state of affairs did make it impossible to discern the "stanzas" in the log. How the original line breaks got lost is a mystery to me. If you don't mind I could try to replace it with something similar but less corrupted. – sehe Jan 29 '17 at 20:20
  • Go for it. I'm used to parsing raw sql logs in teeny-tiny ssh windows, but I can see how other people could find that annoying. – Danack Jan 30 '17 at 11:07