500 エラーのしらべかた【DB Lock 編】

11545 ワード
MySQL ロック MySQL テキストリンク

株式会社オズビジョンのユッコ (@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 では想定外のロックがかかることがある、心して実装するべし