qrnというDBベンチマークツールを作りました。

これは何？

羅列されたクエリを実行するだけのDBベンチマークツールです。今のところMySQLにしか対応していませんが、PostgreSQLへの対応はそんなに難しくないと考えています。

羅列したクエリを実行するだけなので、クエリのログ（MySQLならgeneral log）をほぼそのままテストデータにすることができます。逆に同じクエリを異なるパラメーターで実行するようなことはできないので、そういうむきであればJdbcRunnerなどを使った方がいいと思います。

Installation

https://github.com/winebarrel/qrn/releases から最新版をダウンロードしてください。

Usage

$ echo '{"query":"select 1"}' >> data.jsonl
$ echo '{"query":"select 2"}' >> data.jsonl
$ echo '{"query":"select 3"}' >> data.jsonl
$ qrn -data data.jsonl -dsn root:@/ -nagents 4 -rate 5 -time 10 -histogram
/ run 184 queries (20 qps)

          57µs - 115µs -
         115µs - 173µs -
         173µs - 231µs ---
         231µs - 289µs ------------
         289µs - 346µs ----------
         346µs - 404µs ------------------------------------------
         404µs - 462µs --------------------------------------------------------
         462µs - 520µs ------------------------------
         520µs - 760µs ----------

{
  "Started": "2020-05-13T11:18:14.224848+09:00",
   ...
}

主要なオプション

-dsn DSN
-data テストデータ。JSON Lines形式
-nagents 並列数。1 agentが1コネクション・1 goroutineで実行
-rate 1 agentが1秒に実行するクエリ数の上限。たとえば2 agentでrate 5を指定すると、期待されるQPSは10QPS
-time テストの実行時間（秒）

テストデータ

上記の通りテストデータはJSON Linesです。デフォルトで"query"キーのクエリを実行しますが、-keyオプションで変更できます。クエリ以外のキーは無視します。

テストデータはメモリにロードしないので、大きめのデータでもクライアント側のメモリを圧迫することはないと思います。逆に、10万qpsとか高いスループットが必要な場合、それが足を引っ張る…かも（そこまで試せていないです）。

MySQLの場合、general logをJSON Linesに変換する必要があるので、以下のような変換ツールを作って、logrotateのタイミングでjsonlに変換するようにしています。

/var/log/general.log {
   # ...
    postrotate
        # ...
       /usr/local/bin/mysql-general-log-parser /var/log/general.log-$(date +%Y%m%d%H) | gzip > /var/log/general.log-$(date +%Y%m%d%H).jsonl.gz'
    endscript
}

#!/usr/bin/env ruby
require 'json'

module MysqlGeneralLogParser
  HEADER_REGEXP = /\A(?<time>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+[A-Z]+)\s+(?<id>\d+)\s+(?<command>\w+)\b(?<argument>.*)\z/m

  Chunk = Struct.new('Chunk', :time, :id, :command, :argument)

  def parse(io:)
    chunk = nil

    io.each_line do |line|
      if HEADER_REGEXP =~ line
        yield(chunk) if chunk
        chunk = Chunk.new
        chunk.time = Regexp.last_match[:time]
        chunk.id = Regexp.last_match[:id]
        chunk.command = Regexp.last_match[:command]
        chunk.argument = Regexp.last_match[:argument]
      elsif chunk
        chunk[:argument] << line
      end
    end

    yield(chunk) if chunk
  end
  module_function :parse
end

def main
  MysqlGeneralLogParser.parse(io: ARGF) do |chunk|
    puts chunk.to_h.to_json
  end
end

main

結果の出力

テスト結果はJSONで標準出力に出力されます。

{
  "Started": "2020-05-13T11:18:14.224848+09:00",
  "Finished": "2020-05-13T11:18:24.559912+09:00",
  "Elapsed": 10,
  "Queries": 189,
  "NAgent": 4,
  "Rate": 5,
  "QPS": 18.287694303306097,
  "ExpectedQPS": 20,
  "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
      }
    ]
  }
}

よく見そうな値は

QPS: クライアント側でのスループット
ExpectedQPS: agent数×rateで算出した期待されるQPS。QPSとExpectedQPS乖離が大きいほどキャパオーバーが大きい（と思われる）
Response: 実行した全クエリの応答時間の統計値です。

JSON以外のメッセージについては標準エラー出力に出力されます。

-histogramオプションをつけるとヒストグラムが出力されます

          57µs - 115µs -
         115µs - 173µs -
         173µs - 231µs ---
         231µs - 289µs ------------
         289µs - 346µs ----------
         346µs - 404µs ------------------------------------------
         404µs - 462µs --------------------------------------------------------
         462µs - 520µs ------------------------------
         520µs - 760µs ----------

-htmlオプションをつけると、ヒストグラムのHTMLファイルが出力されます。

f:id:winebarrel:20200515140956p:plain

このへんは https://github.com/jamiealquiza/tachymeter の機能ですね。

モチベーションとか

とあるサービスで使われているDBのベンチマークを取ろうとしたとき、人間がテストデータを書くと、データによって性能の偏りが大きく「サービスで使われているDBのワークロードを再現するのは難しい」「general logをそのままテストデータに使えないかな」と思っていたのと、ほかのベンチマークツールを使っているといろいろいじりたいことが多くて（出力結果など）「自前でベンチマークツールを作っておくと便利そう」と思ったあたりがモチベーションです。

misc

-rateオプションは身の回りで使った感じではまあまあの精度でqpsを制限できているのですが、もう少し厳密にできればいいんですが、逆にそこまで必要かなとも v1.2.0から、まあまあしっかりするようになりました
テストデータはファイル読み込みなのでシャッフルが難しく、いまのところagentごとに読み込み開始位置をランダムにしているだけです。とくに問題はないのですが、もう少し賢くしたいです

追記

スクリプトでのデータ記述に対応しました

https://github.com/winebarrel/qrn#use-script-as-data

$ cat data.js
for (var i = 0; i < 10; i++) {
  query("select " + i);
}

$ qrn  -script data.js -dsn root:@/ -nagents 8 -time 15 -rate 5

追記2

PostgreSQLに対応しました

追記3

general.logをパースしてjsonlにするやつを作りました

github.com

so what

qrnというDBベンチマークツールを作った