Aurora MySQLのローカルストレージ不足で事故ったログ

日次でDB内のとあるテーブルのデータ全件をBigQueryに同期するバッチがあって
RDS for MySQLからデータをselectしていたが、先日Aurora MySQL(5.6.10)に移行した直後から急にバッチがこけはじめた。

原因調査

バッチは使用しているMySQLクライアントの設定値(3600秒)に従ってタイムアウトし落ちていた。

バッチの実行時間帯のCloud Watchメトリクスを確認してみると
AuroraのCPU使用率が30分間ほど平常値から外れて高くなっていた。

しかしバッチを実行しているEC2のネットワークインプットメトリックは特に変動がなく、Auroraからselectした結果を受け取れてなさそうなことも同時にわかった。

DBへの接続がタイムアウトするまでに1時間かかっているのに、selectによるCPU負荷が30分程度しか上昇していないので
クエリが何らかの理由で異常終了している可能性を疑い始める。

空きローカルストレージの急減少

引き続きメトリクスを眺めているとバッチ実行時間帯にAuroraの「空きローカルストレージ」が急減少していることも発見。
数十GBあるローカルストレージが、最も少ないタイミングで残り500MBまで減っているので枯渇している可能性を疑う。

ここまででクエリが正常に終了しているかもわからなかったので、確認用に同じバッチを再実行しshow processlistでクエリの実行状態を確認した。

バッチ実行初期は Sending dataというステータスだったクエリが、30分ほどで cleaned upというステータスに変わっていた。

参考:

テンポラリーテーブルの破損

クエリのステータスが変わったあたりのタイミングで以下のエラーログがAuroraのerror.logに出力されていた。どうやらテンポラリーテーブルが壊れているっぽい。

2018-08-01 06:43:45 8918 [ERROR] /rdsdbbin/oscar/bin/mysqld: Incorrect key file for table '/rdsdbdata/tmp/#sql_22d6_0.MYI'; try to repair it
2018-08-01 06:43:45 8918 [ERROR] Got an error from unknown thread, /opt/brazil-pkg-cache/packages/OscarMysql/OscarMysql-1.0.201259.0/RHEL5_64/generic-flavor/src/oscar_mysql/mysql/storage/myisam/mi_write.c:223

これはCloudWatchで「空きローカルストレージ」が500MBを記録した45秒後に出力されているログ。この時点でローカルストレージの枯渇により、テンポラリーテーブルが破損している可能性が非常に高いと思い始める。

MySQL 5.7.5以前は internal_tmp_disk_storage_engineのデフォルト設定がMyISAMでテンポラリーテーブルがディスク容量を食いつぶすとクエリが途中終了されるようで、今回起こった「ローカルストレージの減少(枯渇)」x「クエリ結果がクライアント側に送信されない」現象と一致する。

参考: