소개

KLab Engineer Advent Calendar 2019의 12일째 기사입니다.
특히 결론이 나오고 있는 것이 아니라, 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. 이 테이블에 우선 800만 레코드를 등록하고, 그 후 1000 레코드의 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

일어난 일

점점 1 세트의 실행에 걸리는 시간이 늘어나 갔습니다.

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에서의 경우 등 실험해 가고 싶습니다.

비슷한 사례와 원인을 아시는 분이 계시면 가르쳐 주시면 감사합니다.