mita2 database life

主にMySQLに関するメモです

MySQL Lock wait timeout exceeded が発生している現場を押さえる

pt-stalk は、vmstatpsといったOSから見える情報や SHOW PROCESSLIST SHOW GLOBAL STATUSといったDBの情報など、MySQLのトラブルシュートに必要な情報をごっそり収集するツールです。

$ sudo ls -l /var/lib/pt-stalk
total 1428
-rw-r--r--. 1 root root  13260 11月 19 06:15 2020_11_19_06_15_10-df
-rw-r--r--. 1 root root    121 11月 19 06:15 2020_11_19_06_15_10-disk-space
-rw-r--r--. 1 root root   5730 11月 19 06:15 2020_11_19_06_15_10-diskstats
-rw-r--r--. 1 root root     22 11月 19 06:15 2020_11_19_06_15_10-hostname
-rw-r--r--. 1 root root   4714 11月 19 06:15 2020_11_19_06_15_10-innodbstatus1
-rw-r--r--. 1 root root   4715 11月 19 06:15 2020_11_19_06_15_10-innodbstatus2
-rw-r--r--. 1 root root  65640 11月 19 06:15 2020_11_19_06_15_10-interrupts
-rw-r--r--. 1 root root  15624 11月 19 06:15 2020_11_19_06_15_10-lock-waits
-rw-r--r--. 1 root root    845 11月 19 06:15 2020_11_19_06_15_10-log_error
-rw-r--r--. 1 root root   2724 11月 19 06:15 2020_11_19_06_15_10-lsof
-rw-r--r--. 1 root root  39780 11月 19 06:15 2020_11_19_06_15_10-meminfo
-rw-r--r--. 1 root root    121 11月 19 06:15 2020_11_19_06_15_10-mutex-status1
-rw-r--r--. 1 root root    121 11月 19 06:15 2020_11_19_06_15_10-mutex-status2
-rw-r--r--. 1 root root  22145 11月 19 06:15 2020_11_19_06_15_10-mysqladmin
-rw-r--r--. 1 root root  30210 11月 19 06:15 2020_11_19_06_15_10-netstat
-rw-r--r--. 1 root root  42810 11月 19 06:15 2020_11_19_06_15_10-netstat_s
-rw-r--r--. 1 root root   3052 11月 19 06:15 2020_11_19_06_15_10-opentables1
-rw-r--r--. 1 root root   3052 11月 19 06:15 2020_11_19_06_15_10-opentables2
-rw-r--r--. 1 root root   8439 11月 19 06:15 2020_11_19_06_15_10-output
-rw-r--r--. 1 root root  10483 11月 19 06:15 2020_11_19_06_15_10-pmap
-rw-r--r--. 1 root root  20060 11月 19 06:15 2020_11_19_06_15_10-processlist
-rw-r--r--. 1 root root  39388 11月 19 06:15 2020_11_19_06_15_10-procstat
-rw-r--r--. 1 root root  73146 11月 19 06:15 2020_11_19_06_15_10-procvmstat
-rw-r--r--. 1 root root  10055 11月 19 06:15 2020_11_19_06_15_10-ps
-rw-r--r--. 1 root root 332400 11月 19 06:15 2020_11_19_06_15_10-slabinfo
-rw-r--r--. 1 root root    660 11月 19 06:15 2020_11_19_06_15_10-slave-status
-rw-r--r--. 1 root root  32799 11月 19 06:15 2020_11_19_06_15_10-sysctl
-rw-r--r--. 1 root root   9648 11月 19 06:15 2020_11_19_06_15_10-top
-rw-r--r--. 1 root root  72480 11月 19 06:15 2020_11_19_06_15_10-transactions
-rw-r--r--. 1 root root    381 11月 19 06:15 2020_11_19_06_15_10-trigger
-rw-r--r--. 1 root root  12789 11月 19 06:15 2020_11_19_06_15_10-variables
-rw-r--r--. 1 root root   2785 11月 19 06:15 2020_11_19_06_15_10-vmstat
-rw-r--r--. 1 root root    327 11月 19 06:15 2020_11_19_06_15_10-vmstat-overall

データベースを定期的に監視し、指定したトリガーが発動したタイミングで、情報収集を行います。 事前に pt-stalk を仕掛けておくことで、障害の現場を押さえることができます。

例)実行状態のコネクションが100を超えたら何かが起きてるので情報を取る

$ pt-stalk --function status --variable Threads_running --threshold=100

SHOW GLOBAL STATUSSHOW PROCCESSLIST の結果をトリガーの条件とすることができます。 それぞれ、--function status--function processlist と指定します。

--function status では ステータスの値が閾値を超えたら、--function processlist では条件を満たすプロセス(接続)数が閾値を超えたら情報収集が発動します。

カスタムトリガーを設定してロック待ち発生現場を押さえる

--functionシェルスクリプトを指定することで、トリガー条件をカスタマイズできます。シェルスクリプトで定義した trg_plugin 関数がpt-stalkから定期的に呼び出されます。

ロック待ちの時間をトリガーの条件としてみます。

$ cat locktime.sh
trg_plugin() {
   mysql  $EXT_ARGV -N -B -e "SELECT IFNULL((SELECT MAX(now() - trx_wait_started) FROM information_schema.INNODB_TRX), 0) AS wt"
}

locktime.sh が出力する数値が --threshold を超えたら、情報収集が発動します。この例では、3秒以上ロックで待たされているクエリが発生したら、情報収集が走ります。

$ sudo pt-stalk --function locktime.sh --threshold=3

ロック待ちが発生している瞬間に、必ずしもロック待ちの原因となったクエリが実行状態とは限りませんが(未コミットのトランザクションがロックを持っている場合がある)、何度か繰り返し情報を集めていれば pt-stalk の結果から原因を見つけることができるでしょう。