こんにちは、Platform Team の荒引 (@a_bicky) です。前回は続・何でも屋になっている SRE 的なチームから責務を分離するまでの道のり 〜新設チームでオンコール体制を構築するまで〜という話を書いたんですが、今回は Repro の運用に 7 年以上携わる中で私が遭遇して印象的だった Aurora MySQL 絡みのトラブルについて紹介します。
Aurora MySQL が詰まってデータ処理のスループットが下がるとか、API のレスポンスが遅くなるとか、ALTER TABLE する度にアプリケーションエラーが発生するとか、胃が痛くなる胸が熱くなる話が多いので、Aurora MySQL を利用していなくても楽しんでいただけるのではないかと思います。Aurora MySQL を利用している方であれば参考になる情報もあるでしょうし、通常の MySQL にも適用可能な話もあります。
数年以上前の話ばかりで、当時の調査メモからしかメトリクスが取得できず、見づらいスクリーンショットもありますがご了承ください。
スロークエリが記録されているわけじゃないのに突然 MySQL の負荷が上がる（2018 年）
事象
ある日のお昼頃、急激に Aurora DB インスタンスの CPU 使用率が 4 倍になり、それが 30 分程度続きました。
CPU 使用率が上がる場合、真っ先にスロークエリを疑うわけですが、上記のスクリーンショットのとおり、スロークエリは全く増えていないように見えました。 たまたまかと思われましたが、翌日も同じ時間帯に負荷が高くなり、同時間帯に実行されているバッチにも心当たりはなく、謎は深まるばかりでした。
昨日、今日とほぼ同じ時間帯に 30 分程度 MySQL が高負荷状態になってて、それを考えると定期バッチの影響しか考えられないんだけど、心当たりがなくて謎過ぎる…。CPU 使用率以外は大きくメトリクスが変化しているものもないし。負荷試験で全力で負荷かけないと起きないレベルなんだけどなぁ…。
— Takeshi Arabiki (@a_bicky) September 4, 2018
もう何年も前のことなのでうろ覚えですが、負荷の上がり方的にスロークエリが原因としか考えられず、スロークエリとして記録される条件を調べていたら min_examined_row_limit というパラメータがあることを知ったと記憶しています。このパラメータは、InnoDB が走査した行数がこの値を下回る場合にスロークエリとして記録しないようにするもので、当時の Repro では 100,000 に設定されていました。
試しに min_examined_row_limit を 100 にしてみると、翌日には CPU 使用率とスロークエリの数に明確な相関が現れ、調査は大きく前進しました。
あとは 12 時台（UTC 3 時台）のスロークエリログをダウンロードし、ログを次のような Ruby スクリプトで 10 分単位に分割した上で mysqldumpslow を使って*1スロークエリの変化について調査しました。
current_minute = 0 out = File.open('mysql-slowquery.log.2018-09-05.04', 'w') File.foreach(ARGV[0]).each do |line| next if line.start_with?('/rdsdbbin/') || line.start_with?('Tcp port:') || line.start_with?('Time') if line =~ /# Time: 180905 3:(\d+):/ minute = $1.to_i if minute >= current_minute + 10 current_minute += 10 out.close out = File.open("mysql-slowquery.log.2018-09-05.#{current_minute}", 'w') end end out.puts line end out.close
for f in mysql-slowquery.log.2018-09-05.*; do mysqldumpslow -s c -t 3 $f > $f.summary done
その結果、Repro を導入しているアプリの起動時にリクエストされる API で取得しているデータのテーブルに、適切なインデックスが設定されていないせいで、必要以上のレコードを走査していることがわかりました。13 時頃に負荷が減っているのは、お昼休みが終わって特定のアプリからのリクエストが減ったからだったようですね。
対応
当該テーブルに適切なインデックスを追加することで事態は収束しました。
Reader が原因不明の再起動をしてその後しばらく writer の latency が高い状態が続く（2019 年）
事象
ある日、Reader が原因不明の再起動をし、その直後から writer の insert latency が 7 倍程度になるなど、writer のパフォーマンスが著しく悪化した状態が長時間続きました。一度だけであれば良かったのですが、それが複数回起きました。writer のパフォーマンスが悪化している間は、SDK が収集したデータを処理しているアプリケーションが遅延する一方で、writer のパフォーマンスが元に戻るまでただただ見守ることしかできませんでした。
Aurora の reader が何故か再起動して、その後 writer のパフォーマンスが著しく落ちる（もしかしたら順序逆かも）という現象がここ 2 週間で 2 回起きてるんだけど reader が再起動するのも原因わからないし、writer のパフォーマンス落ちるのも原因わからなくてとても辛い
— Takeshi Arabiki (@a_bicky) November 11, 2019
メトリクスを確認してみたところ、毎回次の点が共通していました。
- reader が再起動している
- 再起動する前に凄い勢いで freeable memory が減っていっている
- mutex spin waits が激減している
- Rw-excl spin rounds / RW-excl spin waits が 2 倍程度になっている
- commit latency 等の latency が上昇する
- replication lag が上昇する
- volume read iops が増えている
- 1, 2 日経つと元に戻る
以下は writer のメトリクスですが、縦線のタイミングでメトリクスの傾向が急激に変化し、その状態が 1 日以上続いていることが伺えます。
毎回 reader が謎の再起動をしていたことから、reader の再起動によって buffer pool が空になり、DB インスタンスとクラスターストレージ間のネットワーク通信やクラスターストレージの IOPS が増えて writer のパフォーマンスにも影響を与えたのではないかなど、仮説を立てて AWS のサポートに問い合わせたところ、以下のような素晴らしい回答を得ることができました。
情報をいただきました 11/11 の状況を中心に調査を進めました。 その結果、具体的な状態をお伝えすることができず恐れ入りますが、内部情報より Reader の再起動が発生するまでの間、ロールバックセグメント領域が増え続けていたことが確認されました。 また、Reader の再起動後に、ロールバックセグメントの解放が始まっていたこと確認しております。
ロールバックセグメントはレコードのデータが更新された際に、古いデータが必要になる際に備えて情報を残しておくための領域でございます。例えば、あるトランザクションで値が更新された時に、ロールバックする場合や、また別のトランザクションから古いデータを読み取る必要が生じる時などに備えて情報が残されます。
ロールバックセグメントはトランザクションが終了することで不要になるため、不要になった際に解放処理が実行されますが、サイズが大きくなっている場合には解放に時間を要します。 また解放処理の際に発生する I/O が各処理のレイテンシーに影響することがございます。
（中略）
また、Reader で一度検索した値を再度読み込む必要があることもございますため、Reader のトランザクションが長くなった際にも、ロールバックセグメントが増え続ける場合もございます。
今回のお客様の DB インスタンスの状態を確認したところ、11/05 10:16 JST ごろからロールバックセグメントが拡張され、Reader が再起動した 11/11 19:20 JST ごろより解放が始まり、11/13 14:31 JST ごろに完了したことを確認しております。
再起動以降にコミットレイテンシーの値が大きくなっているため、このロールバックセグメントの解放処理の影響を受けた可能性が主に考えられます。11/5 の再起動時に関しましてもロールバックセグメントの増加および再起動後の解放、またコミットレイテンシーの増加という流れは同様でございました。
（中略）
また、一つの可能性ではございますが、コミットに時間がかかることにより、ロックを取得した状態がより長くなることで、別のトランザクションのロック待ちが増えることは考えられます。合わせて、show engine innodb status などよりご確認されている spin wait などの状態が変化した点に関しましても、一連の長いトランザクションが実行されていたこと、またロールバックセグメントの解放処理が実行されていることに関連している可能性を考えております。
なお、ロールバックセグメントの長さにつきましては、show engine innodb status コマンドの "History list length" の値にてご確認いただけます。
早期復旧するために何かできることがないかも質問したのですが、未然に防ぐ以外にはできることがないようでした。
ロールバックセグメントは DB インスタンスに紐づくものではなく、クラスター共通のものでございます。そのため、DB インスタンスの削除追加などにより、ロールバックセグメントの解放を早めたりすることはできず、また IO 性能の調整なども対応することができないため、完了までお待ちいただく必要がございます。 そのため、ロールバックセグメントが肥大化しないようにトランザクションをより小さくすることをご検討ください。
対応
AWS のサポートからアドバイスいただいたように、ロールバックセグメント（Datadog だと mysql.innodb.history_list_length）を監視するモニターを追加しました。
これにより、reader が再起動するほど長時間走り続けるクエリは発見次第 kill するようにし、同様の事象が起きることを未然に防ぐことができるようになりました。たしか原因は Redash から reader に発行されたクエリだったと記憶しています。
なお、モニターを追加して 2 年ほど経つと、毎週のようにアラートが鳴るようになったため、社内周知の上で max_execution_time を設定しました。これによって、今では一定時間経つとクエリが強制終了するようにしています。
ALTER TABLE 実行中のテーブルに reader からアクセスするとコネクションが切断される（2021 年）
事象
ALTER TABLE を実行すると、実行直後に MySQL クライアントのコネクションが切断されて大量のエラーが起きることがありました。
Aurora MySQL 5.7 にした後から 1 秒もかからない altar table を本番環境で実行するとそのテーブルを参照している処理で Lost connection to MySQL server during query になるということが 3 回連続で続いてるんだが、開発環境で試しても再現しなくて困ってる
— Takeshi Arabiki (@a_bicky) January 8, 2021
alter が altar になっていて恥ずかしい…。
開発環境の Aurora MySQL クラスターには reader が存在しなかったので、再現確認は困難を極めたのですが、reader を追加したところ再現に成功しました。 どうも、reader の存在する Aurora MySQL クラスターに対して ALTER TABLE を実行すると、実行直後に ALTER TABLE の対象テーブルを参照する SQL を reader に対して発行している MySQL クライアントのコネクションが切断される（FIN が返ってくる）ようでした。
「これはバグに違いない！」と再現手順をまとめて AWS のサポートに問い合わせたところ、以下の仕様を教えてもらいました。
DDL statements that run on the primary instance might interrupt database connections on the associated Aurora Replicas. If an Aurora Replica connection is actively using a database object, such as a table, and that object is modified on the primary instance using a DDL statement, the Aurora Replica connection is interrupted.
cf. Replication with Amazon Aurora MySQL - Amazon Aurora
余談ですが、似たような問題として、ALTER TABLE を実行すると reader で一時的に ALTER TABLE 対象のテーブルが見えなくなって "Error 1146: Table '...' doesn't exist" というエラーが出る問題もあったりします。こちらはバグのようで、Aurora MySQL 3.05.0 で直っているようです。
Fixed an issue where the reader instance is unable to open a table, with ERROR 1146. This issue occurs when executing certain types of online Data Definition Language (DDL) while the INPLACE algorithm is being used on the writer instance.
対応
アプリケーション側で、コネクションエラーが起きた場合に一度だけリトライするようにしました。例えば、Rails アプリケーションに関しては次のようなモンキーパッチを当てました。
# frozen_string_literal: true module ActiveRecord module RetryOnLostConnection def execute(*args) # Don't retry the query in a transaction because using a transaction in a reader session # might mean enabling repeatable read. # If this method retries the query, the result of the same query can change as follow: # 1. reader: BEGIN # 2. reader: SELECT * FROM apps WHERE id = 1 (name is 'old name') # 3. writer: UPDATE apps SET name = 'new name' WHERE id = 1 # 4. reader: Lost connection and retry (starting another session) # 5. SELECT * FROM apps WHERE id = 1 (name is 'new name') if current_transaction.open? || ActiveRecord::Base.connection_handler == ActiveRecord::Base.connection_handlers[ActiveRecord::Base.writing_role] super else first_try = true begin super rescue ActiveRecord::StatementInvalid => e if first_try && e.message.include?("Lost connection to MySQL server") logger.warn(%Q{Reconnect to MySQL due to "#{e}" (#{e.class})}) ActiveRecord::Base.connection.reconnect! first_try = false retry end raise end end end end end ActiveSupport.on_load :active_record do class ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter prepend ActiveRecord::RetryOnLostConnection end end
上記のモンキーパッチは当時私が導入したもので、今では色んな人の手によってより洗練されたものになっています。
特定のアプリケーションからの突発的な大量のクエリによって CPU 使用率が瞬間的に 2 倍程度に跳ね上がる（2022 年）
事象
特定のアプリケーションからのクエリによって reader の CPU 使用率が瞬間的に跳ね上がる問題に長らく悩まされていたんですが、そろそろ本格的に手を入れなければならない水準になっていました。
同時間帯はスロークエリが増えていることもわかります。
発行されているクエリは次のようなもので、既に (col1, col2) の複合インデックスが存在するため、インデックスを追加することによる改善は見込めそうにありませんでした。
SELECT `col1`, `col2`, ... FROM `tbl` WHERE ( col1 = 1234 AND col2 = 'abcd' ) OR ( col1 = 1234 AND col2 = 'bcde' ) OR ( col1 = 1234 AND col2 = 'cdef' ) OR ( col1 = 2345 AND col2 = 'defg' ) ... ;
参照の局所性はなく、キャッシュによってクエリの発行数を減らすことも難しそうでした。
そこで、WHERE 句で OR の代わりに IN を使うことでパースにかかる負荷を下げられるかもしれないという仮説の下、次のような Ruby スクリプトを使ってスロークエリに記録された SQL を変換してみました。
sql = "SELECT `col1`, `col2`, ... FROM `tbl` WHERE ( col1 = 1234 AND col2 = 'abcd' ) OR ( col1 = 1234 AND col2 = 'bcde' ) OR ( col1 = 1234 AND col2 = 'cdef' ) OR ( col1 = 2345 AND col2 = 'defg' ) ...;" col1_to_col2s = Hash.new { |h, k| h[k] = [] } sql.scan(/col1 = (\d+) AND col2 = ('[^']+')/).each do |col1, col2| col1_to_col2s[col1] << col2 end condition = col1_to_col2s.map do |col1, col2s| "(col1 = #{col1} AND col2 IN (#{col2s.join(',')}))" end.join("\n OR ") refined_sql = <<SQL SELECT `col1`, `col2`, ... FROM `tbl` WHERE #{condition} ; SQL puts refined_sql
多くの場合、col1 には同一の値が指定されることから、上記のスクリプトでは 、(col1 = ... AND col2 IN (...)) OR (col1 = ... AND col2 IN (...)) という条件に変換しています。
パースにかかっている時間は 第130回 クエリをプロファイリングしてみる | gihyo.jp を参考に、SET profiling = 1 を実行した上で計測しました。
Before（OR を使ったクエリの結果）
MySQL [repro]> source before.sql -- snip -- 1710 rows in set (0.18 sec) MySQL [repro]> show profile all; +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+--------------------------------+----------------------+-------------+ | Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+--------------------------------+----------------------+-------------+ | starting | 0.007078 | 0.112000 | 0.052000 | 1251 | 3 | 0 | 0 | 0 | 0 | 0 | 661 | 0 | NULL | NULL | NULL | | checking permissions | 0.000065 | 0.000000 | 0.000000 | 6 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 887 | | Opening tables | 0.000036 | 0.004000 | 0.000000 | 5 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 5842 | | init | 0.002775 | 0.036000 | 0.016000 | 460 | 1 | 0 | 0 | 0 | 0 | 0 | 122 | 0 | handle_query | sql_select.cc | 159 | | System lock | 0.000037 | 0.000000 | 0.000000 | 4 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | mysql_lock_tables | lock.cc | 323 | | optimizing | 0.004192 | 0.076000 | 0.016000 | 725 | 2 | 0 | 0 | 0 | 0 | 0 | 479 | 0 | optimize | sql_optimizer.cc | 203 | | statistics | 0.009252 | 0.172000 | 0.000000 | 1539 | 4 | 0 | 0 | 0 | 0 | 0 | 872 | 0 | optimize | sql_optimizer.cc | 425 | | preparing | 0.003458 | 0.068000 | 0.000000 | 576 | 2 | 0 | 0 | 0 | 0 | 0 | 107 | 0 | optimize | sql_optimizer.cc | 533 | | executing | 0.000052 | 0.000000 | 0.000000 | 12 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 145 | | Sending data | 0.148573 | 3.008000 | 0.472000 | 26582 | 109 | 0 | 0 | 0 | 0 | 0 | 63 | 0 | exec | sql_executor.cc | 221 | | end | 0.000072 | 0.000000 | 0.000000 | 5 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 237 | | query end | 0.000055 | 0.004000 | 0.000000 | 10 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command_internal | sql_parse.cc | 7411 | | closing tables | 0.000057 | 0.000000 | 0.000000 | 13 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command_internal | sql_parse.cc | 7506 | | freeing items | 0.001523 | 0.044000 | 0.020000 | 345 | 7 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 8167 | | cleaned up | 0.000044 | 0.000000 | 0.000000 | 8 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | do_post_processing | oscar_scheduler_cons | 919 | | logging slow query | 0.000137 | 0.004000 | 0.000000 | 25 | 0 | 0 | 216 | 0 | 0 | 0 | 0 | 0 | log_slow_do | log.cc | 1735 | | cleaning up | 0.004483 | 0.112000 | 0.068000 | 905 | 36 | 0 | 0 | 0 | 0 | 0 | 8 | 0 | finish_work_4_dispatch_4_thd | sql_parse.cc | 3104 | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+--------------------------------+----------------------+-------------+ 17 rows in set, 1 warning (0.00 sec)
After（IN を使ったクエリの結果）
MySQL [repro]> source after.sql -- snip -- 1710 rows in set (0.03 sec) MySQL [repro]> show profile all; +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+--------------------------------+----------------------+-------------+ | Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+--------------------------------+----------------------+-------------+ | starting | 0.001150 | 0.008000 | 0.016000 | 201 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL | | checking permissions | 0.000043 | 0.004000 | 0.000000 | 8 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 887 | | Opening tables | 0.000037 | 0.000000 | 0.000000 | 2 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 5842 | | init | 0.001159 | 0.028000 | 0.000000 | 193 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 159 | | System lock | 0.000041 | 0.004000 | 0.000000 | 9 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 323 | | optimizing | 0.000209 | 0.004000 | 0.000000 | 36 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 203 | | statistics | 0.003038 | 0.068000 | 0.000000 | 557 | 1 | 0 | 0 | 0 | 0 | 0 | 3 | 0 | optimize | sql_optimizer.cc | 425 | | preparing | 0.000196 | 0.004000 | 0.000000 | 50 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 533 | | executing | 0.000041 | 0.000000 | 0.000000 | 8 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 145 | | Sending data | 0.032076 | 0.712000 | 0.092000 | 5959 | 15 | 0 | 0 | 0 | 0 | 0 | 58 | 0 | exec | sql_executor.cc | 221 | | end | 0.000062 | 0.000000 | 0.000000 | 13 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc | 237 | | query end | 0.000058 | 0.000000 | 0.000000 | 5 | 0 | 0 | 0 | 0 | 0 | 0 | 5 | 0 | mysql_execute_command_internal | sql_parse.cc | 7411 | | closing tables | 0.000045 | 0.000000 | 0.000000 | 10 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | mysql_execute_command_internal | sql_parse.cc | 7506 | | freeing items | 0.000225 | 0.008000 | 0.000000 | 39 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 8167 | | cleaned up | 0.000038 | 0.000000 | 0.000000 | 4 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | do_post_processing | oscar_scheduler_cons | 919 | | cleaning up | 0.000058 | 0.004000 | 0.000000 | 7 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | finish_work_4_dispatch_4_thd | sql_parse.cc | 3104 | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+--------------------------------+----------------------+-------------+ 16 rows in set, 1 warning (0.00 sec)
optimizing や statistics が減るのはパース処理と関係してそうなのでわからなくもないですが、Sending data が減るのは謎過ぎます…。
Aurora MySQL compatibleでwhere (a = 1 AND b = 1) OR (a = 1 AND b = 2) OR (a = 2 AND b = 1) ... みたいのをwhere (a = 1 AND b IN (1, 2, ...)) OR (a = 2 AND b in (...))に変えてprofile取るとSending dataのCPU_userが下がって謎すぎる…。optimizingとかstatisticsで減るのはわからなくはない
— Takeshi Arabiki (@a_bicky) May 16, 2022
何はともあれ、何度計測しても同じ傾向だったので、負荷が減る可能性はありそうでした。
なお、実行計画はどちらも同じで次のようなものでした。
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: tbl
partitions: NULL
type: range
possible_keys: unique_index_tbl_on_col1_and_col2,index_tbl_on_col1_and_col3
key: unique_index_tbl_on_col1_and_col2
key_len: 206
ref: NULL
rows: 1710
filtered: 100.00
Extra: Using index condition; Using MRR
1 row in set, 1 warning (0.02 sec)
対応
前述の結果を当該アプリケーションの担当チームに伝えて、アプリケーションから発行するクエリを変更してもらいました。その結果、次のように CPU 使用率が 10 ポイント程度下がるだけの効果が得られました。
DMLLatency が上がって API で 5XX が大量に発生する（2019 年）
事象
ある日、API サーバで 5XX*2 が大量に発生しました。CPU 使用率が下がっていることから、アプリケーションサーバの高負荷が原因ではなさそうでした。
Rails の API のアクセスログを見ると、duration に対して db がかなりの割合を占めていることから、MySQL へのアクセスで詰まっていることは明白でした。
一方、MySQL のメトリクスを見ても各種 latency が上がっていること以外に怪しいものはなく、latency が上がっている原因までは特定できませんでした。同時間帯のメトリクスは次のとおりです。
当時の調査メモには次のように記されています。
CloudWatch で確認できるメトリクスや Volume Read IOPS, Volume Write IOPS を見る限りでは各種 Latency が上がったこととに起因すると思われる変化が主で、他には FeeableMemory, FreeLocalStorage が少し怪しい変化をしている程度。
毎日 16:30 頃と 22:30 頃に決まって MySQL (Aurora) が詰まる（DMLLatency が上がる）現象が起きていて謎
— Takeshi Arabiki (@a_bicky) 2019年3月28日
クエリがめちゃくちゃ増えて CPU 使用率上がって DMLLatency が上がるとか、IOPS が上がって DMLLatency が上がるとかならわかるんだけど、DMLLatency が上がるのに伴ってアプリケーションからのリクエスト数が減って CPU 使用率も下がってるという…
— Takeshi Arabiki (@a_bicky) 2019年3月28日
原因が全くわからず頭を抱えていたところ、毎日同じ時間帯に API のレスポンスが悪化したり、SDK が収集したデータを処理しているアプリケーションのスループットが落ちたりしていることから、定期バッチが怪しいと当たりを付けました。そして、ログを確認してみると、一度に 100 万以上のレコードを挿入していることが判明しました。
2019-04-07 13:34:02.551 +0000 [INFO] (0001:transaction): SQL: INSERT INTO ... -- snip -- 2019-04-07 13:35:44.562 +0000 [INFO] (0001:transaction): > 102.01 seconds (4,674,401 rows) -- snip -- 2019-04-07 13:49:39.078 +0000 [INFO] (0001:transaction): SQL: INSERT INTO ... -- snip -- 2019-04-07 13:51:27.285 +0000 [INFO] (0001:transaction): > 108.21 seconds (3,955,907 rows)
この処理は embulk-output-mysql の merge mode によって行われているもので、一時テーブルに挿入対象レコードを溜めてから最後に INSERT INTO <target_table> SELECT * FROM <intermediate_table_1> UNION ALL SELECT * FROM <intermediate_table_2> UNION ALL ... ON DUPLICATE KEY UPDATE ... でまとめて挿入していることを表していました。
元々は merge_direct mode を使用していて、その mode であれば挿入対象テーブルに対して INSERT INTO ... ON DUPLICATE KEY UPDATE ... で一定数のレコードを都度挿入するんですが、Some records will be lost during retrying in MySQL · Issue #241 · embulk/embulk-output-jdbc の対応で merge mode を使うように変更していたところでした。
この issue は、embulk-output-mysql がレコードを挿入する際にデッドロックが発生してリトライすると、デッドロック発生時に挿入しようとしたレコードが欠落するという問題で、レコードの欠落は許容できない問題でした。
対応
前述のとおり、merge mode にすると様々なアプリケーションに影響が出るし、merge_direct mode にするとデッドロック発生時にレコードが欠落します。そこで、embulk-output-mysql の retry_limit に 0 を設定し、デッドロックが起きた場合にリトライすることなく異常終了させ、Embulk を実行しているワークフローエンジン（Rukawa）の方でリトライさせることにしました。
batch_size を調整することで一度に挿入するレコード数を減らしたり、max_threads を少くすることで並列数を減らしたりすることでデッドロックが起きにくくする対応も同時に入れました。
これによって API がバッチの影響を受けることなく安定してレスポンスを返せるようになりました。
最後に
以上、私がこれまでに遭遇した Aurora MySQL 関連のトラブルについてご紹介しました。今回は Aurora MySQL に関するものしか紹介しませんでしたが、Repro では Kafka、Cassandra、Trino など比較的珍しいミドルウェアも使われており、それらの安定化も日々行っています。 Kafka Streams はレコードをどのように処理しているのかからもわかるように、必要であればライブラリのコードを読んでアプリケーションを安定化させることもあります。そんな刺激的な環境に興味を持たれた方は、是非以下のページからご応募ください！
- Systems Architect | サービスのコアを支えるハイトラフィックなストリーミングデータパイプラインを開発・運用したいエンジニア募集 - Repro株式会社
- SRE | 高トラフィックな分散システムを安定稼働し、顧客に信頼を提供し続けるSREを募集！ - Repro株式会社
*1:今なら pt-query-digest を使んですが当時は知らなかったみたいです
*2:当時の記録は残ってないですが、おそらく Rails アプリケーションの backlog が溢れて nginx が 502 を返していたのだと思います
