3

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
Community
  • 1
Freddie
  • 131
  • 1
  • 4

1 Answers1

2

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.

Community
  • 1
RolandoMySQLDBA
  • 185,223
  • 33
  • 326
  • 536