この記事は、株式会社カオナビ Advent Calendar 2023 の3日目です。

はじめに

株式会社カオナビの高橋(@kunit)です。

今回は MySQL バージョンアップ(5.7 -> 8.0) で起きた問題とそれに対してどのように対処したのかを書いていこうと思います。

何が起きたのか

MySQL 5.7 から 8.0 にバージョンアップをするにあたって、CI およびローカル環境でテストができるように MySQL 8.0 のイメージを作成し、それをつかって各機能の担当者にテストを開始してもらっていたのですが、以下のような事が起きました。

接続を MySQL 5.7 から 8.0 に切り替えただけでテストの時間が3倍くらいかかるようになった

そこを変更するだけで3倍遅くなるってやばいぞということで報告してくれた担当者と同じテストを自分でも実施してみると再現性があり、それが以下のどの環境でも発生していることが確認できました。

CI
ローカル環境(Apple Silicon MacBook Pro)
ローカル環境(Intel MacBook Pro)

特定の環境でしか起きていないのであれば、環境依存という可能性もあったのですが、どの環境でもことごとく遅くなっていたので、MySQL 8.0 としてなにか遅くなる原因があるのでは？と調査を開始しました。

原因

今回色々調べた結果、以下のことが原因だということがわかりました。

MySQL 8.0 はクラッシュリカバリに利用する REDO ログ関連で変更がかかっており、この影響で大幅に遅くなった
- 特に TRUNCATE の実行で顕著にでており、MySQL 5.7 だと一瞬で終わる TRUNCATE に結構時間がかかるようになった
MySQL 8.0 はバイナリログをデフォルトで出力するようになっていて、この影響でも少し遅くなっている
- MySQL 5.7 はデフォルトでは出力しない

これらのログはテストを実行する際には特に必要ないので、ログの出力を止めることにより MySQL 5.7 と同じような速度でテストできるようになりました。

※注この記事を公開した後、REDOログを止めなくても MySQL 5.7 の速度にある程度近づける方法を教えていただけたので、その方法も追記しています。

※追記1

今回CIやローカルでのテストの実行時ということで REDO ログの出力を止めていますが、本番では有効にしておくようにしてください。

REDOログの無効化に関して、本家マニュアルでも以下のように書かれています。

この機能は、新しい MySQL インスタンスへのデータのロードのみを目的としています。本番システムで redo ロギングを無効にしないでください。 redo ロギングが無効化されている間はサーバーを停止して再起動できますが、redo ロギングが無効化されている間に予期しないサーバーストップページが発生すると、データが失われ、インスタンスが破損する可能性があります。

※追記2

今回の件、もしかしてログ関連なのでは？と気づいたのは、 @yoku0825 さんからのこの返信のおかげでした。本当にありがとうございました。

計測

REDOログ、バイナリログの2つを止めるとどれくらい影響があるのかを簡単な環境をつくって計測してみたいと思います。

計測環境

以下のようなコンテナ環境をローカルで作って試してみました。(ローカル環境は M2 MacBook Pro)

それぞれ自前の Dockerfile からイメージを build していますが、以下のようなものとなっています。

cli は debian:bullseye-slim をベースにして mysql client をインストールしただけのもの
mysql57/mysql80 は debian:bullseye-slim をベースにして、ソースから make したもの
- 独自に make したのはイメージの作り方の差異が速度差にならないようにするため
- 公式のものは MySQL 5.7 と 8.0 とで platform およびベースイメージを同じにできない

compose.yaml

services:
  cli:
    build: ./docker/cli
    image: kunit/adventcalendar2023-cli
    working_dir: /home/cli
    volumes:
      - .:/home/cli

  mysql57:
    build: ./docker/mysql57
    image: kunit/adventcalendar2023-mysql57
    environment:
      MYSQL_ROOT_PASSWORD: root
      MYSQL_DATABASE: test
      MYSQL_USER: test
      MYSQL_PASSWORD: test
    volumes:
      - ./docker/mysql57/conf.d/my.cnf:/etc/my.cnf
      - ./docker/mysql57/docker-entrypoint-initdb.d:/docker-entrypoint-initdb.d
      - mysql57_data:/var/lib/mysql
    ports:
      - "3306:3306"

  mysql80:
    build: ./docker/mysql80
    image: kunit/adventcalendar2023-mysql80
    environment:
      MYSQL_ROOT_PASSWORD: root
      MYSQL_DATABASE: test
      MYSQL_USER: test
      MYSQL_PASSWORD: test
    volumes:
      - ./docker/mysql80/conf.d/my.cnf:/etc/my.cnf
      - ./docker/mysql80/docker-entrypoint-initdb.d:/docker-entrypoint-initdb.d
      - mysql80_data:/var/lib/mysql
    ports:
      - "3307:3306"

volumes:
  mysql57_data:
  mysql80_data:

設定ファイル

初期の my.cnf は文字コードを設定しただけのシンプルなもので、両バージョンとも同じ内容となっています。

my.cnf

[mysqld]
character-set-server=utf8mb4
collation-server=utf8mb4_general_ci

[client]
default-character-set=utf8mb4

今回テストで使用するテーブル

両方ともで以下のテーブルを使ってテストをします。

特に凝ったことはしておらず、名前が違うだけで同じカラムを持つテーブルを5つ準備しました。

/docker-entrypoint-initdb.d/1_create_tables.sql

use test;

CREATE TABLE test1 (
  id int(11) unsigned NOT NULL AUTO_INCREMENT,
  name varchar(128) NOT NULL,
  email varchar(128) NOT NULL,
  test_type tinyint(3) unsigned NOT NULL,
  created_at datetime NOT NULL,
  updated_at datetime NOT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci;

CREATE TABLE test2 (
  id int(11) unsigned NOT NULL AUTO_INCREMENT,
  name varchar(128) NOT NULL,
  email varchar(128) NOT NULL,
  test_type tinyint(3) unsigned NOT NULL,
  created_at datetime NOT NULL,
  updated_at datetime NOT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci;

CREATE TABLE test3 (
  id int(11) unsigned NOT NULL AUTO_INCREMENT,
  name varchar(128) NOT NULL,
  email varchar(128) NOT NULL,
  test_type tinyint(3) unsigned NOT NULL,
  created_at datetime NOT NULL,
  updated_at datetime NOT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci;

CREATE TABLE test4 (
  id int(11) unsigned NOT NULL AUTO_INCREMENT,
  name varchar(128) NOT NULL,
  email varchar(128) NOT NULL,
  test_type tinyint(3) unsigned NOT NULL,
  created_at datetime NOT NULL,
  updated_at datetime NOT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci;

CREATE TABLE test5 (
  id int(11) unsigned NOT NULL AUTO_INCREMENT,
  name varchar(128) NOT NULL,
  email varchar(128) NOT NULL,
  test_type tinyint(3) unsigned NOT NULL,
  created_at datetime NOT NULL,
  updated_at datetime NOT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci;

計測で使用したスクリプト

実際の環境で遅くなったのはPHPであったりGoで書かれたテストファイルだったのですが、今回はそういう言語の影響を完全に排除するために、mysqlクライアントからのSQL文の実行のみでの計測としました。

データのINSERTを行う
TRUNCATEを行う
これを100回実行する

test.sh

#!/bin/bash

HOST=$1

for i in {1..100}
do
  mysql -h $HOST -u test -ptest test < test_sql/insert.sql
  mysql -h $HOST -u test -ptest test < test_sql/truncate.sql
done

SQLファイルは以下のものとなります。

test_sql/insert.sql

INSERT INTO test1 (name, email, test_type, created_at, updated_at) VALUES ('test1', 'test1@example.com', 1, NOW(), NOW());
INSERT INTO test2 (name, email, test_type, created_at, updated_at) VALUES ('test2', 'test2@example.com', 2, NOW(), NOW());
INSERT INTO test3 (name, email, test_type, created_at, updated_at) VALUES ('test3', 'test3@example.com', 3, NOW(), NOW());
INSERT INTO test4 (name, email, test_type, created_at, updated_at) VALUES ('test4', 'test4@example.com', 4, NOW(), NOW());
INSERT INTO test5 (name, email, test_type, created_at, updated_at) VALUES ('test5', 'test5@example.com', 5, NOW(), NOW());

test_sql/truncate.sql

TRUNCATE test1;
TRUNCATE test2;
TRUNCATE test3;
TRUNCATE test4;
TRUNCATE test5;

MySQL 5.7 の計測結果

cli コンテナから MySQL 5.7 に接続して計測した結果は以下の通りで、大体3秒弱くらいの時間となっています。これが基準になります。

root@dd743bfcb63f:/home/cli# time /bin/bash test.sh mysql57

real    0m2.966s
user    0m0.529s
sys     0m0.047s
root@dd743bfcb63f:/home/cli# time /bin/bash test.sh mysql57

real    0m2.931s
user    0m0.502s
sys     0m0.062s
root@dd743bfcb63f:/home/cli# time /bin/bash test.sh mysql57

real    0m2.819s
user    0m0.509s
sys     0m0.052s
root@dd743bfcb63f:/home/cli#

MySQL 8.0 の計測結果

MySQL 5.7 と同じ設定で起動しただけの場合

MySQL 8.0 を MySQL 5.7 と同じ設定で起動しただけの場合の結果は以下の通りで、8秒前後かかっています。

MySQL 5.7 の3秒弱に比べると、2.7倍くらいかかっています。

root@dd743bfcb63f:/home/cli# time /bin/bash test.sh mysql80

real    0m7.892s
user    0m0.581s
sys     0m0.136s
root@dd743bfcb63f:/home/cli# time /bin/bash test.sh mysql80

real    0m8.019s
user    0m0.565s
sys     0m0.133s
root@dd743bfcb63f:/home/cli# time /bin/bash test.sh mysql80

real    0m7.875s
user    0m0.597s
sys     0m0.102s
root@dd743bfcb63f:/home/cli#

バイナリログを止めた場合

設定ファイルを以下のように変更してみます。バイナリログは設定ファイル以外であれば、起動オプションに --skip-log-bin をつけるという方法でも同様のことができます。

my.cnf

[mysqld]
character-set-server=utf8mb4
collation-server=utf8mb4_general_ci

# バイナリログを止める
skip-log-bin

[client]
default-character-set=utf8mb4

バイナリログを止めた状態で計測すると7秒前後となり、1割ほど速くなりましたが、まだ MySQL 5.7 の2倍くらいかかっています。

root@38caf5c342d9:/home/cli# time /bin/bash test.sh mysql80

real    0m6.607s
user    0m0.551s
sys     0m0.141s
root@38caf5c342d9:/home/cli# time /bin/bash test.sh mysql80

real    0m7.082s
user    0m0.604s
sys     0m0.123s
root@38caf5c342d9:/home/cli# time /bin/bash test.sh mysql80

real    0m6.430s
user    0m0.572s
sys     0m0.131s
root@38caf5c342d9:/home/cli#

REDOログを止めた場合

REDOログは my.cnf や起動オプションでは止めることができず、以下のSQL文を実行する必要があります。

ALTER INSTANCE DISABLE INNODB REDO_LOG;

なお、以下の文を実行すると現在の状況が確認できます。

SHOW STATUS LIKE 'Innodb_redo_log_enabled';

REDOログを止めた状態で計測すると3秒弱になり、MySQL 5.7 とほぼ同等になりました。

root@99fabf2bda4e:/home/cli# time /bin/bash test.sh mysql80

real    0m2.725s
user    0m0.481s
sys     0m0.113s
root@99fabf2bda4e:/home/cli# time /bin/bash test.sh mysql80

real    0m2.985s
user    0m0.571s
sys     0m0.086s
root@99fabf2bda4e:/home/cli# time /bin/bash test.sh mysql80

real    0m2.735s
user    0m0.523s
sys     0m0.074s
root@99fabf2bda4e:/home/cli#

両方のログを止めた場合

最後に両方のログを止めた場合も計測しておきます。

今回の計測では MySQL 5.7 よりも速くなりましたが、実際の社内環境では MySQL 5.7 よりも少し遅いくらいという状態になっています。

root@c594d6a0f147:/home/cli# time /bin/bash test.sh mysql80

real    0m2.260s
user    0m0.533s
sys     0m0.091s
root@c594d6a0f147:/home/cli# time /bin/bash test.sh mysql80

real    0m2.210s
user    0m0.536s
sys     0m0.076s
root@c594d6a0f147:/home/cli# time /bin/bash test.sh mysql80

real    0m2.477s
user    0m0.556s
sys     0m0.110s
root@c594d6a0f147:/home/cli#

(追記) innodb_log_writer_threads を OFF にした場合

この記事を公開した後にこのような情報をいただきました。

ということで、 my.cnf に innodb_log_writer_threads=OFF の設定を追加して計測してみると 4.4秒くらいになり、元の8秒に比べると45％高速になり、MySQL 5.7 に対して 2.7倍かかっていたところから 1.5倍くらいのところまできました。

root@6adfa1bbad21:/home/cli# time /bin/bash test.sh mysql80

real    0m4.514s
user    0m0.483s
sys     0m0.124s
root@6adfa1bbad21:/home/cli# time /bin/bash test.sh mysql80

real    0m4.445s
user    0m0.537s
sys     0m0.064s
root@6adfa1bbad21:/home/cli# time /bin/bash test.sh mysql80

real    0m4.392s
user    0m0.502s
sys     0m0.096s
root@6adfa1bbad21:/home/cli#

バイナリログを止めつつ、 innodb_log_writer_threads=OFF も設定すると 3.6秒になり、MySQL 5.7 に比べて 1.2倍くらいかかるというところまで短縮できました。

root@82d75749aaa1:/home/cli# time /bin/bash test.sh mysql80

real    0m3.682s
user    0m0.480s
sys     0m0.108s
root@82d75749aaa1:/home/cli# time /bin/bash test.sh mysql80

real    0m3.612s
user    0m0.513s
sys     0m0.079s
root@82d75749aaa1:/home/cli# time /bin/bash test.sh mysql80

real    0m3.665s
user    0m0.493s
sys     0m0.106s
root@82d75749aaa1:/home/cli#

REDOログの出力をとめなくてもここまで短縮できることがわかりました。 @yoku0825さん、情報ありがとうございました。

最後に

今回は、MySQL 5.7 から 8.0 へのバージョンアップを進めるにあたって発生した問題と対処方法をご紹介しました。

これから MySQL のバージョンアップをされる方々の参考になれば幸いです。

株式会社カオナビでは一緒に働く仲間を募集しています。カジュアル面談も行っていますので、ご興味がある方は気軽にお声がけください。

MySQL 5.7 から 8.0 にしたらテストが激遅になった