How do you read MySQL InnoDB Monitor output?

Question

I am new to DB Administration. I am trying to figure out the cause of deadlock exceptions, but I am unable to make sense of the logs.

The log says that "transaction 1 is rolled back". Why is this the case? The wager table has a foreign key relationship to the account table but is it "normal" for it (the trans running the insert) to not be able to obtain an S lock and therefore die as a result of a deadlock? I mean that seems pretty bad considering it is just a read to verify referential integrity.

And the second transaction is also writing to a wager table but there are no updates. So is the "mechanism" for creating auto-inc keys, or indexing mechanism or both that are causing a deadlock? Why would they not happen in serial fashion? Or may be they are but the wait period of some sort is too short.

Any help, pointers, further reading on how to use the log below to solve a deadlock problem appreciated.

111031 17:39:26
*** (1) TRANSACTION:
TRANSACTION 0 984899905, ACTIVE 180 sec, process no 10882, OS thread id 1104619856 inserting
mysql tables in use 1, locked 1
LOCK WAIT 13 lock struct(s), heap size 3024, undo log entries 86
MySQL thread id 122, query id 28932942 localhost 127.0.0.1 bt update

INSERT INTO wager (amount_won, confirmation, created_by_partner, creation_date, description, fantasy_league, 
     first_game_start, image_thumb, image_wide, kind, last_game_start, last_update_version, locked, name, 
     num_future, num_past, num_present, partner, partner_wager_id, percent, progressive_num, result, status, 
     sub_kind, teaser_type, user_account, wager_amount, win_amount) 
 VALUES (null, 2, 1, '2011-10-31 17:39:26', 'Straight Bet', null, null, 'http://iphonebet_s.png', 
     'http://iphonebet_l.png', 9, null, 0, 1, 'NFL: KC +4, -140', 0, 0, 0, 26, '39812820-1', 
     null, null, 1, 1, null, null, 2176, '7000', '5000')

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 2712 n bits 264 index `PRIMARY` of table `bt/user_account` trx id 0 984899905 lock mode S locks rec but not gap waiting
Record lock, heap no 126 


*** (2) TRANSACTION:
TRANSACTION 0 984900638, ACTIVE 61 sec, process no 10882, OS thread id 1076607312 setting auto-inc lock
mysql tables in use 1, locked 1
38 lock struct(s), heap size 6752, undo log entries 147
MySQL thread id 121, query id 28932947 localhost 127.0.0.1 bt update
INSERT INTO wager (amount_won, confirmation, created_by_partner, creation_date, description, fantasy_league, 
     first_game_start, image_thumb, image_wide, kind, last_game_start, last_update_version, locked, name, 
     num_future, num_past, num_present, partner, partner_wager_id, percent, progressive_num, result, status, 
     sub_kind, teaser_type, user_account, wager_amount, win_amount) 
 VALUES (null, 2, 1, '2011-10-31 17:39:26', 'Straight Bet', null, null, 'http://iphonebet_s.png', 
     'http://iphonebet_l.png', 9, null, 0, 1, 'NFL: SD/KC o +7.5', 0, 0, 0, 26, '39812916-1', 
     null, null, 1, 1, null, null, 2045, '260', '200')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 2712 n bits 264 index `PRIMARY` of table `bt/user_account` trx id 0 984900638 lock_mode X locks rec but not gap
Record lock, heap no 72 
Record lock, heap no 107 
Record lock, heap no 126 
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `bt/wager` trx id 0 984900638 lock mode AUTO-INC waiting
*** WE ROLL BACK TRANSACTION (1)

score 2 · Answer 1 · edited Apr 13 '17 at 12:42

Please look at this phrase from your question

*** (1) WAITING FOR THIS LOCK TO BE GRANTED: 
RECORD LOCKS space id 0 page no 2712 n bits 264 index `PRIMARY` of table `bt/user_account` trx id 0 984899905 lock mode S locks rec but not gap waiting 
Record lock, heap no 126

It says index PRIMARY has a shared lock (lock mode S) in Transaction 1

Now, check out this phrase from your question

*** (2) HOLDS THE LOCK(S):     
RECORD LOCKS space id 0 page no 2712 n bits 264 index `PRIMARY` of table `bt/user_account` trx id 0 984900638 lock_mode X locks rec but not gap     
Record lock, heap no 72       
Record lock, heap no 107       
Record lock, heap no 126

It says index PRIMARY has an exclusive lock (lock mode X) in Transaction 2. Three locks of this type are being held.

I have answered questions like this in the past, even as recent as 4 days ago

Trouble deciphering a deadlock in an innodb status log (Jun 6, 2011)
Will these two queries result in a deadlock if executed in sequence? (Jun 8, 2011)
Reasons for occasionally slow queries? (Jun 14, 2011)
Are InnoDB Deadlocks exclusive to INSERT/UPDATE/DELETE? (Aug 8, 2011)
Concurrently update with limit mysql (Oct 28, 2011)

Here is the bottom line: The PRIMARY KEY, contained in the clustered index (internally called gen_clust_index), can experience intermittent locks when bulk inserting or performing multiple single INSERTs in a transaction. The application should be designed to perform a manual COMMIT after each INSERT. If this is not permissible due to the nature of the application, redesign the app to bulk insert into temp tables before populating the wager table.

As a sidenote, the reason these things do not run in serial fashion is due to the default transaction isolation as well as your app's design when it comes to INSERTs.

Here are the four(4) possible modes:

There are probably deeper explanations that the things I have already stated. If there is anyone out there with any further explanation or information I've missed, please chime in.

How do you read MySQL InnoDB Monitor output?

1 Answers1