[mysql] Deadlock in InnoDB interpreteren

[-FoX-]

In zeldzame gevallen valt het wel eens voor dat er een deadlock optreedt in onze web applicatie. Op basis van volgend commando vraag ik de status aan de InnoDB engine op om de reden van deze deadlock te kunnen achterhalen:

SQL:

SHOW ENGINE INNODB STATUS;

Waarbij MySQL mij een zeer gedetailleerd overzicht geeft van de huidige status en de laatste deadlock die gedetecteerd werd. Ik vind het echter niet zo evident om dit correct te interpreteren, en misschien kan iemand me hier wel wat mee helpen?

code:

=====================================
110825 12:24:03 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 33 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 7704, signal count 7694
Mutex spin waits 0, rounds 92815, OS waits 1571
RW-shared spins 10158, OS waits 5075; RW-excl spins 523, OS waits 497
------------------------
LATEST DETECTED DEADLOCK
------------------------
110825 11:40:44
*** (1) TRANSACTION:
TRANSACTION 0 5656138, ACTIVE 0 sec, process no 741, OS thread id 140274376251136 inserting
mysql tables in use 1, locked 1
LOCK WAIT 13 lock struct(s), heap size 3024, 20 row lock(s), undo log entries 16
MySQL thread id 525000, query id 3093370 localhost cooldb update
INSERT INTO `snapshot` (`c_id`, `timestamp`, `timestamp`, `size`, `content`, `fluid`, `leakage`, `installation_id`, `circuit_id`, `parent_id`, `action_id`) VALUES (47, '2011-08-17 12:30:00', '2011-08-25 11:40:44', 22000, 0, 'AB123', 0, 1484, NULL, NULL, 5298)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 990 n bits 256 index `PRIMARY` of table `cooldb`.`action` trx id 0 5656138 lock mode S locks rec but not gap waiting
Record lock, heap no 190 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
 0: len 4; hex 800014b2; asc     ;; 1: len 6; hex 000000564e43; asc    VNC;; 2: len 7; hex 00000004c92fa4; asc      / ;; 3: len 4; hex 800000e3; asc     ;; 4: len 4; hex 800000e3; asc     ;; 5: len 8; hex 8000124a6a9649b8; asc    Jj I ;; 6: len 8; hex 8000124a6a9649bc; asc    Jj I ;; 7: len 4; hex 8000002f; asc    /;; 8: len 4; hex 00000001; asc     ;; 9: len 4; hex 80001337; asc    7;; 10: len 4; hex 800005cc; asc     ;; 11: SQL NULL; 12: len 11; hex 4c65616b61676554657374; asc LTest;;

*** (2) TRANSACTION:
TRANSACTION 0 5656131, ACTIVE 1 sec, process no 741, OS thread id 140274376652544 starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
10 lock struct(s), heap size 1216, 5 row lock(s), undo log entries 4
MySQL thread id 524996, query id 3093372 localhost cooldb Updating
UPDATE `installations` SET `creator_id` = 83, `modifier_id` = 83, `created_date` = '2011-03-07 09:46:03', `modified_date` = '2011-08-25 11:40:44', `c_id` = 47, `location_id` = 744, `reference` = 'Koeling', `reference_customer` = '', `machine_type` = '', `installation_type` = 0, `priority` = NULL, `delivery_date` = NULL, `mobile` = 0, `closed` = 0, `leakage_control_system` = '', `notes` = '', `content` = 22000, `fluid` = 'AB123', `token` = 'a33dc9', `serial_nr` = '', `power` = NULL, `inactivation_date` = NULL, `last_control` = '2011-08-17', `include_fc` = 1, `reason_fc` = '', `system_calculating` = '2011-08-25 11:40:40', `nr_attempts_to_calculate` = 0 WHERE `installations`.`id` = 1484
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 990 n bits 256 index `PRIMARY` of table `cooldb`.`action` trx id 0 5656131 lock_mode X locks rec but not gap
Record lock, heap no 190 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
 0: len 4; hex 800014b2; asc     ;; 1: len 6; hex 000000564e43; asc    VNC;; 2: len 7; hex 00000004c92fa4; asc      / ;; 3: len 4; hex 800000e3; asc     ;; 4: len 4; hex 800000e3; asc     ;; 5: len 8; hex 8000124a6a9649b8; asc    Jj I ;; 6: len 8; hex 8000124a6a9649bc; asc    Jj I ;; 7: len 4; hex 8000002f; asc    /;; 8: len 4; hex 00000001; asc     ;; 9: len 4; hex 80001337; asc    7;; 10: len 4; hex 800005cc; asc     ;; 11: SQL NULL; 12: len 11; hex 4c65616b61676554657374; asc LTest;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 377 n bits 160 index `PRIMARY` of table `cooldb`.`installations` trx id 0 5656131 lock_mode X locks rec but not gap waiting
Record lock, heap no 87 PHYSICAL RECORD: n_fields 30; compact format; info bits 0
 0: len 4; hex 800005cc; asc     ;; 1: len 6; hex 000000564e48; asc    VNH;; 2: len 7; hex 00000004c10110; asc        ;; 3: len 4; hex 80000053; asc    S;; 4: len 4; hex 80000053; asc    S;; 5: len 8; hex 8000124a4bb5f04b; asc    JK  K;; 6: len 8; hex 8000124a6a9649bc; asc    Jj I ;; 7: len 4; hex 8000002f; asc    /;; 8: len 4; hex 800002e8; asc     ;; 9: len 14; hex 4b6f656c696e6720526f76656d61; asc Koeling Rovema;; 10: len 0; hex ; asc ;; 11: len 4; hex 00000000; asc     ;; 12: SQL NULL; 13: len 0; hex ; asc ;; 14: SQL NULL; 15: len 1; hex 80; asc  ;; 16: len 0; hex ; asc ;; 17: len 1; hex 80; asc  ;; 18: len 4; hex 000055f0; asc   U ;; 19: len 4; hex 52353037; asc AB123;; 20: len 6; hex 613338646339; asc a38dc9;; 21: len 0; hex ; asc ;; 22: SQL NULL; 23: SQL NULL; 24: len 3; hex 8fb711; asc    ;; 25: len 8; hex 8000124a6a9649bb; asc    Jj I ;; 26: len 4; hex 00000001; asc     ;; 27: len 0; hex ; asc ;; 28: len 1; hex 81; asc  ;; 29: len 0; hex ; asc ;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 0 5657410
Purge done for trx's n:o < 0 5656813 undo n:o < 0 0
History list length 5
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 741, OS thread id 140274376050432
MySQL thread id 526177, query id 3100904 localhost root
SHOW ENGINE INNODB STATUS
---TRANSACTION 0 5657409, ACTIVE 1 sec, process no 741, OS thread id 140274376652544
MySQL thread id 526180, query id 3100903 localhost cooldb
Trx read view will not see trx with id >= 0 5657410, sees < 0 5657410
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
20481 OS file reads, 77053 OS file writes, 38656 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
380 inserts, 380 merged recs, 368 merges
Hash table size 17393, node heap has 27 buffer(s)
0.42 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 246665274
Log flushed up to   0 246665274
Last checkpoint at  0 246665274
0 pending log writes, 0 pending chkp writes
25574 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 21740768; in additional pool allocated 1048064
Dictionary memory allocated 537040
Buffer pool size   512
Free buffers       0
Database pages     485
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 22318, created 88, written 52899
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
Main thread process no. 741, id 140274217907968, state: sleeping
Number of rows inserted 5970, updated 9077, deleted 2587, read 14404834
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.48 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Andere opmerkingen of feedback hierover is altijd welkom!

[-FoX-]

Geen MySQL guru's hiero?

[Remus]

Transaction 1 wil een lock op 'cooldb'.'action' welke in gebruik is door transaction 2. Transaction 2 wacht weer op een lock op 'cooldb'.'installations'.

Er staat echter niet bij welke thread de lock op 'cooldb'.'installations' heeft. Belangrijk is iig dat als je deze twee tabellen wijzigt in één transactie, dat je dat altijd in dezelfde volgorde doet.

[dusty]

Remus, Nee; Connectie 1 wilt een lock op een object die in gebruik is door connectie 2. en vice versa; Als hij transacties zou gebruiken zou dit juist niet moeten voor komen.

Als je aan het begin van je commando eerst een "begin;" stuurt en dan na het commando(s) een "commit;" dat zorgt ervoor dat de database er zelf voor dat de commando's allemaal samen worden uitgevoerd en zorgt de database er zelf voor dat er dus geen deadlock ontstaat.

code:

Begin;
Insert into SomeTable values ('blaat');
Commit;

Wees er wel bewust van dat de database dus niets uitvoert totdat hij een "Commit" commando krijgt.

[GlowMouse]

dusty schreef op zondag 28 augustus 2011 @ 17:03:
Als je aan het begin van je commando eerst een "begin;" stuurt en dan na het commando(s) een "commit;" dat zorgt ervoor dat de database er zelf voor dat de commando's allemaal samen worden uitgevoerd en zorgt de database er zelf voor dat er dus geen deadlock ontstaat.

Transacties voorkomen geen deadlocks, en wachten ook niet met uitvoeren tot je commit doet. Opvallend is dat

SQL:

INSERT INTO `snapshot` (`c_id`, `timestamp`, `timestamp`, `size`, `content`, `fluid`, `leakage`, `installation_id`, `circuit_id`, `parent_id`, `action_id`) VALUES (47, '2011-08-17 12:30:00', '2011-08-25 11:40:44', 22000, 0, 'AB123', 0, 1484, NULL, NULL, 5298)

wacht op table `cooldb`.`action`, terwijl die tabel niet in de query voorkomt. Ik verwacht dat het met een foreign key te maken heeft, waarop transactie 2 een lock heeft. Omgekeerd wil transactie 2 iets met de tabel installation, maar daar zal transactie 1 iets mee hebben (of een transactie 3 wellicht die weer op 1 wacht). Ideeën tegen deadlocks staan op http://dev.mysql.com/doc/refman/5.0/en/innodb-deadlocks.html

[dusty]

Okay blijkbaar voor MYSQL moet je ook de tables "handmatig" locken...

van de pagina die GlowMouse gaf:

•If nothing else helps, serialize your transactions with table-level locks. The correct way to use LOCK TABLES with transactional tables, such as InnoDB tables, is to begin a transaction with SET autocommit = 0 (not START TRANSACTION) followed by LOCK TABLES, and to not call UNLOCK TABLES until you commit the transaction explicitly. For example, if you need to write to table t1 and read from table t2, you can do this:

MySQL:

SET autocommit=0;
LOCK TABLES t1 WRITE, t2 READ, ...;
... do something with tables t1 and t2 here ...
COMMIT;
UNLOCK TABLES;

Table-level locks make your transactions queue nicely and avoid deadlocks.

[GlowMouse]

dusty schreef op zondag 28 augustus 2011 @ 17:35:
Okay blijkbaar voor MYSQL moet je ook de tables "handmatig" locken...

van de pagina die GlowMouse gaf:

[...]

Nee dat 'moet' niet, maar is slechts een oplossing als je geen slimmere oplossing kunt bedenken ('if nothing else helps'). En dit is niet specifiek voor MySQL maar voor elke db.

[Remus]

dusty schreef op zondag 28 augustus 2011 @ 17:03:
Remus, Nee; Connectie 1 wilt een lock op een object die in gebruik is door connectie 2. en vice versa; Als hij transacties zou gebruiken zou dit juist niet moeten voor komen.

Dat zie ik niet. Connection 1 heeft op dit moment helemaal geen locks, hij wacht op een lock die connection 2 heeft, terwijl connection 2 op een andere lock wacht (die iig niet in bezit is van connection 1!)

GlowMouse schreef op zondag 28 augustus 2011 @ 17:19:
[...]

Transacties voorkomen geen deadlocks, en wachten ook niet met uitvoeren tot je commit doet. Opvallend is dat

SQL:

INSERT INTO `snapshot` (`c_id`, `timestamp`, `timestamp`, `size`, `content`, `fluid`, `leakage`, `installation_id`, `circuit_id`, `parent_id`, `action_id`) VALUES (47, '2011-08-17 12:30:00', '2011-08-25 11:40:44', 22000, 0, 'AB123', 0, 1484, NULL, NULL, 5298)

wacht op table `cooldb`.`action`, terwijl die tabel niet in de query voorkomt. Ik verwacht dat het met een foreign key te maken heeft, waarop transactie 2 een lock heeft. Omgekeerd wil transactie 2 iets met de tabel installation, maar daar zal transactie 1 iets mee hebben (of een transactie 3 wellicht die weer op 1 wacht). Ideeën tegen deadlocks staan op http://dev.mysql.com/doc/refman/5.0/en/innodb-deadlocks.html

Er staat zo te zien een foreign key naar 'action' in (action_id), dus waarschijnlijk is die lock benodigd om de referential integrity to controleren en te garanderen.

[ Voor 52% gewijzigd door Remus op 29-08-2011 09:59 ]

[Infinitive]

Deze reactie is wellicht wat offtopic, maar ik wil de volgende reactie van nog wat meer content voorzien:

GlowMouse schreef op zondag 28 augustus 2011 @ 17:19:
[...]

Transacties voorkomen geen deadlocks, en wachten ook niet met uitvoeren tot je commit doet.

Om precizer te zijn: je kunt transacties op verschillende manieren implementeren, maar om te garanderen dat een commit (en het proces ernaartoe) altijd succesvol is zul je of veel performance moeten inleveren, of een flinke prijs in de isolatie van transacties moeten betalen. Daarom is het niet verwonderlijk dat je database systeem je niet deze garanties geeft.

Je kunt dan twee richtingen opgaan. De richting zoals bovenstaand al door anderen opgemerkt: zelf proberen deze garanties te realiseren door middel van kennis van de database en de queries die je er op af schiet en hoe je systeem er mee omgaat (lastig, kan wijzigen), in combinatie met extra locking (kan enorm effect op performance hebben) en evt. verlagen van isolatie level (potentieel gevaarlijk voor je data consistency). Merk op dat het verlagen van het isolatie-level naar read-uncommitted effectief betekend dat je het transactie-mechanisme alleen voor de mogelijkheid om rollbacks te doen gebruikt.

De andere richting is dat je je complete transactie opnieuw doet (rollback en retry) wanneer deze niet meer succesvol kan zijn (dit kan je bij de commit merken, maar mogelijk ook bij een eerdere query - daar ben ik me in geval van Innodb niet zeker van). Met herhalen bedoel ik dat je effectief een loop om je code zet totdat de transactie succesvol is. Zolang je systeem een zekere mate van 'fairness' en 'progress' aanbiedt (ook daarvan ben ik me in geval van Innodb niet zeker, maar dat zal doorgaans in de praktijk geen probleem zijn) dan krijg je de garantie dat je de transactie hooguit een eindig aantal keer hoeft te herhalen. Je kan bovendien na een aantal keer herhalen bij de gebruiker rapporteren dat het op het moment wel erg druk is. Het herhalen van een transactie is in sommige exotische gevallen misschien niet mogelijk.

In echt moeilijke gevallen (veel activiteit in de database) kan je een combinatie van beide gevallen implementeren. Queries die bijvoorbeeld statistieken berekenen kan je doorgaans best op een lager isolatienivo draaien omdat daar enige onnauwkeurigheid toelaatbaar is en je wilt bijvoorbeeld niet alle tabellen locken terwijl deze berekening draait.

En in de praktijk... hangt het nogal van de applicatie af. Inderdaad is het daarvoor nuttig om te weten waar deadlocks ontstaan (zoals de topic starter doet). Maar ik denk niet dat je deadlocks/conflicten volledig kan uitsluiten, dus zou ik wel voor een aanpak gaan waarin een dergelijke situatie enigermate vriendelijk wordt afgehandeld.