最近はZX-25Rが気になっている菅原です。4気筒250ccといえば、以前バリオス2に乗っていたんですが、あれもよく回るよいバイクでした。足つきの良さが懐かしいです。

この記事では、クエリログを使ったAurora MySQLの負荷テストの話を書きます。

MySQLの負荷テスト

サービスに使われているデータベースは、Webサーバと比べて自動的なスケールアップ・スケールアウトが簡単ではないためキャパシティプランニングは非常に重要です。サービスへのアクセス増による負荷増大の結果、急激に性能が低下するためなるべく事前にキャパシティを把握しておきたいところです。

クックパッドではサービスのデータベースとして主にAurora MySQLを利用しているのですが、キャパシティを把握するための負荷テストには以前から苦労してきました。

1. シナリオを書くのが大変

サービスで使われているデータベースの負荷テストのシナリオを人間が書こうとすると、あるシナリオでは極端に性能がよくなり、またあるシナリオでは極端に性能が悪くなるということがあり、実際のサービスを模してシナリオを書くのが非常に困難で、意味のある負荷テストをすることが難しいことが多くありました。

2. 大きなサイズのシナリオを実行する負荷テストツールがない

データベースの負荷テストツールは大きく２種類あり、一つはTCP-xのような決められたモデルを実行するツールで、もう一つは任意のシナリオを実行するツールです。TCP-xを実行するツールはクックパッドのサービスの性質とは異なるため、任意のシナリオを実行するツールを用いて負荷テストを行っていたのですが、MySQLで任意のクエリやシナリオを実行するツールはあまり多くなく、私の知る限りは以下の通りでした。

クエリログを使ったMySQLの負荷テスト

今までは上記のツールを使って負荷テストを行っていました（特にJdbcRunnerはとても便利でした！）。

しかし、既存のツールにはいくつか不満がありました。

1. 基本的にシナリオを人間が書く必要がある＆大きなシナリオを読み込むのにメモリが必要

mysqlslapを除き任意のシナリオを実行することができるのですが、当然、人間がDSLやJavaScriptでシナリオを書く必要があり、前述の通り、実際のサービスに沿ったシナリオを書くことが困難でした。また、シナリオはメモリに読み込まれるため、大量の異なるデータをテストデータにしようとすると、クライアント側にデータを読み込むための大量のメモリが必要になりました。

2. 結果のデータの解析が難しい

負荷テストの実行結果について、平均応答時間だけではなく、中央値やヒストグラムなどが欲しいのですが、あまり多くの情報は出力されなく、出力されるデータは単純なテキストであったため、データをパースして結果を集計するにもやや手間がかかりました。

Webサーバの場合、アクセスログをテストデータとして負荷テストを行うことが多いと思います。MySQLに関しても同じようなことができないかと以前から考えていたのですが

データが大きく（GB単位）、メモリに乗せるのが難しい
データの羅列をDSLやJavaScriptに変換するのに手間がかかる

という問題がありました。

それらの問題を解決するためqrnという負荷テストツールを新たに作成しました。

qrn

データベース負荷テストツールqrnの大きな特徴は次の通りです。

JSON Linesをテストデータとする
テストデータは逐次ディスクから読み取り、全体をメモリにはロードしない
テスト結果をJSONで細かく出力する

たとえば、以下のデータを

{"query":"select 1"}
{"query":"select 2"}
{"query":"select 3"}

4並列・5 qps/userで10秒間実行する場合、コマンドと出力結果は次のようになります。

$ qrn -data data.jsonl -dsn root:@/ -nagents 4 -rate 5 -time 10
00:07 | 4 agents / run 184 queries (20 qps)
{
  "DSN": "root:@/",
  "Files": [
    "data.jsonl"
  ],
  "Started": "2020-05-13T11:18:14.224848+09:00",
  "Finished": "2020-05-13T11:18:24.559912+09:00",
  "Elapsed": 10,
  "Queries": 189,
  "NAgents": 4,
  "Rate": 5,
  "QPS": 18.287694303306097,
  "MaxQPS": 21,
  "MinQPS": 18,
  "MedianQPS": 19,
  "ExpectedQPS": 20,
  "LoopCount": 15894,
  "Response": {
    "Time": {
      "Cumulative": "78.389862ms",
      "HMean": "392.47µs",
      "Avg": "414.761µs",
      "P50": "418.565µs",
      "P75": "462.099µs",
      "P95": "532.099µs",
      "P99": "735.68µs",
      "P999": "760.585µs",
      "Long5p": "632.823µs",
      "Short5p": "218.38µs",
      "Max": "760.585µs",
      "Min": "182.384µs",
      "Range": "578.201µs",
      "StdDev": "90.961µs"
    },
    "Rate": {
      "Second": 2411.0260584461803
    },
    "Samples": 189,
    "Count": 189,
    "Histogram": [
      {
        "57µs - 115µs": 1
      },
      {
        "115µs - 173µs": 1
      },
      {
        "173µs - 231µs": 4
      },
      {
        "231µs - 289µs": 14
      },
      {
        "289µs - 346µs": 12
      },
      {
        "346µs - 404µs": 48
      },
      {
        "404µs - 462µs": 63
      },
      {
        "462µs - 520µs": 34
      },
      {
        "520µs - 760µs": 12
      }
    ]
  },
  "Token": "a579889e-97f9-4fd1-8b33-93ab2c78e6ad"
}

クエリログのテストデータ化

MySQLのクエリログ（general log）をqrnのテストデータとして使用する場合、general logをJSON Linesに変換する必要があります。そのためのツールgenlogも新たに作成しました。

以下のようなgeneral logをJSON Linesに変換できます。

2020-05-27T05:03:27.500301Z   11 Query   SET @@sql_log_bin=off
2020-05-27T05:03:27.543379Z   11 Query  select @@session.tx_read_only
2020-05-27T05:03:27.683485Z   11 Query  COMMIT

$ genlog general.log # or `cat general.log | genlog`
{"Time":"2020-05-27T05:03:27.500301Z","Id":"11","Command":"Query","Argument":"SET @@sql_log_bin=off"}
{"Time":"2020-05-27T05:03:27.543379Z","Id":"11","Command":"Query","Argument":"select @@session.tx_read_only"}
{"Time":"2020-05-27T05:03:27.683485Z","Id":"11","Command":"Query","Argument":"COMMIT"}

また、クエリログからSELECT文のみを抽出したい場合は、jqを使ってフィルタリングします。

$ jq -rc 'select(.Command == "Query") | select(.Argument | test("select" ; "i"))' general.log.jsonl > mysql-general-select.jsonl

general logの出力については負荷増大の懸念から、今まで避けているところがあったのですが、実際に出力してみるとそれほどCPU使用率は上がらなかったため、現在では必要であれば出力するようにしています。

ただしAurora MySQLでgeneral logをCloudWatch Logsにエクスポートした場合は、それなりにCPU使用率が上がるため、Aurora MySQLのgeneral logを使用する場合にはエクスポートせずに、DBインスタンスの各ログをダウンロードするようにしました（ダウンロード用のツールも作成しました）。

テスト結果の集計

テスト結果は前述のようにJSONで出力しているのですが、どのクエリがどの程度応答時間を占めているのかを分析したい場合、負荷テストを実施しているテスト用データベースのlong_query_timeを0にして、すべてのクエリのスロークエリログを出力し、それをpt-query-digestで分析するということを行っています。

ウェイトを占めるクエリがわかるため、実際にサービスでスロークエリログが出力する前に重いクエリを改善するというようなことに役立ちます。

まとめ

データベースの負荷テストツールを自作することにより、クエリログをテストデータとした負荷テストが行えるようになり、Webサーバのような感覚で簡単にデータベースの負荷テストを行えるようになりました。これにより、事前のデータベースのキャパシティ把握が容易になったと考えています。

今はまだ手動で負荷テストを実施しているので、今後は負荷テストの自動化を目指したいところです。