Cara Memperbaiki Error Lock Wait Timeout Exceeded di MySQL

Salah satu kesalahan InnoDB yang paling populer adalah batas waktu tunggu penguncian InnoDB terlampaui, misalnya:

SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

Di atas berarti transaksi telah mencapai innodb_lock_wait_timeout sambil menunggu untuk mendapatkan kunci eksklusif yang defaultnya adalah 50 detik. Penyebab umumnya adalah:

1. Transaksi ofensif tidak cukup cepat untuk melakukan atau mengembalikan transaksi dalam durasi innodb_lock_wait_timeout.
2. Transaksi ofensif menunggu kunci baris dilepaskan oleh transaksi lain.

Efek dari Waktu Tunggu Kunci InnoDB

Batas waktu tunggu kunci InnoDB dapat menyebabkan dua implikasi utama:

• Pernyataan yang gagal tidak dibatalkan secara default.
• Bahkan jika innodb_rollback_on_timeout diaktifkan, ketika pernyataan gagal dalam transaksi, ROLLBACK masih merupakan operasi yang lebih mahal daripada COMMIT.

Mari bermain-main dengan contoh sederhana untuk lebih memahami efeknya. Perhatikan dua tabel berikut dalam database mydb:

mysql> CREATE SCHEMA mydb;
mysql> USE mydb;

Tabel pertama (tabel1):

mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';

Tabel kedua (tabel2):

mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';

Kami mengeksekusi transaksi kami dalam dua sesi berbeda dengan urutan sebagai berikut:

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            |
+----+-----------------------------------+

Setelah T2 berhasil dikomit, orang akan mengharapkan untuk mendapatkan output yang sama "T2 sedang memperbarui baris" untuk table1 dan table2 tetapi hasilnya menunjukkan bahwa hanya table2 yang diperbarui. Orang mungkin berpikir bahwa jika ada kesalahan yang ditemukan dalam suatu transaksi, semua pernyataan dalam transaksi akan otomatis dibatalkan, atau jika transaksi berhasil dilakukan, seluruh pernyataan dieksekusi secara atomik. Ini berlaku untuk kebuntuan, tetapi tidak untuk waktu tunggu kunci InnoDB.

Kecuali Anda mengatur innodb_rollback_on_timeout=1 (defaultnya adalah 0 - dinonaktifkan), rollback otomatis tidak akan terjadi untuk kesalahan waktu tunggu kunci InnoDB. Artinya, dengan mengikuti pengaturan default, MySQL tidak akan gagal dan mengembalikan seluruh transaksi, atau mencoba lagi pernyataan timed out dan hanya memproses pernyataan berikutnya hingga mencapai COMMIT atau ROLLBACK. Ini menjelaskan mengapa transaksi T2 dilakukan sebagian!

Dokumentasi InnoDB dengan jelas mengatakan "InnoDB hanya mengembalikan pernyataan terakhir pada batas waktu transaksi secara default". Dalam hal ini, kami tidak mendapatkan atomisitas transaksi yang ditawarkan oleh InnoDB. Atomisitas dalam ACID compliant adalah kami mendapatkan semua atau tidak sama sekali dari transaksi, yang berarti sebagian transaksi tidak dapat diterima.

Menangani Waktu Tunggu Kunci InnoDB

Jadi, jika Anda mengharapkan transaksi untuk auto-rollback ketika menemukan kesalahan menunggu kunci InnoDB, sama seperti apa yang akan terjadi di kebuntuan, atur opsi berikut di file konfigurasi MySQL:

innodb_rollback_on_timeout=1

Diperlukan restart MySQL. Saat menggunakan cluster berbasis MySQL, ClusterControl akan selalu mengatur innodb_rollback_on_timeout=1 pada setiap node. Tanpa opsi ini, aplikasi Anda harus mencoba kembali pernyataan gagal, atau melakukan ROLLBACK secara eksplisit untuk mempertahankan atomisitas transaksi.

Untuk memverifikasi apakah konfigurasi dimuat dengan benar:

mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON    |
+----------------------------+-------+

Untuk memeriksa apakah konfigurasi baru berfungsi, kita dapat melacak penghitung com_rollback ketika kesalahan ini terjadi:

mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback  | 1     |
+---------------+-------+

Melacak Transaksi Pemblokiran

Ada beberapa tempat yang bisa kita lihat untuk melacak transaksi atau pernyataan pemblokiran. Mari kita mulai dengan melihat status mesin InnoDB di bawah bagian TRANSAKSI:

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 < 3097

Dari informasi di atas, kita bisa mendapatkan gambaran tentang transaksi yang sedang aktif di server. Transaksi 3097 saat ini mengunci baris yang perlu diakses oleh transaksi 3100. Namun, output di atas tidak memberi tahu kami teks kueri sebenarnya yang dapat membantu kami mencari tahu bagian mana dari kueri/pernyataan/transaksi yang perlu kami selidiki lebih lanjut . Dengan menggunakan pemblokir MySQL thread ID 48, mari kita lihat apa yang dapat kita kumpulkan dari daftar proses MySQL:

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 menunjukkan perintah sebagai 'Sleep'. Namun, ini tidak banyak membantu kita untuk mengetahui pernyataan mana yang memblokir transaksi lainnya. Ini karena pernyataan dalam transaksi ini telah dieksekusi dan transaksi terbuka ini pada dasarnya tidak melakukan apa-apa saat ini. Kita perlu menyelam lebih jauh ke bawah untuk melihat apa yang terjadi dengan utas ini.

Untuk MySQL 8.0, instrumentasi kunci tunggu InnoDB tersedia di bawah tabel data_lock_waits di dalam database performance_schema (atau tabel innodb_lock_waits di dalam database sys). Jika event lock wait sedang terjadi, kita akan melihat sesuatu seperti ini:

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   | 139887487548648

Perhatikan bahwa di MySQL 5.6 dan 5.7, informasi serupa disimpan di dalam tabel innodb_lock_waits di bawah database information_schema. Perhatikan nilai BLOCKING_THREAD_ID. Kita dapat menggunakan informasi ini untuk mencari semua pernyataan yang dieksekusi oleh utas ini di tabel events_statements_history:

mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in set

Sepertinya informasi utasnya sudah tidak ada lagi. Kita dapat memverifikasi dengan memeriksa nilai minimum dan maksimum kolom thread_id di tabel events_statements_history dengan query berikut:

mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98               | 129              |
+------------------+------------------+

Utas yang kami cari (87) telah dipotong dari tabel. Kami dapat mengonfirmasi ini dengan melihat ukuran tabel event_statements_history:

mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10                                                  |
+-----------------------------------------------------+

Di atas berarti events_statements_history hanya dapat menyimpan 10 utas terakhir. Untungnya, performance_schema memiliki tabel lain untuk menyimpan lebih banyak baris yang disebut events_statements_history_long, yang menyimpan informasi serupa tetapi untuk semua utas dan dapat berisi lebih banyak baris:

mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000                                                    |
+----------------------------------------------------------+

Namun, Anda akan mendapatkan hasil kosong jika Anda mencoba mengkueri tabel events_statements_history_long untuk pertama kalinya. Hal ini diharapkan karena secara default, instrumentasi ini dinonaktifkan di MySQL seperti yang dapat kita lihat pada tabel setup_consumers berikut:

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     |
+----------------------------------+---------+

Untuk mengaktifkan tabel events_statements_history_long, kita perlu mengupdate tabel setup_consumers seperti di bawah ini:

mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';

Verifikasi apakah ada baris di tabel events_statements_history_long sekarang:

mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4                  |
+--------------------+

Dingin. Sekarang kita bisa menunggu sampai event lock wait InnoDB muncul lagi dan ketika itu terjadi, Anda akan melihat baris berikut di tabel data_lock_wais:

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   | 139887487548648

Sekali lagi, kami menggunakan nilai BLOCKING_THREAD_ID untuk memfilter semua pernyataan yang telah dieksekusi oleh utas ini terhadap tabel events_statements_history_long: 

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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+

Akhirnya kami menemukan pelakunya. Kita dapat mengetahuinya dengan melihat urutan kejadian pada thread 57 dimana transaksi di atas (T1) masih belum selesai (tidak ada COMMIT atau ROLLBACK), dan kita dapat melihat pernyataan terakhir telah memperoleh kunci eksklusif ke baris untuk pembaruan operasi yang dibutuhkan oleh transaksi lain (T2) dan hanya tergantung di sana. Itu menjelaskan mengapa kita melihat 'Tidur' di output daftar proses MySQL.

Seperti yang bisa kita lihat, pernyataan SELECT di atas mengharuskan Anda untuk mendapatkan nilai thread_id terlebih dahulu. Untuk menyederhanakan query ini, kita dapat menggunakan klausa IN dan subquery untuk menggabungkan kedua tabel. Kueri berikut menghasilkan hasil yang sama seperti di atas:

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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+

Namun, tidak praktis bagi kami untuk menjalankan kueri di atas setiap kali peristiwa tunggu kunci InnoDB terjadi. Terlepas dari kesalahan dari aplikasi, bagaimana Anda tahu bahwa acara kunci menunggu sedang terjadi? Kami dapat mengotomatiskan eksekusi kueri ini dengan skrip Bash sederhana berikut, yang disebut track_lockwait.sh:

$ 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
done

Terapkan izin yang dapat dieksekusi dan lakukan daemonisasi skrip di latar belakang:

$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &

Sekarang, kita hanya perlu menunggu laporan dibuat di bawah direktori /root/lockwait. Bergantung pada beban kerja database dan pola akses baris, Anda mungkin melihat banyak file di bawah direktori ini. Pantau direktori dengan cermat jika tidak, direktori akan dibanjiri terlalu banyak file laporan.

Jika Anda menggunakan ClusterControl, Anda dapat mengaktifkan fitur Log Transaksi di bawah Kinerja -> Log Transaksi di mana ClusterControl akan memberikan laporan tentang kebuntuan dan transaksi yang berjalan lama yang akan memudahkan hidup Anda dalam menemukan pelakunya.

Kesimpulan

Ringkasnya, jika kita menghadapi kesalahan “Lock Wait Timeout Exceeded” di MySQL, pertama-tama kita harus memahami efek kesalahan tersebut terhadap infrastruktur kita, kemudian melacak transaksi ofensif dan menindaklanjutinya baik dengan skrip shell seperti track_lockwait.sh, atau perangkat lunak manajemen database seperti ClusterControl.

Jika Anda memutuskan untuk menggunakan skrip shell, perlu diingat bahwa skrip tersebut dapat menghemat uang Anda tetapi akan menghabiskan waktu Anda, karena Anda perlu mengetahui satu atau dua hal tentang cara kerjanya, terapkan izin, dan mungkin membuatnya berjalan di latar belakang, dan jika Anda tersesat di hutan shell, kami dapat membantu.

Apa pun yang Anda putuskan untuk diterapkan, pastikan untuk mengikuti kami di Twitter atau berlangganan umpan RSS kami untuk mendapatkan lebih banyak kiat tentang meningkatkan kinerja perangkat lunak Anda dan basis data yang mendukungnya, seperti posting ini yang mencakup 6 skenario kegagalan umum di MySQL.