Einer der beliebtesten InnoDB-Fehler ist die Überschreitung des InnoDB-Sperrwartezeitlimits, zum Beispiel:
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionDas Obige bedeutet einfach, dass die Transaktion das innodb_lock_wait_timeout erreicht hat, während sie darauf wartet, eine exklusive Sperre zu erhalten, die standardmäßig 50 Sekunden beträgt. Die häufigsten Ursachen sind:
- Die anstößige Transaktion ist nicht schnell genug, um die Transaktion innerhalb der Dauer von innodb_lock_wait_timeout festzuschreiben oder rückgängig zu machen.
- Die anstößige Transaktion wartet darauf, dass die Zeilensperre von einer anderen Transaktion aufgehoben wird.
Die Auswirkungen einer InnoDB-Sperrwartezeit
InnoDB lock wait timeout kann zwei wichtige Auswirkungen haben:
- Die fehlgeschlagene Anweisung wird standardmäßig nicht zurückgesetzt.
- Selbst wenn innodb_rollback_on_timeout aktiviert ist, ist ROLLBACK immer noch eine teurere Operation als COMMIT, wenn eine Anweisung in einer Transaktion fehlschlägt.
Lassen Sie uns mit einem einfachen Beispiel herumspielen, um den Effekt besser zu verstehen. Betrachten Sie die folgenden zwei Tabellen in der Datenbank mydb:
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;Die erste Tabelle (Tabelle1):
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';Die zweite Tabelle (Tabelle2):
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Wir haben unsere Transaktionen in zwei verschiedenen Sitzungen in der folgenden Reihenfolge ausgeführt:
| Bestellung | Transaktion Nr. 1 (T1) | Transaktion Nr. 2 (T2) |
| 1 | SELECT * FROM table1; (OK) | SELECT * FROM table1; (OK) |
| 2 | UPDATE table1 SET data ='T1 aktualisiert die Zeile' WHERE id =1; (OK) | |
| 3 | UPDATE table2 SET data ='T2 aktualisiert die Zeile' WHERE id =1; (OK) | |
| 4 | UPDATE table1 SET data ='T2 aktualisiert die Zeile' WHERE id =1; (Hängt für eine Weile und gibt schließlich einen Fehler zurück "Lock Wait Timeout überschritten; Versuchen Sie, die Transaktion neu zu starten") | |
| 5 | COMMIT; (OK) | |
| 6 | COMMIT; (OK) |
mysql> SELECT * FROM table1 WHERE id = 1;
+----+-----------------------------------+
| id | data |
+----+-----------------------------------+
| 1 | T1 is updating the row |
+----+-----------------------------------+
mysql> SELECT * FROM table2 WHERE id = 1;
+----+-----------------------------------+
| id | data |
+----+-----------------------------------+
| 1 | T2 is updating the row |
+----+-----------------------------------+Nachdem T2 erfolgreich festgeschrieben wurde, würde man erwarten, die gleiche Ausgabe "T2 aktualisiert die Zeile" für Tabelle1 und Tabelle2 zu erhalten, aber die Ergebnisse zeigen, dass nur Tabelle2 aktualisiert wurde. Man könnte meinen, dass beim Auftreten eines Fehlers innerhalb einer Transaktion alle Anweisungen in der Transaktion automatisch rückgängig gemacht würden, oder dass bei einem erfolgreichen Commit einer Transaktion die gesamten Anweisungen atomar ausgeführt würden. Dies gilt für Deadlocks, aber nicht für das InnoDB-Sperrwartezeitlimit.
Sofern Sie nicht innodb_rollback_on_timeout=1 (Standardwert ist 0 – deaktiviert) festlegen, wird kein automatisches Rollback für den InnoDB-Sperrwartezeitüberschreitungsfehler durchgeführt. Das bedeutet, dass MySQL, indem es der Standardeinstellung folgt, weder fehlschlägt und die gesamte Transaktion rückgängig macht, noch die zeitlich abgelaufene Anweisung erneut versucht und nur die nächsten Anweisungen verarbeitet, bis COMMIT oder ROLLBACK erreicht wird. Dies erklärt, warum Transaktion T2 teilweise festgeschrieben wurde!
In der InnoDB-Dokumentation heißt es eindeutig:„InnoDB setzt nur die letzte Anweisung bei einem Transaktions-Timeout zurück standardmäßig". In diesem Fall erhalten wir nicht die von InnoDB angebotene Transaktionsatomarität. Die Atomarität in ACID-konform ist, dass wir entweder alle oder nichts von der Transaktion erhalten, was bedeutet, dass eine Teiltransaktion lediglich nicht akzeptabel ist.
Umgang mit einem InnoDB Lock Wait Timeout
Wenn Sie also erwarten, dass eine Transaktion automatisch zurückgesetzt wird, wenn ein InnoDB-Sperrwartefehler auftritt, ähnlich wie bei einem Deadlock, setzen Sie die folgende Option in der MySQL-Konfigurationsdatei:
innodb_rollback_on_timeout=1Ein MySQL-Neustart ist erforderlich. Beim Bereitstellen eines MySQL-basierten Clusters setzt ClusterControl immer innodb_rollback_on_timeout=1 auf jedem Knoten. Ohne diese Option muss Ihre Anwendung die fehlgeschlagene Anweisung wiederholen oder explizit ROLLBACK ausführen, um die Atomarität der Transaktion aufrechtzuerhalten.
So überprüfen Sie, ob die Konfiguration korrekt geladen wurde:
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+Um zu überprüfen, ob die neue Konfiguration funktioniert, können wir den com_rollback-Zähler verfolgen, wenn dieser Fehler auftritt:
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Verfolgung der Sperrtransaktion
Es gibt mehrere Orte, an denen wir nachschauen können, um die Sperrtransaktion oder Kontoauszüge nachzuverfolgen. Sehen wir uns zunächst den Status der InnoDB-Engine im Abschnitt TRANSAKTIONEN an:
mysql> SHOW ENGINE INNODB STATUS\G
------------
TRANSACTIONS
------------
...
---TRANSACTION 3100, ACTIVE 2 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 50, OS thread handle 139887555282688, query id 360 localhost ::1 root updating
update table1 set data = 'T2 is updating the row' where id = 1
------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6 page no 4 n bits 72 index PRIMARY of table `mydb`.`table1` trx id 3100 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000001; asc ;;
1: len 6; hex 000000000c19; asc ;;
2: len 7; hex 020000011b0151; asc Q;;
3: len 22; hex 5431206973207570646174696e672074686520726f77; asc T1 is updating the row;;
------------------
---TRANSACTION 3097, ACTIVE 46 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 48, OS thread handle 139887556167424, query id 358 localhost ::1 root
Trx read view will not see trx with id >= 3097, sees < 3097Aus den obigen Informationen können wir uns einen Überblick über die Transaktionen verschaffen, die derzeit auf dem Server aktiv sind. Transaktion 3097 sperrt derzeit eine Zeile, auf die Transaktion 3100 zugreifen muss. Die obige Ausgabe gibt uns jedoch nicht den tatsächlichen Abfragetext an, der uns dabei helfen könnte, herauszufinden, welchen Teil der Abfrage/Anweisung/Transaktion wir weiter untersuchen müssen . Sehen wir uns an, was wir anhand der Blocker-MySQL-Thread-ID 48 aus der MySQL-Prozessliste entnehmen können:
mysql> SHOW FULL PROCESSLIST;
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+
| 4 | event_scheduler | localhost | <null> | Daemon | 5146 | Waiting on empty queue | <null> |
| 10 | root | localhost:56042 | performance_schema | Query | 0 | starting | show full processlist |
| 48 | root | localhost:56118 | mydb | Sleep | 145 | | <null> |
| 50 | root | localhost:56122 | mydb | Sleep | 113 | | <null> |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+Thread-ID 48 zeigt den Befehl als „Sleep“. Trotzdem hilft uns das nicht viel zu wissen, welche Anweisungen die andere Transaktion blockieren. Dies liegt daran, dass die Anweisung in dieser Transaktion ausgeführt wurde und diese offene Transaktion im Moment im Grunde nichts tut. Wir müssen weiter nach unten tauchen, um zu sehen, was mit diesem Thread los ist.
Für MySQL 8.0 ist die InnoDB-Sperrwarteinstrumentierung unter der data_lock_waits-Tabelle in der performance_schema-Datenbank (oder innodb_lock_waits-Tabelle in der sys-Datenbank) verfügbar. Wenn ein Lock-Wait-Ereignis stattfindet, sollten wir etwa Folgendes sehen:
mysql> SELECT * FROM performance_schema.data_lock_waits\G
***************************[ 1. row ]***************************
ENGINE | INNODB
REQUESTING_ENGINE_LOCK_ID | 139887595270456:6:4:2:139887487554680
REQUESTING_ENGINE_TRANSACTION_ID | 3100
REQUESTING_THREAD_ID | 89
REQUESTING_EVENT_ID | 8
REQUESTING_OBJECT_INSTANCE_BEGIN | 139887487554680
BLOCKING_ENGINE_LOCK_ID | 139887595269584:6:4:2:139887487548648
BLOCKING_ENGINE_TRANSACTION_ID | 3097
BLOCKING_THREAD_ID | 87
BLOCKING_EVENT_ID | 9
BLOCKING_OBJECT_INSTANCE_BEGIN | 139887487548648Beachten Sie, dass in MySQL 5.6 und 5.7 ähnliche Informationen in der Tabelle innodb_lock_waits unter der Datenbank information_schema gespeichert werden. Achten Sie auf den BLOCKING_THREAD_ID-Wert. Wir können diese Informationen verwenden, um nach allen Anweisungen zu suchen, die von diesem Thread in der Tabelle events_statements_history ausgeführt werden:
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setEs sieht so aus, als ob die Thread-Informationen nicht mehr vorhanden sind. Wir können dies überprüfen, indem wir den Mindest- und Höchstwert der Spalte thread_id in der Tabelle events_statements_history mit der folgenden Abfrage überprüfen:
mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98 | 129 |
+------------------+------------------+Der gesuchte Thread (87) wurde aus der Tabelle entfernt. Wir können dies bestätigen, indem wir uns die Größe der Tabelle event_statements_history ansehen:
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Das Obige bedeutet, dass die events_statements_history nur die letzten 10 Threads speichern kann. Glücklicherweise verfügt performance_schema über eine weitere Tabelle zum Speichern weiterer Zeilen namens events_statements_history_long, die ähnliche Informationen speichert, jedoch für alle Threads, und viel mehr Zeilen enthalten kann:
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Sie erhalten jedoch ein leeres Ergebnis, wenn Sie zum ersten Mal versuchen, die Tabelle events_statements_history_long abzufragen. Dies ist zu erwarten, da diese Instrumentierung in MySQL standardmäßig deaktiviert ist, wie wir in der folgenden setup_consumers-Tabelle sehen können:
mysql> SELECT * FROM performance_schema.setup_consumers;
+----------------------------------+---------+
| NAME | ENABLED |
+----------------------------------+---------+
| events_stages_current | NO |
| events_stages_history | NO |
| events_stages_history_long | NO |
| events_statements_current | YES |
| events_statements_history | YES |
| events_statements_history_long | NO |
| events_transactions_current | YES |
| events_transactions_history | YES |
| events_transactions_history_long | NO |
| events_waits_current | NO |
| events_waits_history | NO |
| events_waits_history_long | NO |
| global_instrumentation | YES |
| thread_instrumentation | YES |
| statements_digest | YES |
+----------------------------------+---------+Um die Tabelle events_statements_history_long zu aktivieren, müssen wir die Tabelle setup_consumers wie folgt aktualisieren:
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Überprüfen Sie jetzt, ob Zeilen in der Tabelle events_statements_history_long vorhanden sind:
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Cool. Jetzt können wir warten, bis das InnoDB-Sperrwarteereignis erneut ausgelöst wird, und wenn dies geschieht, sollten Sie die folgende Zeile in der Tabelle data_lock_waits sehen:
mysql> SELECT * FROM performance_schema.data_lock_waits\G
***************************[ 1. row ]***************************
ENGINE | INNODB
REQUESTING_ENGINE_LOCK_ID | 139887595270456:6:4:2:139887487555024
REQUESTING_ENGINE_TRANSACTION_ID | 3083
REQUESTING_THREAD_ID | 60
REQUESTING_EVENT_ID | 9
REQUESTING_OBJECT_INSTANCE_BEGIN | 139887487555024
BLOCKING_ENGINE_LOCK_ID | 139887595269584:6:4:2:139887487548648
BLOCKING_ENGINE_TRANSACTION_ID | 3081
BLOCKING_THREAD_ID | 57
BLOCKING_EVENT_ID | 8
BLOCKING_OBJECT_INSTANCE_BEGIN | 139887487548648Auch hier verwenden wir den BLOCKING_THREAD_ID-Wert, um alle Anweisungen zu filtern, die von diesem Thread anhand der Tabelle events_statements_history_long ausgeführt wurden:
mysql> SELECT `THREAD_ID`,`EVENT_ID`,`EVENT_NAME`, `CURRENT_SCHEMA`,`SQL_TEXT` FROM events_statements_history_long
WHERE `THREAD_ID` = 57
ORDER BY `EVENT_ID`;
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| THREAD_ID | EVENT_ID | EVENT_NAME | CURRENT_SCHEMA | SQL_TEXT |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| 57 | 1 | statement/sql/select | <null> | select connection_id() |
| 57 | 2 | statement/sql/select | <null> | SELECT @@VERSION |
| 57 | 3 | statement/sql/select | <null> | SELECT @@VERSION_COMMENT |
| 57 | 4 | statement/com/Init DB | <null> | <null> |
| 57 | 5 | statement/sql/begin | mydb | begin |
| 57 | 7 | statement/sql/select | mydb | select 'T1 is in the house' |
| 57 | 8 | statement/sql/select | mydb | select * from table1 |
| 57 | 9 | statement/sql/select | mydb | select 'some more select' |
| 57 | 10 | statement/sql/update | mydb | update table1 set data = 'T1 is updating the row' where id = 1 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Endlich haben wir den Übeltäter gefunden. Anhand der Ereignisfolge von Thread 57 können wir erkennen, dass die obige Transaktion (T1) noch nicht abgeschlossen ist (kein COMMIT oder ROLLBACK), und wir können sehen, dass die allerletzte Anweisung eine exklusive Sperre für die Zeile zur Aktualisierung erhalten hat Operation, die von der anderen Transaktion (T2) benötigt wurde und einfach dort hängt. Das erklärt, warum wir 'Sleep' in der Ausgabe der MySQL-Prozessliste sehen.
Wie wir sehen können, erfordert die obige SELECT-Anweisung, dass Sie vorher den thread_id-Wert erhalten. Um diese Abfrage zu vereinfachen, können wir die IN-Klausel und eine Unterabfrage verwenden, um beide Tabellen zu verbinden. Die folgende Abfrage erzeugt ein identisches Ergebnis wie das obige:
mysql> SELECT `THREAD_ID`,`EVENT_ID`,`EVENT_NAME`, `CURRENT_SCHEMA`,`SQL_TEXT` from events_statements_history_long WHERE `THREAD_ID` IN (SELECT `BLOCKING_THREAD_ID` FROM data_lock_waits) ORDER BY `EVENT_ID`;
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| THREAD_ID | EVENT_ID | EVENT_NAME | CURRENT_SCHEMA | SQL_TEXT |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| 57 | 1 | statement/sql/select | <null> | select connection_id() |
| 57 | 2 | statement/sql/select | <null> | SELECT @@VERSION |
| 57 | 3 | statement/sql/select | <null> | SELECT @@VERSION_COMMENT |
| 57 | 4 | statement/com/Init DB | <null> | <null> |
| 57 | 5 | statement/sql/begin | mydb | begin |
| 57 | 7 | statement/sql/select | mydb | select 'T1 is in the house' |
| 57 | 8 | statement/sql/select | mydb | select * from table1 |
| 57 | 9 | statement/sql/select | mydb | select 'some more select' |
| 57 | 10 | statement/sql/update | mydb | update table1 set data = 'T1 is updating the row' where id = 1 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Es ist jedoch nicht praktikabel, die obige Abfrage auszuführen, wenn das InnoDB-Sperrwarteereignis auftritt. Abgesehen von dem Fehler der Anwendung, woher wissen Sie, dass das Lock-Wait-Ereignis stattfindet? Wir können diese Abfrageausführung mit dem folgenden einfachen Bash-Skript namens track_lockwait.sh automatisieren:
$ cat track_lockwait.sh
#!/bin/bash
## track_lockwait.sh
## Print out the blocking statements that causing InnoDB lock wait
INTERVAL=5
DIR=/root/lockwait/
[ -d $dir ] || mkdir -p $dir
while true; do
check_query=$(mysql -A -Bse 'SELECT THREAD_ID,EVENT_ID,EVENT_NAME,CURRENT_SCHEMA,SQL_TEXT FROM events_statements_history_long WHERE THREAD_ID IN (SELECT BLOCKING_THREAD_ID FROM data_lock_waits) ORDER BY EVENT_ID')
# if $check_query is not empty
if [[ ! -z $check_query ]]; then
timestamp=$(date +%s)
echo $check_query > $DIR/innodb_lockwait_report_${timestamp}
fi
sleep $INTERVAL
doneWenden Sie die Ausführungsberechtigung an und dämonisieren Sie das Skript im Hintergrund:
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Jetzt müssen wir nur noch warten, bis die Berichte im Verzeichnis /root/lockwait generiert werden. Abhängig von der Datenbankauslastung und den Zeilenzugriffsmustern sehen Sie möglicherweise viele Dateien in diesem Verzeichnis. Überwachen Sie das Verzeichnis genau, da es sonst mit zu vielen Berichtsdateien überflutet würde.
Wenn Sie ClusterControl verwenden, können Sie die Transaktionsprotokollfunktion unter Leistung -> Transaktionsprotokoll aktivieren, wo ClusterControl einen Bericht über Deadlocks und lang andauernde Transaktionen bereitstellt, was Ihnen das Finden des Übeltäters erleichtern wird.
Fazit
Zusammenfassend lässt sich sagen, dass wir bei einem „Lock Wait Timeout Exceeded“-Fehler in MySQL zuerst die Auswirkungen verstehen müssen, die ein solcher Fehler auf unsere Infrastruktur haben kann, dann die anstößige Transaktion verfolgen und entsprechend handeln entweder mit Shell-Skripten wie track_lockwait.sh oder Datenbankverwaltungssoftware wie ClusterControl.
Wenn Sie sich für Shell-Skripte entscheiden, denken Sie daran, dass sie zwar Geld sparen, aber auch Zeit kosten, da Sie ein oder zwei Dinge darüber wissen müssen, wie sie funktionieren, wenden Sie sich an Berechtigungen, und lassen Sie sie möglicherweise im Hintergrund laufen, und wenn Sie sich im Shell-Dschungel verirren, können wir Ihnen helfen.
Was auch immer Sie implementieren möchten, folgen Sie uns auf Twitter oder abonnieren Sie unseren RSS-Feed, um weitere Tipps zur Verbesserung der Leistung Ihrer Software und der sie unterstützenden Datenbanken zu erhalten, wie z. B. diesen Beitrag, der 6 häufige Fehlerszenarien in MySQL abdeckt /P>
