Mysql – Unexplained InnoDB timeouts

innodblocked-objectsMySQLquery

I've been seeing some very basic updates timing out lately and have not been able to determine the cause. An example:

//# Query_time: 51 Lock_time: 0 Rows_sent: 0 Rows_examined: 0

UPDATE photos SET position = position + 1 WHERE (photo_album_id = 40470);

The same log has no entries with a Lock_time > 0. Running show innodb status does not reveal any related locks either. This problem appears to be affecting at least 5 different tables based on my app server logs (which show a Mysql::Error: Lock wait timeout exceeded error related to each corresponding entry in the mysql-slow log).

Any idea on where to go from here? I'm hitting dead-ends in all directions. Thanks.

EDIT:

CREATE TABLE `photos` (
  `id` int(11) NOT NULL auto_increment,
  `type` varchar(255) NOT NULL,
  `photo_album_id` int(11) NOT NULL,
  `user_id` int(11) NOT NULL,
  `title` varchar(255) default 'Untitled',
  `description` text,
  `credit` varchar(255) default NULL,
  `photo_file_name` varchar(255) default NULL,
  `photo_content_type` varchar(255) default NULL,
  `photo_file_size` int(11) default NULL,
  `photo_updated_at` datetime default NULL,
  `position` int(11) default '0',
  `views` int(11) default '0',
  `folder` varchar(255) default NULL,
  `published` tinyint(1) default '0',
  `published_at` datetime default NULL,
  `created_at` datetime default NULL,
  `updated_at` datetime default NULL,
  `album_published` tinyint(1) default '0',
  `comment_count` int(11) default '0',
  `audio_file_name` varchar(255) default NULL,
  `audio_content_type` varchar(255) default NULL,
  `audio_file_size` int(11) default NULL,
  `audio_updated_at` datetime default NULL,
  `cover` tinyint(1) default '0',
  `slug` varchar(255) default NULL,
  `comments_count` int(11) default '0',
  `delete_from_s3` tinyint(1) default '0',
  `batch` int(11) default NULL,
  `audio` varchar(255) default NULL,
  PRIMARY KEY  (`id`),
  KEY `index_photos_on_album_published` (`album_published`),
  KEY `index_photos_on_batch` (`batch`),
  KEY `index_photos_on_comment_count` (`comment_count`),
  KEY `index_photos_on_created_at` (`created_at`),
  KEY `index_photos_on_delete_from_s3` (`delete_from_s3`),
  KEY `index_photos_on_photo_album_id` (`photo_album_id`),
  KEY `index_photos_on_published` (`published`),
  KEY `index_photos_on_published_at` (`published_at`),
  KEY `index_photos_on_type` (`type`),
  KEY `index_photos_on_user_id` (`user_id`)
) ENGINE=InnoDB AUTO_INCREMENT=42830 DEFAULT CHARSET=utf8

Best Answer

I know this is really late, but you really need to capture the output of SHOW ENGINE INNODB STATUS; during that query to see why it's waiting.

If it happens a lot during a specific time, it would be easy to just grab that output every x seconds and hope you capture it (or perhaps artificially generate the load).