株式会社オズビジョンのユッコ (@terra_yucco) です。
最近一部の API でたまーに 500 が出ていましたが、今日晴れて原因を特定できたので、そこまでの過程をメモ書きしていこうと思います。
※タイトルでネタバレしていますが、原因は DB の Lock にありました。
きっかけ
監視及びユーザさんからのお問い合わせで、特定の API が HTTP レスポンスコードに 500 を返しているらしいことがわかりました。
ただし、その API 自体はログなどは残しておらず、どこでどんな原因で 500 になったのかは特定ができていませんでした。
1) とりあえず救う
第 1 フェーズでは、とりあえず別処理でリトライさせることで救うことに。
2) とりあえずエラーを特定する
FW が出力していたログと、導入した New Relic で、原因がある程度絞り込めました。
FW のログ
ERROR - 2019-06-07 02:19:37 --> Query error: Lock wait timeout exceeded; try restarting transaction
New Relic
APM > 該当アプリ > EVENTS - Errors
この Message のリンク先で、実際のエンドポイントがアクセスログと一致していることも確認できました。
また、特定の処理ではなく、共通部分 (insert をするところ) でエラーになっていることを確認できました。
3) 原因を調べる
定期的に show processlist を保存するようなことはしていましたが、それだけではロック先とロック主を正確には特定できないので、以下のような処理を一時的に書きました。
※今から思えば両テーブルを JOIN すればよかった
investigation.sh
# !/bin/bash -u
while [ 1 ]; do
mysql --default-character-set=utf8 --verbose \
-h <endpoint> \
-u <user> -p<pass> -D information_schema \
-e"set session time_zone = 'asia/tokyo'; select now(); select * from innodb_trx\G select * from innodb_lock_waits; select now();" >> /path/to/log/$( date +%Y%m%d_investigation.log )
sleep 300
done
この処理でずっと記録を取るつもりでしたが、落ちた時のことを考えて cron を以下のように設定しました。
flock --timeout=1 は、利用 flock の ver が 0 に対応していなかったための設定で、多重起動をお手軽に抑止するために使いました。
crontab
*/5 * * * * flock --timeout=1 /path/to/lock /path/to/script/investigation.sh
4) クエリを特定する
ログ
以下のようなログが取得できました。
--------------
set session time_zone = 'asia/tokyo'
--------------
--------------
select now()
--------------
now()
2019-06-07 11:42:35
--------------
select * from innodb_trx
--------------
*************************** 1. row ***************************
trx_id: 25511719128
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719128:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979812
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 2. row ***************************
trx_id: 25511719119
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719119:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4980011
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 3. row ***************************
trx_id: 25511719100
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719100:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979976
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 4. row ***************************
trx_id: 25511719086
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:18
trx_requested_lock_id: 25511719086:44:952896:791
trx_wait_started: 2019-06-07 02:42:18
trx_weight: 3
trx_mysql_thread_id: 4979714
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 5. row ***************************
trx_id: 25511716742
trx_state: LOCK WAIT
trx_started: 2019-06-07 02:42:08
trx_requested_lock_id: 25511716742:44:952896:791
trx_wait_started: 2019-06-07 02:42:08
trx_weight: 3
trx_mysql_thread_id: 4979817
trx_query: INSERT INTO table_A (<columns>) VALUES (<values>)
trx_operation_state: inserting
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 376
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 6. row ***************************
trx_id: 25511667859
trx_state: RUNNING
trx_started: 2019-06-07 02:40:38
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 557234
trx_mysql_thread_id: 4974505
trx_query: delete from table_A where a_date < DATE_ADD(NOW(),INTERVAL -180 DAY) and status = 1 order by id limit 500
trx_operation_state: fetching rows
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 556894
trx_lock_memory_bytes: 376
trx_rows_locked: 49379043
trx_rows_modified: 340
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
--------------
select * from innodb_lock_waits
--------------
requesting_trx_id requested_lock_id blocking_trx_id blocking_lock_id
25511719128 25511719128:44:952896:791 25511667859 25511667859:44:952896:791
25511719119 25511719119:44:952896:791 25511667859 25511667859:44:952896:791
25511719100 25511719100:44:952896:791 25511667859 25511667859:44:952896:791
25511719086 25511719086:44:952896:791 25511667859 25511667859:44:952896:791
25511716742 25511716742:44:952896:791 25511667859 25511667859:44:952896:791
--------------
select now()
--------------
now()
2019-06-07 11:42:35
クエリの特定
innodb_lock_waits 側を見ると、ロックを要求しているトランザクションは全部で 5 本あります。
トランザクション ID は
- 25511719128
- 25511719119
- 25511719100
- 25511719086
- 25511716742
ですが全部同じ 25511667859 にブロックされています。
innodb_trx 側を見ると、待っている側は全て insert で、ブロックしている側は delete でした。
不要なデータを消して全体を軽くするはずの処理が、必要なデータの登録をブロックしてしまうとは... 
5) 改修
は、まだできていませんが、削除クエリを発行している側の処理をどうにかすれば対処はできそうです。
付記
削除クエリ側は explain をとってみると一応インデックスを使うようになっているので、なぜロックがかかるのだろうと思いましたが、おそらくこのあたりの挙動なのだろうと思います。
一般に、ロック読み取り、UPDATE、または DELETE では、SQL ステートメントの処理時にスキャンされるすべてのインデックスレコード上に、レコードロックが設定されます。 行を除外する WHERE 条件がステートメント内に存在するかどうかは、関係ありません。InnoDB には正確な WHERE 条件が記憶されませんが、スキャンされたインデックスの範囲は認識されます。
Conclusion
- 500 エラーの原因はきちんと調べるべし
- UPDATE や DELETE では想定外のロックがかかることがある、心して実装するべし