Transaction Lock Timeouts When Updating a Row

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: St

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

• Trouble deciphering a deadlock in an innodb status log (June 6, 2011)

• Will these two queries result in a deadlock if executed in sequence? (June 8, 2011)

• Reasons for occasionally slow queries? (June 14, 2011)

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 STATU

StackExchange Database Administrators Q#17561, answer score: 2