Aurora MySQL を使っていたら異様にパフォーマンスが落ちた話

はじめに

KLab Engineer Advent Calendar 2019 の １２日目の記事です。
特に結論が出ているものではなく、Auroraをいろいろ検証していた際に遭遇した事例紹介となります

環境

エンジンバージョン：5.6.10a
インスタンスクラス：db.r5.large

きっかけ

Auroraのストレージ設計としては履歴の塊なので、書き換えをし続けるとストレージ消費がどんどん増えていくのではないか？と考えて以下のようなワークロードを回してみました。

やってみた

1 . ガチャを引いては殆どを売却（削除）するようなプレイを想定し、以下のようなテーブルを作成して実験を行いました。

CREATE TABLE aurora_disk_test.heavy_write_test_table (
    id BIGINT PRIMARY KEY AUTO_INCREMENT,
    message VARCHAR(511) -- データ量が多いテーブルの簡略化イメージで多めの文字列型
);

2 . このテーブルにまず８００万レコードを登録し、その後１０００レコードの DELETE & INSERT を繰り返してみました。

MYSQL_CMD="mysql -h${DBHOST} -u${DBUSER} -p${DBPASS}"
TABLE_NAME="aurora_disk_test.heavy_write_test_table"

# INIT 約800万レコード登録
INIT_QUERY="BEGIN; DELETE FROM ${TABLE_NAME};"
INIT_QUERY="${INIT_QUERY} INSERT INTO ${TABLE_NAME} (message) VALUES (SUBSTRING(MD5(RAND()), 1, 511));"
for _ in $(seq 1 23);
do
  INIT_QUERY="${INIT_QUERY} INSERT INTO ${TABLE_NAME} (message) SELECT SUBSTRING(MD5(RAND()), 1, 511) FROM ${TABLE_NAME};"
done
INIT_QUERY="${INIT_QUERY} COMMIT;"
${MYSQL_CMD} -e "${INIT_QUERY}"


# DELETE & INSERT
for i in $(seq 1 100000);
do
  echo "${i}: $(date)"
  # 古いレコードから1000件まとめてDELETE
  DELETE_TARGETS=$(${MYSQL_CMD} -e "SELECT id FROM ${TABLE_NAME} ORDER BY id LIMIT 1000" -N | tr "\n" "," | sed -e "s/,\$//")
  LOOP_QUERY="DELETE FROM ${TABLE_NAME} WHERE id IN (${DELETE_TARGETS});"

  # 1件ずつ1000レコードINSERT
  for _ in $(seq 1 1000);
  do
    LOOP_QUERY="${LOOP_QUERY} INSERT INTO ${TABLE_NAME} (message) VALUES (SUBSTRING(MD5(RAND()), 1, 511));"
  done

  ${MYSQL_CMD} -e "${LOOP_QUERY}"
done

これは、グラフのように最初増え続けましたが途中で増加が止まりました。

※：再検証時のCloudWatchでのグラフ

3 . さらに極端な例として800万レコード全てで DELETE & INSERT を繰り返してみました。

MYSQL_CMD="mysql -h${DBHOST} -u${DBUSER} -p${DBPASS}"
TABLE_NAME="aurora_disk_test.heavy_write_test_table"

QUERY="DELETE FROM ${TABLE_NAME};"
QUERY="${QUERY} INSERT INTO ${TABLE_NAME} (message) VALUES (SUBSTRING(MD5(RAND()), 1, 511));"

# DELETE&INSERTするクエリの作成
# auto commit を利用して、それぞれのクエリを別々のトランザクションとして実行する
for _ in $(seq 1 23);
do
  QUERY="${QUERY} INSERT INTO ${TABLE_NAME} (message) SELECT SUBSTRING(MD5(RAND()), 1, 511) FROM ${TABLE_NAME};"
done

# クエリのループ実行
for i in $(seq 1 100);
do
  echo "${i}: $(date)"
  ${MYSQL_CMD} -e "${QUERY}"
done

おきたこと

だんだんと１セットの実行にかかる時間が伸びていきました。

9: Tue Nov 26 13:59:44 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.
10: Tue Nov 26 18:22:28 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.
11: Tue Nov 26 22:56:14 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.
12: Wed Nov 27 03:42:15 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.
13: Wed Nov 27 08:43:18 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.
14: Wed Nov 27 13:56:24 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.
15: Wed Nov 27 19:21:04 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.
16: Thu Nov 28 00:51:18 UTC 2019
mysql: [Warning] Using a password on the command line interface can be insecure.

時間がかかっていたので途中でループを停止させてテーブルのカウントを取得してみました。

mysql> SELECT count(id) FROM aurora_disk_test.heavy_write_test_table;
+-----------+
| count(id) |
+-----------+
|       512 |
+-----------+
1 row in set (12 min 16.16 sec)

カウント件数は少ないのにクエリ実行にかなりの時間がかかる事態に遭遇しました。

まとめ

負荷試験などで毎度大量のDELETE&INSERTしていると同じ事態に遭遇することがあるかもしれません。
後日再度カウントのクエリを実行した際には0秒でクエリの結果が出たため、バイナリログのような段階に大量に残っている段階だと処理スピードに影響しているのでしょうか。
あらためて時間を作って TRUNCATE での場合など実験していってみたいと思います。

同様の事例や原因をご存知の方がいらっしゃいましたら、教えていただければありがたいです。