負荷試験をしていたらMySQLと繋がらなくなってしまった話

皆さんこんにちは、技術統括本部IdMユニットの木村です。

最近は負荷試験とパフォーマンスチューニングを主に行っていて、検証中に起こってしまった事象に関して手元で簡易的に紹介していきます。

負荷試験を行っていた環境とは、RDSのAuroraを利用していたり、細々としたバージョンは違うのですが、ローカル環境でも再現するので紹介します。再現環境としては、macOS(10.15.5), Ruby(2.7.1), Rails(6.0.3.2), MySQL(8.0.20)を利用しています。

まずはRails側の準備していきます。RailsのインストールやMySQLへの接続の方法は割愛します。

今回はuuidを保存するだけの簡単なテーブルをscaffoldで生成してしまいます。

$ rails g scaffold uuid uuid:string

Running via Spring preloader in process 53830
      invoke  active_record
      create    db/migrate/20200625234402_create_uuids.rb
      create    app/models/uuid.rb
      invoke    test_unit
      create      test/models/uuid_test.rb
      create      test/fixtures/uuids.yml
      invoke  resource_route
       route    resources :uuids
      invoke  scaffold_controller
      create    app/controllers/uuids_controller.rb
      invoke    test_unit
      create      test/controllers/uuids_controller_test.rb

db:create, db:migrateを済ませた後にrails consoleで中に入り15万件ほどuuidを登録します。

$ rails db:create
~~~~省略~~~~
$ rails db:migrate
~~~~省略~~~~
$ rails console
irb(main):001:1* 150000.times do
irb(main):002:1*   Uuid.create(uuid: SecureRandom.uuid)
irb(main):003:0> end
~~~省略~~~~
irb(main):004:0> Uuid.count
   (0.4ms)  SET NAMES utf8mb4,  @@SESSION.sql_mode = CONCAT(CONCAT(@@sql_mode, ',STRICT_ALL_TABLES'), ',NO_AUTO_VALUE_ON_ZERO'),  @@SESSION.sql_auto_is_null = 0, @@SESSION.wait_timeout = 2147483
   (14.6ms)  SELECT COUNT(*) FROM `uuids`
=> 150000

15万件登録されていることがわかりました。

この状態でwhere in等を用いてちょっと大きなSELECT文を生成してみます。

irb(main):005:0> Uuid.where(uuid: Uuid.pluck(:uuid))
~~~省略~~~
Traceback (most recent call last):
ActiveRecord::StatementInvalid (Mysql2::Error::ConnectionError: MySQL server has gone away)
irb(main):006:0> 

「MySQLサーバーはお亡くなりになりました」(超意訳)と表示されていて、何やら不穏な空気を感じます。 rails consoleのプロセスはまだ続けて何か実行してみましょう。

irb(main):007:0> Uuid.count
   (0.3ms)  SELECT COUNT(*) FROM `uuids`
Traceback (most recent call last):
        2: from (irb):4
        1: from (irb):5:in `rescue in irb_binding'
ActiveRecord::StatementInvalid (Mysql2::Error: MySQL client is not connected)

なんとMySQLと接続ができなくなってしまいました!どうして!WHERE INを実行しただけなのに!と思うかも知れません。

原因をサクッと言ってしまうとmax_allowed_packetの値が足りてないせいでした。

まずは、そもそもmax_allowed_packetってなんですか?という話をしていきます。

max_allowed_packetは、MySQLのパラメータのうちの一つで、サーバ、クライアント間の通信で1行あたりで送信できる最大のパケットサイズとなります。日本語版のドキュメントはこちらのMySQLの公式ページから確認することが出来ます。

設定値を確認する方法としては、MySQLにログインして show variables like 'max_allowed_packet'と実行してみるとわかります。

以下は、私のローカル環境で実行しているMySQLのmax_allowed_packetの値になります。

mysql> show variables like 'max_allowed_packet';
+--------------------+---------+
| Variable_name      | Value   |
+--------------------+---------+
| max_allowed_packet | 4194304 |
+--------------------+---------+
1 row in set (0.00 sec)

上記から1024*1024*4 = 4194304ということで4MBの値が設定されていることがわかります。

さて、この上限を超えてしまった場合Railsではコネクションエラーが発生してしまいました。

このことはやはり公式ページにも書いてあります。

MySQL クライアントまたは mysqld サーバーが max_allowed_packet バイトより大きいパケットを受け取ると、ER_NET_PACKET_TOO_LARGE エラーが発行され、接続が失われます。一部のクライアントでは、パケットが大きすぎる場合、「クエリー中に MySQL サーバーへの接続が失われました」というエラーを受け取ることもあります。

なるほど、投げたクエリのサイズを計測してみます。

 Uuid.where(uuid: Uuid.pluck(:uuid)).to_sql.bytesize
   (46.5ms)  SELECT `uuids`.`uuid` FROM `uuids`
=> 6000054

大体6M程度ありますね…ちょっと越えてしまっています。

ということでとりあえずmax_allowed_packetの値を大きくしてみます。

8MB(1024* 1024 * 8 = 8388608)に変更してみます。

mysql> set global max_allowed_packet = 8388608;
Query OK, 0 rows affected (0.00 sec)
mysql> exit

# 再ログイン後
mysql> show variables like 'max_allowed_packet';
+--------------------+---------+
| Variable_name      | Value   |
+--------------------+---------+
| max_allowed_packet | 8388608 |
+--------------------+---------+
1 row in set (0.00 sec)

set global構文を使うとMySQLを再起動するまで一時的に変数を定義することが出来ます。もし再起動後も設定値を変更したい場合は、my.cnfへの記載を忘れずに行いましょう。

もう一度Railsから実行してみましょう。ここで大事なのは一回 rails consoleもログアウトすることです

irb(main):001:0> Uuid.where(uuid: Uuid.pluck(:uuid))
~~~中略~~~
1807293-219b-46d0-87b2-fed117ad0a1c', '96c0cc9f-8e0f-4c07-998a-b4a7a3bab5b7', 'bd163a7d-6618-43b4-889c-92882298d86c', '6a222060-9bf9-4c74-95af-757c0c405d9b', '08691d4b-e214-482c-82e9-bdabfab309a1', 'bbd346f7-fb89-4a80-a30d-3d55555e5da4', 'd10ad215-04a0-4ef6-9d41-fb5531687464', '9cba5cc2-d04a-40bb-8274-4263a8d8cdc8', '01a87cf2-452c-4a10-aaaf-6f8040e65287', '968ee62e-df8c-4e02-8ded-74380e0109aa', '8cb80b63-1764-4334-ba52-b51335fa6cf2', 'abbafb8a-b580-49bd-8a5f-f4d7ab39cfdf') LIMIT 11
=> #<ActiveRecord::Relation [#<Uuid id: 1, uuid: "a204ee51-e89e-42b5-b83a-3135d9e21a64", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 2, uuid: "fafb1f26-0f3f-42b1-a376-53bf7839d9ed", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 3, uuid: "c8e30944-fd92-48b5-abf9-510302b369bf", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 4, uuid: "876d8de8-ed94-4bab-b602-26ad964f8452", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 5, uuid: "980a9016-4de0-4f38-8e3c-baa3e4c46a6e", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 6, uuid: "4ce87bfb-b057-440c-ae58-20b31343a7a6", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 7, uuid: "ad8c3386-d735-4f38-837c-d3a7d053ecfb", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 8, uuid: "dd002bd6-bf22-44ab-89d9-7b3b6765629a", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 9, uuid: "63780a97-2a22-4396-9a0a-685b6797367c", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, #<Uuid id: 10, uuid: "64ace006-0a97-4d97-8867-c6d8d3cbb314", created_at: "2020-06-26 02:29:33", updated_at: "2020-06-26 02:29:33">, ...]>

というわけで問題なく実行できる様になったことがわかりました。今回は負荷試験という側面から考えて、max_allowed_packetの値を大きくしました。

ただし、実際にこれが本番環境で発生してしまった場合に対応策として考えられるのは、以下の2つだと思います。

  • max_allowed_packetの上限を緩和する(一次対応)
  • クエリを適切な範囲で分割する(恒久対応)

max_allowed_packetの上限を緩和するのは今回のように非常に単純でわかりやすいのですが、誤って大きなクエリを投げしまった場合にメモリーの使用率に影響が出る場合があるのでインフラ環境と相談して注意して変更する必要があります。

クエリを適切な範囲で分割する場合は、業務ロジックなどに影響が出ないように注意をして行う必要があります。

どちらも一長一短ある感じなのですが、本番でもし発生してしまった場合は一旦max_allowed_packetを引き上げてクエリの分割を検討する事になると思います。今回の負荷試験では、インフラ環境に相当の余裕があったのと、max_allowed_packetの上限を引きあげた際の挙動を確認する意味でも引き上げて試してみることにしました。

ただ、突然この様な事象が発生してしまうと引き上げても大丈夫なのか判断に悩む事になってしまうため、皆さんも是非一度作成したサービスがユーザやレコードを増やした場合に、どこまで耐えられるのか一度試してみてはいかがでしょうか。

オプティムではインフラ環境を日々改善していき、より良いアプリケーションを一緒に提供していけるエンジニアを募集しています。

www.optim.co.jp