Jak debugować Przekroczono limit czasu oczekiwania blokady na MySQL?

W moich dziennikach błędów produkcyjnych czasami widzę:

SQLSTATE [HY000]: Błąd ogólny: 1205 Przekroczono limit czasu oczekiwania na blokadę; spróbuj ponownie uruchomić transakcję

Wiem, które zapytanie próbuje uzyskać dostęp do bazy danych w tym momencie, ale czy istnieje sposób, aby dowiedzieć się, które zapytanie miało blokadę w tym właśnie momencie?

To, co to daje, to słowo transakcja . Wyraźnie widać w stwierdzeniu, że zapytanie próbowało zmienić co najmniej jeden wiersz w co najmniej jednej tabeli InnoDB.

Ponieważ znasz zapytanie, wszystkie tabele, do których masz dostęp, są kandydatami na winowajcę.

Stamtąd powinieneś być w stanie biec SHOW ENGINE INNODB STATUS\G

Powinieneś być w stanie zobaczyć tabele, których dotyczy problem

Otrzymujesz wszelkiego rodzaju dodatkowe informacje o blokowaniu i muteksie.

Oto próbka jednego z moich klientów:

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
110514 19:44:14 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 9014315, signal count 7805377
Mutex spin waits 0, rounds 11487096053, OS waits 7756855
RW-shared spins 722142, OS waits 211221; RW-excl spins 787046, OS waits 39353
------------------------
LATEST FOREIGN KEY ERROR
------------------------
110507 21:41:35 Transaction:
TRANSACTION 0 606162814, ACTIVE 0 sec, process no 29956, OS thread id 1223895360 updating or deleting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
14 lock struct(s), heap size 3024, 8 row lock(s), undo log entries 1
MySQL thread id 3686635, query id 124164167 10.64.89.145 viget updating
DELETE FROM file WHERE file_id in ('6dbafa39-7f00-0001-51f2-412a450be5cc' )
Foreign key constraint fails for table `backoffice`.`attachment`:
,
  CONSTRAINT `attachment_ibfk_2` FOREIGN KEY (`file_id`) REFERENCES `file` (`file_id`)
Trying to delete or update in parent table, in index `PRIMARY` tuple:
DATA TUPLE: 17 fields;
 0: len 36; hex 36646261666133392d376630302d303030312d353166322d343132613435306265356363; asc 6dbafa39-7f00-0001-51f2-412a450be5cc;; 1: len 6; hex 000024214f7e; asc   $!O~;; 2: len 7; hex 000000400217bc; asc    @   ;; 3: len 2; hex 03e9; asc   ;; 4: len 2; hex 03e8; asc   ;; 5: len 36; hex 65666635323863622d376630302d303030312d336632662d353239626433653361333032; asc eff528cb-7f00-0001-3f2f-529bd3e3a302;; 6: len 40; hex 36646234376337652d376630302d303030312d353166322d3431326132346664656366352e6d7033; asc 6db47c7e-7f00-0001-51f2-412a24fdecf5.mp3;; 7: len 21; hex 416e67656c73204e6f7720436f6e666572656e6365; asc Angels Now Conference;; 8: len 34; hex 416e67656c73204e6f7720436f6e666572656e6365204a756c7920392c2032303131; asc Angels Now Conference July 9, 2011;; 9: len 1; hex 80; asc  ;; 10: len 8; hex 8000124a5262bdf4; asc    JRb  ;; 11: len 8; hex 8000124a57669dc3; asc    JWf  ;; 12: SQL NULL; 13: len 5; hex 8000012200; asc    " ;; 14: len 1; hex 80; asc  ;; 15: len 2; hex 83e8; asc   ;; 16: len 4; hex 8000000a; asc     ;;

But in child table `backoffice`.`attachment`, in index `PRIMARY`, there is a record:
PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 30; hex 36646261666133392d376630302d303030312d353166322d343132613435; asc 6dbafa39-7f00-0001-51f2-412a45;...(truncated); 1: len 30; hex 38666164663561652d376630302d303030312d326436612d636164326361; asc 8fadf5ae-7f00-0001-2d6a-cad2ca;...(truncated); 2: len 6; hex 00002297b3ff; asc   "   ;; 3: len 7; hex 80000040070110; asc    @   ;; 4: len 2; hex 0000; asc   ;; 5: len 30; hex 416e67656c73204e6f7720436f6e666572656e636520446f63756d656e74; asc Angels Now Conference Document;;

------------
TRANSACTIONS
------------
Trx id counter 0 620783814
Purge done for trx's n:o < 0 620783800 undo n:o < 0 0
History list length 35
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1192212800
MySQL thread id 5341758, query id 189708501 127.0.0.1 lwdba
show innodb status
---TRANSACTION 0 620783788, not started, process no 29956, OS thread id 1196472640
MySQL thread id 5341773, query id 189708353 10.64.89.143 viget
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1223895360
MySQL thread id 5341667, query id 189706152 10.64.89.145 viget
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1227888960
MySQL thread id 5341556, query id 189699857 172.16.135.63 lwdba
---TRANSACTION 0 620781112, not started, process no 29956, OS thread id 1222297920
MySQL thread id 5341511, query id 189696265 10.64.89.143 viget
---TRANSACTION 0 620783736, not started, process no 29956, OS thread id 1229752640
MySQL thread id 5339005, query id 189707998 10.64.89.144 viget
---TRANSACTION 0 620783785, not started, process no 29956, OS thread id 1198602560
MySQL thread id 5337583, query id 189708349 10.64.89.145 viget
---TRANSACTION 0 620783469, not started, process no 29956, OS thread id 1224161600
MySQL thread id 5333500, query id 189708478 10.64.89.144 viget
---TRANSACTION 0 620781240, not started, process no 29956, OS thread id 1198336320
MySQL thread id 5324256, query id 189708493 10.64.89.145 viget
---TRANSACTION 0 617458223, not started, process no 29956, OS thread id 1195141440
MySQL thread id 736, query id 175038790 Has read all relay log; waiting for the slave I/O thread to update it
--------
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
519878 OS file reads, 18962880 OS file writes, 13349046 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 6.25 writes/s, 4.50 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 1190, seg size 1192,
174800 inserts, 174800 merged recs, 54439 merges
Hash table size 35401603, node heap has 35160 buffer(s)
0.50 hash searches/s, 11.75 non-hash searches/s
---
LOG
---
Log sequence number 28 1235093534
Log flushed up to   28 1235093534
Last checkpoint at  28 1235091275
0 pending log writes, 0 pending chkp writes
12262564 log i/o's done, 3.25 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 18909316674; in additional pool allocated 1048576
Dictionary memory allocated 2019632
Buffer pool size   1048576
Free buffers       175763
Database pages     837653
Modified db pages  6
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 770138, created 108485, written 7795318
0.00 reads/s, 0.00 creates/s, 4.25 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 29956, id 1185823040, state: sleeping
Number of rows inserted 6453767, updated 4602534, deleted 3638793, read 388349505551
0.25 inserts/s, 1.25 updates/s, 0.00 deletes/s, 2.75 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set, 1 warning (0.00 sec)

Należy rozważyć zwiększenie wartości limitu czasu oczekiwania na blokadę dla InnoDB poprzez ustawienie innodb_lock_wait_timeout , domyślnie 50 sekund

mysql> show variables like 'innodb_lock_wait_timeout';
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_lock_wait_timeout | 50    |
+--------------------------+-------+
1 row in set (0.01 sec)

Za /etc/my.cnfpomocą tego wiersza możesz ustawić wyższą wartość na stałe

[mysqld]
innodb_lock_wait_timeout=120

i zrestartuj mysql. Jeśli nie możesz teraz ponownie uruchomić mysql, uruchom to:

SET GLOBAL innodb_lock_wait_timeout = 120; 

Możesz także ustawić go na czas trwania sesji

SET innodb_lock_wait_timeout = 120; 

a następnie zapytanie

Jak ktoś wspomniał w jednym z wielu wątków SO dotyczących tego problemu: Czasami proces, który zablokował tabelę, pojawia się jako spanie na liście procesów! Odrywałem włosy, aż zabiłem wszystkie śpiące wątki, które były otwarte w danej bazie danych (żadne z nich nie było wtedy aktywne). To w końcu odblokowało tabelę i pozwoliło uruchomić zapytanie o aktualizację.

Komentator powiedział coś podobnego do „Czasami wątek MySQL blokuje tabelę, a następnie śpi, czekając na coś niezwiązanego z MySQL”.

Po ponownym przejrzeniu pliku show engine innodb status dziennika (kiedy wyśledziłem klienta odpowiedzialnego za blokadę) zauważyłem, że zablokowany wątek był wymieniony na samym dole listy transakcji, pod aktywnymi zapytaniami, które miały się pomylić z powodu zamrożonego zamka:

------------------
---TRANSACTION 2744943820, ACTIVE 1154 sec(!!)
2 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 276558, OS thread handle 0x7f93762e7710, query id 59264109 [ip] [database] cleaning up
Trx read view will not see trx with id >= 2744943821, sees < 2744943821

(niepewny, czy komunikat „Widok odczytu Trx” jest powiązany z zamrożoną blokadą, ale w przeciwieństwie do innych aktywnych transakcji, ta nie wyświetla się z wysłanym zapytaniem i zamiast tego twierdzi, że transakcja „czyści”, ale ma wiele blokady rzędu)

Morał tej historii jest taki, że transakcja może być aktywna, nawet jeśli wątek śpi.

Ze względu na popularność MySQL nic dziwnego, że przekroczono limit czasu oczekiwania na blokadę; spróbuj ponownie uruchomić transakcję wyjątek zyska tyle uwagi na SO.

Im więcej masz rywalizacji, tym większa szansa na zakleszczenie, które silnik DB rozwiąże przez przekroczenie limitu czasu jednej z zakleszczonych transakcji. Ponadto długotrwałe transakcje, które zmodyfikowały (np. UPDATELub DELETE) dużą liczbę pozycji (które blokują się, aby uniknąć nieprawidłowych zapisów, jak wyjaśniono w sekcji Wytrzymałość Java o wysokiej wydajności książce ), są bardziej narażone na konflikty z innymi transakcjami.

Chociaż InnoDB MVCC, nadal możesz zażądać jawnych blokad za pomocą FOR UPDATEklauzuli . Jednak w przeciwieństwie do innych popularnych baz danych (Oracle, MSSQL, PostgreSQL, DB2), MySQL używa REPEATABLE_READjako domyślnego poziomu izolacji .

Teraz blokady, które uzyskałeś (modyfikując wiersze lub używając jawnego blokowania), są wstrzymywane na czas trwania bieżącej transakcji. Jeśli chcesz dobre wyjaśnienie różnicy między REPEATABLE_READi READ COMMITTEDw odniesieniu do blokowania, należy przeczytać ten artykuł Percona .

W REPEATABLE READ każdy blokada uzyskana podczas transakcji jest utrzymywana przez czas trwania transakcji.

W READ COMMITTED blokady, które nie pasują do skanu, są zwalniane po zakończeniu instrukcji STATEMENT.

...

Oznacza to, że w READ COMMITTED inne transakcje mogą aktualizować wiersze, których nie byłyby w stanie zaktualizować (w REPEATABLE READ) po zakończeniu instrukcji UPDATE.

Dlatego: Im bardziej restrykcyjny poziom izolacji ( REPEATABLE_READ,SERIALIZABLE ), tym większa szansa na zakleszczenie. To nie jest problem „per se”, to kompromis.

Możesz uzyskać bardzo dobre wyniki READ_COMMITED, ponieważ potrzebujesz zapobiegania utracie aktualizacji na poziomie aplikacji, gdy używasz transakcji logicznych obejmujących wiele żądań HTTP. Te optymistyczne zamek cele podejście utracone aktualizacje , które mogą się zdarzyć nawet jeśli używasz SERIALIZABLEpoziom izolacji przy jednoczesnym zmniejszeniu twierdzenie blokady przez co pozwala na użycie READ_COMMITED.

Dla przypomnienia wyjątek limitu czasu oczekiwania na blokadę występuje również, gdy występuje zakleszczenie i MySQL nie może go wykryć, więc po prostu upłynął limit czasu. Innym powodem może być bardzo długo działające zapytanie, które jednak jest łatwiejsze do rozwiązania / naprawy i nie będę tutaj opisywał tego przypadku.

MySQL jest zazwyczaj w stanie poradzić sobie z impasami, jeśli są one skonstruowane „prawidłowo” w ramach dwóch transakcji. MySQL następnie zabija / przywraca jedną transakcję, która ma mniej blokad (jest mniej ważna, ponieważ wpłynie na mniej wierszy) i pozwala drugiej zakończyć.

Załóżmy teraz, że istnieją dwa procesy A i B oraz 3 transakcje:

Process A Transaction 1: Locks X
Process B Transaction 2: Locks Y
Process A Transaction 3: Needs Y => Waits for Y
Process B Transaction 2: Needs X => Waits for X
Process A Transaction 1: Waits for Transaction 3 to finish

(see the last two paragraph below to specify the terms in more detail)

=> deadlock 

Jest to bardzo niefortunna konfiguracja, ponieważ MySQL nie widzi zakleszczenia (obejmuje 3 transakcje). Więc to, co robi MySQL, to ... nic! Po prostu czeka, bo nie wie, co robić. Czeka, aż pierwsza uzyskana blokada przekroczy limit czasu (Proces A Transakcja 1: Blokuje X), a następnie odblokuje Blokadę X, która odblokuje Transakcję 2 itd.

Sztuka polega na ustaleniu, co (które zapytanie) powoduje pierwszą blokadę (Blokada X). Będziesz mógł łatwo zobaczyć ( show engine innodb status), że Transakcja 3 czeka na Transakcję 2, ale nie zobaczysz, na którą Transakcja 2 czeka (Transakcja 1). MySQL nie wydrukuje żadnych blokad ani zapytań związanych z Transakcją 1. Jedyną wskazówką będzie to, że na samym dole listy transakcji (show engine innodb status wydruku) zobaczysz Transakcję 1 najwyraźniej nic nie robiąc (ale w rzeczywistości czeka na Transakcję 3, aby koniec).

Technika określania, które zapytanie SQL powoduje przyznanie blokady (Lock X) dla danej transakcji, która czeka, została opisana tutaj Tracking MySQL query history in long running transactions

Jeśli zastanawiasz się, na czym dokładnie polega proces i transakcja. Proces jest procesem PHP. Transakcja jest transakcją zdefiniowaną przez innodb-trx-table . W moim przypadku miałem dwa procesy PHP, w każdym rozpocząłem transakcję ręcznie. Co ciekawe, mimo że rozpocząłem jedną transakcję w procesie, MySQL użył w rzeczywistości dwóch osobnych transakcji (nie mam pojęcia, dlaczego, może niektórzy deweloperzy MySQL mogą to wyjaśnić).

MySQL zarządza wewnętrznie własnymi transakcjami i zdecydował (w moim przypadku), aby użyć dwóch transakcji do obsługi wszystkich żądań SQL pochodzących z procesu PHP (Proces A). Stwierdzenie, że Transakcja 1 czeka na zakończenie Transakcji 3, jest wewnętrzną sprawą MySQL. MySQL „wiedział”, że transakcja 1 i transakcja 3 zostały faktycznie utworzone w ramach jednego żądania „transakcji” (z procesu A). Teraz cała „transakcja” została zablokowana, ponieważ transakcja 3 (podsekcja „transakcji”) została zablokowana. Ponieważ „transakcja” nie była w stanie zakończyć Transakcji 1 (również podsekcja „transakcji”) została również oznaczona jako niezakończona. To mam na myśli przez „Transakcja 1 czeka na zakończenie transakcji 3”.

Dużym problemem związanym z tym wyjątkiem jest to, że zwykle nie jest on odtwarzalny w środowisku testowym i nie jesteśmy w pobliżu, aby uruchomić status silnika innodb, gdy dzieje się to na prod. Dlatego w jednym z projektów umieściłem poniższy kod w bloku catch dla tego wyjątku. To pomogło mi złapać status silnika, kiedy nastąpił wyjątek. To bardzo pomogło.

Statement st = con.createStatement();
ResultSet rs =  st.executeQuery("SHOW ENGINE INNODB STATUS");
while(rs.next()){
    log.info(rs.getString(1));
    log.info(rs.getString(2));
    log.info(rs.getString(3));
}

Spójrz na stronę podręcznika pt-deadlock-loggernarzędzia :

brew install percona-toolkit
pt-deadlock-logger --ask-pass server_name

Wydobywa informacje ze engine innodb statuswspomnianego powyżej, a także można go użyć do utworzenia, daemonktóry działa co 30 sekund.

Ekstrapolując z powyższej odpowiedzi Rolando, to one blokują twoje zapytanie:

---TRANSACTION 0 620783788, not started, process no 29956, OS thread id 1196472640
MySQL thread id 5341773, query id 189708353 10.64.89.143 viget

Jeśli musisz wykonać zapytanie i nie możesz czekać na uruchomienie innych, zabij ich za pomocą identyfikatora wątku MySQL:

kill 5341773 <replace with your thread id>

^{(oczywiście z poziomu mysql, a nie powłoki, oczywiście)}

Musisz znaleźć identyfikatory wątku z:

show engine innodb status\G

polecenie i dowiedz się, który z nich blokuje bazę danych.

Oto, co ostatecznie musiałem zrobić, aby dowiedzieć się, co „inne zapytanie” spowodowało problem z przekroczeniem limitu czasu blokady. W kodzie aplikacji śledzimy wszystkie oczekujące wywołania bazy danych w osobnym wątku poświęconym temu zadaniu. Jeśli jakiekolwiek wywołanie DB trwa dłużej niż N sekund (dla nas to 30 sekund), logujemy:

-- Pending InnoDB transactions
SELECT * FROM information_schema.innodb_trx ORDER BY trx_started; 

-- Optionally, log what transaction holds what locks
SELECT * FROM information_schema.innodb_locks;

Dzięki powyższym byliśmy w stanie wskazać współbieżne zapytania blokujące wiersze powodujące impas. W moim przypadku były to stwierdzenia podobneINSERT ... SELECT które w przeciwieństwie do zwykłych instrukcji SELECT blokują leżące poniżej wiersze. Następnie możesz zreorganizować kod lub użyć innej izolacji transakcji, np. Odczytać niezaangażowane.

Powodzenia!

Możesz użyć:

show full processlist

która wyświetli listę wszystkich połączeń w MySQL i bieżący stan połączenia, a także wykonywane zapytanie. Istnieje również krótszy wariant, show processlist;który wyświetla skrócone zapytanie oraz statystyki połączenia.

Jeśli używasz JDBC, masz opcję
includeInnodbStatusInDeadlockExceptions = true

https://dev.mysql.com/doc/connector-j/8.0/en/connector-j-reference-configuration-properties.html

Aktywuj MySQL general.log (wymagający dużej ilości dysku) i użyj mysql_analyse_general_log.pl, aby wyodrębnić długoterminowe transakcje, na przykład:

--min-duration = twoja wartość innodb_lock_wait_timeout

Następnie wyłącz general.log.