HiveBrain v1.2.0
Get Started
← Back to all entries
patternsqlMinor

Trouble deciphering a deadlock in an innodb status log

Submitted by: @import:stackexchange-dba··
0
Viewed 0 times
logdeadlockinnodbdecipheringstatustrouble

Problem

We are accessing MySQL from the Microsoft ADO.NET connector.

Occasionally we are seeing the following deadlock in our innodb status and haven't been able to identify the cause of the problem. It looks like transaction (2) is waiting for and holding the same lock?

``
------------------------
LATEST DETECTED DEADLOCK
------------------------
110606 5:35:09
*** (1) TRANSACTION:
TRANSACTION 0 45321452, ACTIVE 0 sec, OS thread id 3804 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 84, query id 3265713 localhost 127.0.0.1 famdev Updating
UPDATE people SET company_id = 1610, name = '', password = '', temp_password = NULL, reset_password_hash = NULL, email = '@yahoo.com', phone = NULL, mobile = '', iphone_device_id = 'android:-', iphone_device_time = '2011-06-06 05:35:09', last_checkin = '2011-06-06 05:24:42', location_lat = , location_long = -, gps_strength = 3296, picture_blob_id = 1190, authority = 1, active = 1, date_created = '2011-04-13 20:21:20', last_login = '2011-06-06 05:35:09', panic_mode = 0, battery_level = NULL, battery_state = NULL WHERE people_id = 3125
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 11144 n bits 152 index
PRIMARY of table family.people` trx id 0 45321452 lock_mode X locks rec but not gap waiting
Record lock, heap no 12 PHYSICAL RECORD: n_fields 25; compact format; info bits 0
0: len 8; hex 8000000000000c35; asc 5;; 1: len 6; hex 000002b38ce6; asc ;; 2: len 7; hex 00000002801f89; asc ;; 3: len 8; hex 800000000000064a; asc J;; 4: len 4; hex ; asc ;; 5: len 30; hex ; asc ;...(truncated); 6: SQL NULL; 7: SQL NULL; 8: len 16; hex ; asc @yahoo.com;; 9: SQL NULL; 10: len 10; hex ; asc ;; 11: len 30; hex ; asc android:;...(truncated); 12: len 8; hex ; asc J] Z;; 13: len 8; hex ; asc J] Z;; 14: len 8; hex a39410acaa9b4340; asc C@;; 15: len 8; hex ; asc m S ;; 16: len

Solution

Here is what I am seeing

I see three queries, all almost identical.

UPDATE people SET company_id = 1610, name = '', password = '',
temp_password = NULL, reset_password_hash = NULL, email = '@yahoo.com',
phone = NULL, mobile = '', iphone_device_id = 'android:-',
iphone_device_time = '2011-06-06 05:35:09', last_checkin = '2011-06-06 05:24:42',
location_lat = , location_long = -, gps_strength = 3296,
picture_blob_id = 1190,authority = 1, active = 1,
date_created = '2011-04-13 20:21:20',
last_login = '2011-06-06 05:35:09', panic_mode = 0, battery_level = NULL,
battery_state = NULL WHERE people_id = 3125;


The differences

TRANSACTION 1

iphone_device_time = '2011-06-06 05:24:42', last_checkin = '2011-06-06 05:35:07'

TRANSACTION 2

iphone_device_time = '2011-06-06 05:35:09', last_checkin = '2011-06-06 05:24:42'

Please notice that the column values are flipped. Normally, a deadlock occurs when two different transactions are accessing two locks from two tables with TX1 (Transaction 1) getting row A and then row B while TX2 is getting row B and then row A. In this case, it is TX1 and TX2 are accessing the same row but changing two different columns (iphone_device_time,last_checkin).

The values do not make any sense. At 5:24:42, your last checkin was 5:35:07. Ten minutes and 27 seconds later (5:35:07 - 05:24:42), the column values are reversed.

The big question is: Why is TX1 held up for almost 11 min ???

This is not really an answer. This is just bandwidth and throughout from me. I hope these observations help.

UPDATE 2011-06-06 09:57

Please check out this link concerning innodb_locks_unsafe_for_binlog : The reason I suggest reading this is something else I saw in your INNODB STATUS display. The phrase lock_mode X (exclusive lock) and lock_mode S (shared lock) indicates both locks being imposed (or attempting to impose) on the same row . There may be some internal serialization going on doing next row locking. The default is OFF. After reading this, you may need to consider enabling it.

UPDATE 2011-06-06 10:03

Another reason to examine this line of thought is the fact that all the transactions are traversing the PRIMARY key. Since the PRIMARY is a clustered index in InnoDB, the PRIMARY key and the row itself are together. Thus, traversing a row and and the PRIMARY KEY are one and the same. Therefore, any index lock on the PRIMARY KEY is a row level lock as well.

UPDATE 2011-06-06 19:21

Check what auocommit value you have. If autocommit is off, I can see two(2) possible problems

  • updating the same row twice in the same transaction



  • updating the same row in two different transactions



In fact, the SHOW ENGINE INNODB STATUS you show in the question has exactly both scenarios.

Code Snippets

UPDATE people SET company_id = 1610, name = '<name>', password = '<hash>',
temp_password = NULL, reset_password_hash = NULL, email = '<redacted>@yahoo.com',
phone = NULL, mobile = '<phone>', iphone_device_id = 'android:<id>-<id>',
iphone_device_time = '2011-06-06 05:35:09', last_checkin = '2011-06-06 05:24:42',
location_lat = <lat>, location_long = -<lng>, gps_strength = 3296,
picture_blob_id = 1190,authority = 1, active = 1,
date_created = '2011-04-13 20:21:20',
last_login = '2011-06-06 05:35:09', panic_mode = 0, battery_level = NULL,
battery_state = NULL WHERE people_id = 3125;

Context

StackExchange Database Administrators Q#3179, answer score: 6

Revisions (0)

No revisions yet.