Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

I'm trying to determine the cause of an InnoDB transaction lock timeout. This one is very strange in that it appears to be a deadlock error instead - nonetheless, here's the output of my slow log when the issue occurred:

# Time: 120502 10:21:20
# User@Host: StudioN_rw[StudioN_rw] @  [xxx]
# Query_time: 201.089701  Lock_time: 0.000094 Rows_sent: 0  Rows_examined: 0
SET timestamp=1335954080;
UPDATE `user_project` SET `uuid` = '937be287-c6c7-44d0-971e-850cd926bd58', `uuid_short` = '9850cd926bd58', `owner_id` = 45993, `submitted_by_id` = 33029, `partner_id` = 64, `partner_account_id` = 63, `region_id` = 887, `region2_id` = NULL, `partner_ref` = '5037', `partner_ref2` = '6064', `status` = 'IP', `reason_id` = 259, `date_reason` = '2012-03-01 20:50:35', `type` = 'Edit', `LOB` = 'B', `phone` = '913-592-2020', `title` = 'Whitesell Bill L OD', `instructions` = '', `editor_id` = 16803, `media_expected` = 0, `return_address_id` = NULL, `parent_project` = 0, `related_project` = 0, `related_movie` = 0, `related_action` = NULL, `num_assets` = 5, `num_video` = 2, `num_image` = 3, `num_audio` = 0, `local_thumb` = 0, `http_referrer` = NULL, `http_client` = '66.35.40.135', `http_browser` = 'Java/1.6.0_20', `http_flash` = NULL, `session_key` = NULL, `referring_user_id` = NULL, `date_created` = '2012-03-01 12:11:40', `date_modified` = '2012-05-02 10:17:59', `date_due` = '2012-05-02
  15:30:00', `date_posted` = '2012-04-19 22:45:34', `date_started` = '2012-04-20 02:08:27', `date_shoot` = '2012-04-30 09:00:00', `date_first_cut` = NULL, `date_completed` = '2012-05-02 06:50:30', `date_reviewed` = NULL, `date_approved` = NULL, `date_due_delivery` = '2012-06-01 00:00:00', `date_last_message` = NULL, `date_followup` = NULL, `date_closed` = NULL, `date_delivered` = NULL, `hours_worked` = 0, `price` = 340, `partner_product_code_id` = NULL, `package_id` = 400, `package_code_orig` = 'DEXCSTVID', `package_price_orig` = 340, `editor_level` = 1 WHERE `user_project`.`id` = 40827;
# User@Host: StudioN_rw[StudioN_rw] @  [xxx]
# Query_time: 201.046430  Lock_time: 0.000087 Rows_sent: 0  Rows_examined: 0
SET timestamp=1335954080;
UPDATE `user_project` SET `uuid` = '937be287-c6c7-44d0-971e-850cd926bd58', `uuid_short` = '9850cd926bd58', `owner_id` = 45993, `submitted_by_id` = 33029, `partner_id` = 64, `partner_account_id` = 63, `region_id` = 887, `region2_id` = NULL, `partner_ref` = '5037', `partner_ref2` = '6064', `status` = 'IP', `reason_id` = 259, `date_reason` = '2012-03-01 20:50:35', `type` = 'Edit', `LOB` = 'B', `phone` = '913-592-2020', `title` = 'Whitesell Bill L OD', `instructions` = '', `editor_id` = 16803, `media_expected` = 0, `return_address_id` = NULL, `parent_project` = 0, `related_project` = 0, `related_movie` = 0, `related_action` = NULL, `num_assets` = 5, `num_video` = 2, `num_image` = 3, `num_audio` = 0, `local_thumb` = 0, `http_referrer` = NULL, `http_client` = '66.35.40.135', `http_browser` = 'Java/1.6.0_20', `http_flash` = NULL, `session_key` = NULL, `referring_user_id` = NULL, `date_created` = '2012-03-01 12:11:40', `date_modified` = '2012-05-02 10:17:59', `date_due` = '2012-05-02
  15:30:00', `date_posted` = '2012-04-19 22:45:34', `date_started` = '2012-04-20 02:08:27', `date_shoot` = '2012-04-30 09:00:00', `date_first_cut` = NULL, `date_completed` = '2012-05-02 06:50:30', `date_reviewed` = NULL, `date_approved` = NULL, `date_due_delivery` = '2012-06-01 00:00:00', `date_last_message` = NULL, `date_followup` = NULL, `date_closed` = NULL, `date_delivered` = NULL, `hours_worked` = 0, `price` = 340, `partner_product_code_id` = NULL, `package_id` = 400, `package_code_orig` = 'DEXCSTVID', `package_price_orig` = 340, `editor_level` = 1 WHERE `user_project`.`id` = 40827;

Both of these queries failed and were reported back to the application as a transaction lock timeout. While I realize there is some application logic that is busted here (i.e. the application is attempting to save the same record twice at exactly the same time), I still don't understand why a transaction lock timeout occurred (or rather was reported back up to the application).

Notice that the timestamp is exactly the same in the log and that there is no "Time" header for the second query. My innodb_lock_wait_timeout is set to 200, which corresponds to the Query_time in the log.

Is it possible that these updates were attempting to happen at the same exact time on the same exact row and locked each other out?

Here's the create table for this particular table:

Create Table: CREATE TABLE `user_project` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `uuid` varchar(36) NOT NULL,
  `uuid_short` varchar(15) NOT NULL,
  `owner_id` int(11) NOT NULL,
  `submitted_by_id` int(11) DEFAULT NULL,
  `status` varchar(10) NOT NULL,
  `reason_id` int(11) DEFAULT NULL,
  `date_reason` datetime DEFAULT NULL,
  `type` varchar(6) DEFAULT NULL,
  `LOB` varchar(6) DEFAULT NULL,
  `phone` varchar(100) DEFAULT NULL,
  `title` varchar(100) DEFAULT NULL,
  `instructions` longtext,
  `editor_id` int(11) DEFAULT NULL,
  `media_expected` int(11) DEFAULT NULL,
  `return_address_id` int(11) DEFAULT NULL,
  `parent_project` int(11) DEFAULT NULL,
  `related_project` int(11) DEFAULT NULL,
  `related_movie` int(11) DEFAULT NULL,
  `related_action` varchar(10) DEFAULT NULL,
  `num_assets` int(11) DEFAULT NULL,
  `num_video` int(11) DEFAULT NULL,
  `num_image` int(11) DEFAULT NULL,
  `num_audio` int(11) DEFAULT NULL,
  `http_referrer` varchar(300) DEFAULT NULL,
  `http_client` char(15) DEFAULT NULL,
  `http_browser` varchar(300) DEFAULT NULL,
  `http_flash` varchar(20) DEFAULT NULL,
  `session_key` varchar(40) DEFAULT NULL,
  `referring_user_id` int(11) DEFAULT NULL,
  `date_created` datetime DEFAULT NULL,
  `date_modified` datetime DEFAULT NULL,
  `date_due` datetime DEFAULT NULL,
  `date_started` datetime DEFAULT NULL,
  `date_shoot` datetime DEFAULT NULL,
  `date_first_cut` datetime DEFAULT NULL,
  `date_completed` datetime DEFAULT NULL,
  `date_reviewed` datetime DEFAULT NULL,
  `date_approved` datetime DEFAULT NULL,
  `date_due_delivery` datetime DEFAULT NULL,
  `date_last_message` datetime DEFAULT NULL,
  `date_followup` datetime DEFAULT NULL,
  `date_closed` datetime DEFAULT NULL,
  `date_delivered` datetime DEFAULT NULL,
  `hours_worked` double NOT NULL,
  `price` double DEFAULT NULL,
  `local_thumb` tinyint(1) NOT NULL DEFAULT '0',
  `package_id` int(11) DEFAULT NULL,
  `package_code_orig` varchar(50) DEFAULT NULL,
  `package_price_orig` double DEFAULT NULL,
  `editor_level` int(11) NOT NULL DEFAULT '0',
  `date_posted` datetime DEFAULT NULL,
  `partner_id` int(11) DEFAULT '0',
  `partner_account_id` int(11) NOT NULL DEFAULT '-1',
  `region_id` int(11) DEFAULT NULL,
  `region2_id` int(11) DEFAULT NULL,
  `partner_ref` varchar(100) DEFAULT NULL,
  `partner_ref2` varchar(100) DEFAULT NULL,
  `partner_product_code_id` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `uuid` (`uuid`),
  UNIQUE KEY `user_project_uuid` (`uuid`),
  UNIQUE KEY `uuid_short` (`uuid_short`),
  KEY `user_project_owner_id` (`owner_id`),
  KEY `user_project_status` (`status`),
  KEY `user_project_type` (`type`),
  KEY `user_project_LOB` (`LOB`),
  KEY `user_project_editor_id` (`editor_id`),
  KEY `user_project_return_address_id` (`return_address_id`),
  KEY `user_project_referring_user_id` (`referring_user_id`),
  KEY `user_project_parent_project` (`parent_project`),
  KEY `user_project_editor_level` (`editor_level`),
  KEY `user_project_package_id` (`package_id`),
  KEY `user_project_date_created` (`date_created`),
  KEY `user_project_date_closed` (`date_closed`),
  KEY `region_id_refs_id_4c0e6069` (`region_id`),
  KEY `user_project_submitted_by_id` (`submitted_by_id`),
  KEY `partner_product_code_id_refs_id_47922511` (`partner_product_code_id`),
  KEY `user_project_partner_account_id` (`partner_account_id`),
  KEY `user_project_reason_id` (`reason_id`)
) ENGINE=InnoDB AUTO_INCREMENT=46045 DEFAULT CHARSET=utf8
share|improve this question
    
I assume that you have an index on the field user_project.id? As without the index, it could be that the queries when combined are just taking too long to read through the data and make the update, ending with both of them timing out. How long does the query take when you run it by hand? And does it complete successfully? –  Dave Rix May 8 '12 at 13:25
    
Yes, there is an index on that column. I also just included the create table information for this question as well. This statement normally executes almost instantly. I truly believe it was waiting for a lock either on the row, page or table. But could there have been a possibility that either replication locked it somehow or maybe an index was corrupted? This has been almost a week ago now when it happened and it happened at 5:00 AM in the morning when the system was barely even being used. The only thing I can come up with was a job doing a select that overlapped this job run. –  Freddie May 9 '12 at 14:46

1 Answer 1

Whenever these deadlocks occur, you need to use SHOW ENGINE INNODB STATUS\G

This will give you a more granular look at the locks imposed. It is best to run this during this deadlock situation.

I remember about a year ago helping someone troubleshoot a similar deadlock situation

Not to be overlooked is the fact that InnoDB deadlocks can be caused by SELECT statements under specific circumstances : Are InnoDB Deadlocks exclusive to INSERT/UPDATE/DELETE? (August 8, 2011)

Getting back to your question

Is it possible that these updates were attempting to happen at the same exact time on the same exact row and locked each other out?

The answer is Yes. Why?

Look back at the slow log output

# Time: 120502 10:21:20
# User@Host: StudioN_rw[StudioN_rw] @  [xxx]
# Query_time: 201.089701  Lock_time: 0.000094 Rows_sent: 0  Rows_examined: 0
SET timestamp=1335954080;
UPDATE `user_project` SET `uuid` = '937be287-c6c7-44d0-971e-850cd926bd58', `uuid_short` = '9850cd926bd58', `owner_id` = 45993, `submitted_by_id` = 33029, `partner_id` = 64, `partner_account_id` = 63, `region_id` = 887, `region2_id` = NULL, `partner_ref` = '5037', `partner_ref2` = '6064', `status` = 'IP', `reason_id` = 259, `date_reason` = '2012-03-01 20:50:35', `type` = 'Edit', `LOB` = 'B', `phone` = '913-592-2020', `title` = 'Whitesell Bill L OD', `instructions` = '', `editor_id` = 16803, `media_expected` = 0, `return_address_id` = NULL, `parent_project` = 0, `related_project` = 0, `related_movie` = 0, `related_action` = NULL, `num_assets` = 5, `num_video` = 2, `num_image` = 3, `num_audio` = 0, `local_thumb` = 0, `http_referrer` = NULL, `http_client` = '66.35.40.135', `http_browser` = 'Java/1.6.0_20', `http_flash` = NULL, `session_key` = NULL, `referring_user_id` = NULL, `date_created` = '2012-03-01 12:11:40', `date_modified` = '2012-05-02 10:17:59', `date_due` = '2012-05-02
  15:30:00', `date_posted` = '2012-04-19 22:45:34', `date_started` = '2012-04-20 02:08:27', `date_shoot` = '2012-04-30 09:00:00', `date_first_cut` = NULL, `date_completed` = '2012-05-02 06:50:30', `date_reviewed` = NULL, `date_approved` = NULL, `date_due_delivery` = '2012-06-01 00:00:00', `date_last_message` = NULL, `date_followup` = NULL, `date_closed` = NULL, `date_delivered` = NULL, `hours_worked` = 0, `price` = 340, `partner_product_code_id` = NULL, `package_id` = 400, `package_code_orig` = 'DEXCSTVID', `package_price_orig` = 340, `editor_level` = 1 WHERE `user_project`.`id` = 40827;
# User@Host: StudioN_rw[StudioN_rw] @  [xxx]
# Query_time: 201.046430  Lock_time: 0.000087 Rows_sent: 0  Rows_examined: 0
SET timestamp=1335954080;
UPDATE `user_project` SET `uuid` = '937be287-c6c7-44d0-971e-850cd926bd58', `uuid_short` = '9850cd926bd58', `owner_id` = 45993, `submitted_by_id` = 33029, `partner_id` = 64, `partner_account_id` = 63, `region_id` = 887, `region2_id` = NULL, `partner_ref` = '5037', `partner_ref2` = '6064', `status` = 'IP', `reason_id` = 259, `date_reason` = '2012-03-01 20:50:35', `type` = 'Edit', `LOB` = 'B', `phone` = '913-592-2020', `title` = 'Whitesell Bill L OD', `instructions` = '', `editor_id` = 16803, `media_expected` = 0, `return_address_id` = NULL, `parent_project` = 0, `related_project` = 0, `related_movie` = 0, `related_action` = NULL, `num_assets` = 5, `num_video` = 2, `num_image` = 3, `num_audio` = 0, `local_thumb` = 0, `http_referrer` = NULL, `http_client` = '66.35.40.135', `http_browser` = 'Java/1.6.0_20', `http_flash` = NULL, `session_key` = NULL, `referring_user_id` = NULL, `date_created` = '2012-03-01 12:11:40', `date_modified` = '2012-05-02 10:17:59', `date_due` = '2012-05-02
  15:30:00', `date_posted` = '2012-04-19 22:45:34', `date_started` = '2012-04-20 02:08:27', `date_shoot` = '2012-04-30 09:00:00', `date_first_cut` = NULL, `date_completed` = '2012-05-02 06:50:30', `date_reviewed` = NULL, `date_approved` = NULL, `date_due_delivery` = '2012-06-01 00:00:00', `date_last_message` = NULL, `date_followup` = NULL, `date_closed` = NULL, `date_delivered` = NULL, `hours_worked` = 0, `price` = 340, `partner_product_code_id` = NULL, `package_id` = 400, `package_code_orig` = 'DEXCSTVID', `package_price_orig` = 340, `editor_level` = 1 WHERE `user_project`.`id` = 40827;

The same query launched twice. What do you see ???

  • The first query was locked 0.000007 seconds longer that then second query
  • The first query's total query time was 0.043271 seconds longer that then second query

In light of this, the first query got executed first. Under the hood, gen_clust_index (the Clustered Index) of the user_project table would have an exclusive lock issue issued on the row. The second query would attempt the same type of lock. While this is only speculation on my part this would have been quite visible had you run SHOW INNODB ENGINE STATUS\G during the deadlock. (See How can I find who holds the lock based on the hex-dumped? )

In the meantime, what would each query be doing? Setting up MVCC info inside ibdata1. Simply put, all the columns you are replacing in the UPDATE would be copied into the Undo Logs and Rollback Segments within ibdata1. Both queries had to do this within milliseconds and attempt to commandeer the row and its clustered index entry.

The fact both queries waited over 200 seconds (since you mentioned your innodb_lock_wait_timeout is set to 200) show that this sequence of events did occur and that whoever timed out first would release its claim to doing the exclusive lock on the row and its clustered index entry.

Given this scenario, the first query would have launched second and the second query first. Evidently, the transaction (the single UPDATE of the second query) must have restarted itself and retried the UPDATE. By the time of that cycle, the first query would have completed the UPDATE and released its MVCC info in ibdata1 as well as its hold on row and its clustered index entry.

I hope this clarifies why this was possible.

share|improve this answer
    
Thanks so much for the time spent answering this question. Any way to automatically get the INNODB STATUS when they occur? –  Freddie May 28 '12 at 21:25

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.