経緯

qrnを作ってからndjsonとかJSON Linesとか呼ばれているJSONを一行にして改行で並べたフォーマット*1がなかなか合理的で便利なことに気づいた。

たとえば

複数行のデータ（SQLなど）をエスケープして一行にまとめられる
jqで加工・フィルタリングしやすい

とか。

一方でcoreutilsみたいな基本的なツールはなかなか見つからなくて、複数ファイルをJSONのキーでJOINしてキーの値でソートする、みたいなことをやろうとすると、ツール探す・ツール作る・sed/awk/ruby/etc..とひと手間かけなくてはいけなくて、なにかそういうツールが欲しいと思っていた。

sortを作る

GUN sortやBSD sortの良いところは、どれだけ大きいファイルの入力しても、時間はかかってもソートしてくれるところで、あれはどうなっているのかなと調べたら外部マージソートを使っている…らしい。

なるほどと思って、Rustでファイルを指定されたキャパシティでチャンクファイルに分けて、ファイルとメモリでマージソートするcrateを愚直に書いてみた。

github.com

このcrateを使ってsortプログラムを書いてみたところ、目論見通りメモリ使用量は抑えつつそこそこの速度でファイルをソートできたので「じゃあ次はndjsonやるか」と意気揚々としていたのだが。

ndjsonをソートする

serde_jsonを使って実装した。

jlsort/main.rs at v0.1.0 · winebarrel/jlsort · GitHub

が…遅い…。219MBぐらいのndjsonのソートで2分半ぐらいかかる。

何が遅いかというと実装していて薄々気づいていたが、比較用の関数内でJSONのデシリアライズを行っており、それが比較のたびに毎行毎行行われるため、処理に時間がかかってしまっている。

jlsort/main.rs at v0.1.0 · winebarrel/jlsort · GitHub

JSONの指定されたキーの値でソートしているので、デシリアライズしないわけにはいかない。

sort_by_cached_keyを使う

そういうソートキーの抽出に馬鹿みたいに時間がかかることを見越してかRustにはすでにsort_by_cached_key()というおあつらえ向きのメソッドが用意されていたので、それを使うように変更する。

ex_merge_sort crateに新しく機能を追加するにはけっこうな改修が必要そうだったので、新しくex_merge_sort_by_keyというcrateを作成した。

github.com

jlsortのライブラリをex_merge_sort_by_keyに変更したところ、現実的な時間でソートが行えるようになった。キャッシュにメモリを使っていることもあって--capacityオプションで指定した値と2倍ぐらい乖離があるが、メモリ使用量を制限できているし、まあ…

--capacity 4gと指定して3.4GBのndjsonをソートしたところ、実行時間が2分24秒、メモリ使用量が8GBいかないくらいだったので、巨大なndjsonをソートするときはまあまあ実用的に使えると思う。

% ls -lah 16xsalaries.ndjson
-rw-r--r--  1 sugawara  staff   3.4G  8 22 16:07 16xsalaries.ndjson

% time -f "Time:%E, Memory:%M KB" jlsort -k to_date -c 4g 16xsalaries.ndjson > /dev/null
Time:2:42.51, Memory:7729932 KB

ちなみにさっきはてブで見つけた超便利そうなCSV/TSV/JSONのスイスアーミーナイフmillerで上記のndjsonをソートしたところ、30GB以上のメモリを使いつつ20分たっても結果は返ってこなかったので、現時点ではjlsortは巨大ndjsonに対してはそこそこ有用なツールな気がする。

さらに速度を上げるためには

これ以上速度を上げるとなるとすっきりとしたやり方は難しそうで、デシリアライズが速いフォーマットにいったんまとめて変換してからソートすることを思いついたが、Apache ArrowとかFlexBuffersを横目に見つつ、めんどくさそうなので手が動いていない。

追記メモ

サンプルのsalaries.ndjsonだとsort -t, -k4でもソートできそうなので手元のMacで少し検証してみた。

sort（たぶんBSD?）

% gtime -f "Time:%E, Memory:%M KB" sort -t, -k4 16xsalaries.ndjson > /dev/null
^CCommand exited with non-zero status 255
Time:15:41.08, Memory:17817920 KB

15分待って結果は返ってこず。

GNU sort

% gtime -f "Time:%E, Memory:%M KB" gsort -t, -k4 16xsalaries.ndjson > /dev/null
Time:4:23.87, Memory:4195664 KB

% gtime -f "Time:%E, Memory:%M KB" gsort -t, -k4 -S $((1024 * 1024 * 16)) 16xsalaries.ndjson > /dev/null
Time:4:45.35, Memory:9277104 KB

% gtime -f "Time:%E, Memory:%M KB" env LANG=C gsort -t, -k4 -S $((1024 * 1024 * 16)) 16xsalaries.ndjson > /dev/null
Time:0:29.30, Memory:9276800 KB

LANG=C速い。

*1:RFCなどにはなっていないと思う cf. Relationship to jsonlines.org · Issue #1 · ndjson/ndjson.github.io · GitHub

2021-07-21

PostgreSQL版のmysqlslapを作った

先日作ったqlapを流用してPostgreSQL版のmysqlslapを作った。

github.com

概ねmysqlslapと同じ動作になる、と思うとりあえず動いたのでv1.0.0をリリース

2021-04-06

qlapでAurora MySQLのdb.r6g.largeとdb.r5.largeの性能を比較した

先日作成したMySQL負荷テストツールのqlapでdb.r6g.largeとdb.r5.largeを比較した。 Aurora MySQLのバージョンは2.09.2。パラメータグループはデフォルト。

作業手順

以下のようなスクリプトでload typeとrateを変えながらテスト。

DSN='root:..@tcp(...:3306)/'

for i in $(seq 50 10 150); do
  qlap -drop-existing-db -dsn "$DSN" -nagents 100 -rate $i -time 120 \
       -auto-generate-sql -auto-generate-sql-load-type mixed -auto-generate-sql-write-number 3000 \
       | tee $i.json

  sleep 15
done

出力されたjsonをjqで集計。

 jq -r '[.StartedAt, .Rate, .QPS, .MedianQPS, .ExpectedQPS, .Response.Time.P95] | @tsv' *.json  | sort -k2 -n  | tr -d Z | tr 'T' ' '

結果

https://gist.github.com/winebarrel/f2bfa781bc28831754b8caec3fc81fa8

スプレッドシート

2021-04-05

mysqlslapのGo版みたいなものを書いた

qrnである程度知見がたまったのでmysqlslapのGo版みたいなものを書いた。

github.com

単純なワークロードのタイプを指定できて、実行するクエリを自動生成できるやつ。生成するクエリはmysqlslapと大体おなじような感じで、以下のような違いがある。

レートリミットがかけられる。逆に「何回クエリを実行」というオプションはない
自動生成するクエリは実行時に生成してメモリにロードしない
- qpsが100万とか1000万とかになったら問題になるかも
結果レポートがJSON
--auto-generate-sql-load-typeのreadはフルスキャンでユースケースが少なそうだったので実装しない

Usage

$ qlap -dsn root:@/ -nagents 3 -rate 100 -time 10 \
    -auto-generate-sql -auto-generate-sql-load-type mixed \
    -number-int-cols 3 -number-char-cols 3

のような感じでコマンドを実行すると

並列数: 3
qpsの上限: 100
テスト時間は10秒
SQLは自動生成
ワークロードはselect(key)とinsertを1:1
intのカラム数: 3
varcharのカラム数: 3

という感じでDBとテーブル作って負荷テストを実行する。

こういうクエリが流れる。

2021-04-05T11:57:18.491610Z        56 Query     CREATE DATABASE `qlap`
2021-04-05T11:57:18.492202Z        56 Query     USE `qlap`
2021-04-05T11:57:18.492378Z        56 Query     CREATE TABLE t1 (id SERIAL, intcol1 INT(32), intcol2 INT(32), intcol3 INT(32),
charcol1 VARCHAR(128), charcol2 VARCHAR(128), charcol3 VARCHAR(128))
2021-04-05T11:57:18.519544Z        56 Query     INSERT INTO t1 VALUES (NULL,953375677,1345621682,2029700311,'JHmVynWl3FRBBtwlDo
xiXUEYEQUSG5YMXbXR23Rns191q0sNlLVxfc9luZ7OLtxROpkYozAZv6A8ZqOWdRrUhzwyqbegL1Fq9Zi7eEbckVbsp8g0pyhkzfbfOwUXHBsX','nBDEKISedaPGFi
JCJj7kbb9J3LhPScGbzXaXDnettwnNBYrfxYyLyUluhawZND12s6PwOwwVWrYlLpeo413y6oMk3mfCyxyF4XZwcGvxjMHMt81vSrVXePUJuXv6OaMP','7YVykjuPnG
ltArdBpy7SS16aJeaxRCzEqeqrkZRPymJTDjkPRzJkJYm6WRLtT0CNTuBW8HNODJmD7W2jz386cg6TcZDbR88pQNXSRXN4HjgNh16wyVRXMu12YxRJM8rU')
2021-04-05T11:57:18.520344Z        56 Query     INSERT INTO t1 VALUES (NULL,411811214,1348318636,684257996,'Tys207WxUhcK1v8jXAs
...
2021-04-05T11:57:18.543225Z        61 Query     SELECT 'agent(0) start: token=bf9716b4-c9c8-4539-9295-701cc46daa21'
2021-04-05T11:57:18.543263Z        62 Query     SELECT 'agent(1) start: token=bf9716b4-c9c8-4539-9295-701cc46daa21'
2021-04-05T11:57:18.543301Z        60 Query     SELECT intcol1,intcol2,intcol3,charcol1,charcol2,charcol3 FROM t1 WHERE id = 60
2021-04-05T11:57:18.543337Z        61 Query     SELECT intcol1,intcol2,intcol3,charcol1,charcol2,charcol3 FROM t1 WHERE id = 77
2021-04-05T11:57:18.543359Z        62 Query     SELECT intcol1,intcol2,intcol3,charcol1,charcol2,charcol3 FROM t1 WHERE id = 8
2021-04-05T11:57:18.553569Z        61 Query     INSERT INTO t1 VALUES (NULL,440504017,1314478656,374979147,'BwukJykBzxQ7GazScoB

結果レポートは以下のような感じ。

{
  "StartedAt": "2021-04-05T20:47:48.122543+09:00",
  "FinishedAt": "2021-04-05T20:47:58.140224+09:00",
  "ElapsedTime": 10,
  "NAgents": 3,
  "Rate": 100,
  "AutoGenerateSql": true,
  "NumberPrePopulatedData": 100,
  "DropExistingDatabase": false,
  "Engine": "",
  "LoadType": "mixed",
  "NumberSecondaryIndexes": 0,
  "CommitRate": 0,
  "NumberIntCols": 3,
  "IntColsIndex": false,
  "NumberCharCols": 3,
  "CharColsIndex": false,
  "Query": "",
  "PreQueries": null,
  "Token": "bf9716b4-c9c8-4539-9295-701cc46daa21",
  "Queries": 2930,
  "QPS": 292.4863396144265,
  "MaxQPS": 305,
  "MinQPS": 202,
  "MedianQPS": 303,
  "ExpectedQPS": 300,
  "Response": {
    "Time": {
      "Cumulative": "1.70378355s",
      "HMean": "499.554µs",
      "Avg": "581.496µs",
      "P50": "535.414µs",
      "P75": "703.491µs",
      "P95": "951.235µs",
      "P99": "1.224525ms",
      "P999": "3.198177ms",
      "Long5p": "1.242647ms",
      "Short5p": "249.39µs",
      "Max": "7.235566ms",
      "Min": "145.575µs",
      "Range": "7.089991ms",
      "StdDev": "274.566µs"
    },
    "Rate": {
      "Second": 1719.7020126177413
    },
    "Samples": 2930,
    "Count": 2930,
    "Histogram": [
      {
        "145µs - 854µs": 2610
      },
      {
        "854µs - 1.563ms": 312
      },
      {
        "1.563ms - 2.272ms": 1
      },
      {
        "2.272ms - 2.981ms": 1
      },
      {
        "2.981ms - 3.69ms": 5
      },
      {
        "3.69ms - 4.399ms": 1
      },
      {
        "4.399ms - 5.108ms": 0
      },
      {
        "5.108ms - 5.817ms": 0
      },
      {
        "5.817ms - 6.526ms": 0
      }
    ]
  }
}

mysqlslapを使っているなら、同じ感覚で使えると思う。

2021-01-17

RailsでMySQLのEXPLAINのやばそうなキーワードに色をつけるやつ

一応、ブログに残しておく。

https://github.com/winebarrel/mysql_casual_explain

2020-10-21

Aurora/RDS用プロダクション→ステージングレプリケーションツールを書いた

github.com

これは何？

Aurora/RDSでプロダクション→ステージングのデータのレプリケーションを行うツールです。

「開発環境のデータをできるだけ本番に近づける - クックパッド開発者ブログ」という記事があって、同じことをAurora/RDSで行うために作りました。

Aurora/RDSでの問題

mysql.rds_set_external_masterを使う場合

レプリケーションフィルターが使えない
- REPLICATE_WILD_IGNORE_TABLEとかが使えないので、ステージングに流したくないテーブルの情報もレプリケーションされます
エラーがスキップしにくい
- mysql.rds_skip_repl_errorはあるんですがslave-skip-errorsの用にまとめて複数のエラーのスキップができないため、event schedulerで毎分呼び出す、みたいな苦しい運用に

DMSを使う場合

いろいろ制限がある
- https://docs.aws.amazon.com/ja_jp/dms/latest/userguide/CHAP_Source.MySQL.html
- AUTO_INCREMENTがマイグレーションされないとか、対応していない方があるとか、いろいろと
なんだかんだでマイグレーションが止まる
- レプリケーションインスタンスのバージョンアップとかディスクの使用量が100%とか
- DMLのマイグレーションは多少の差異を無視できるけど、DDLのエラースキップができないとか、ステージングのスキーマが頻繁に変更されると止まりやすい
- エラーを追うのが結構めんどくさい
- （プロダクション→ステージングのような用途は想定されていない・向いていない、のかも）

binrpt

MySQLのレプリカサーバのようにrowフォーマットのbinlogを読み込んで、SQL（INSERT・UPDATE・DELETE）に変換するか、流れてきたDDLをレプリカに対して実行します。

特徴

テーブルのフィルタリングができる
エラーは無視
接続が切れたら再接続

ラフにレプリケーションをできるようにしてるので、逆に厳密なレプリケーションには向かないです。

misc: go-mysqlがすごい

binlogを読み込むのにgo-mysqlを使っています。

github.com

googleabilityが悪くて「go-mysql」で検索してするとgo-sql-driver/mysqlが出てきたりするんですが

MySQLのクライアントライブラリ
binlogを継続的に読み込む（go-mysql-elasticsearchで使われているようです）
サーバとしてクライアントを受け付けられる

と、ニッチな気がする方向で強力でした。

MySQL Binlog APIのライブラリって、まだMySQL Labsからダウンロードできるんでしたっけ…？ MySQL Binlog APIはベータ版であまり完成度が高くなく、実装がめんどくさかった（日本語まわりでバグもあった）記憶があって「binlogで自前レプリケーションはつらい」という印象だったんですが、go-mysqlはかなりサクッと使えて、わりあい頑丈なので（再接続なども実装済み）驚いてます

追記

go-mysqlのMySQLクライアントとしての動作、メモリまわりが怪しい… あと https://github.com/siddontang/go-mysql/pull/466 これバグってないかな

2020-07-19

SpringOnion: Railsの遅そうなEXPLAINをログ出力するgem

SpringOnionというRailsの遅そうなEXPLAINをログ出力するgemを作りました。

github.com

某kamopoさんのMySQLCasualLog.pmの移植？です。

cf. ふつうのWeb開発者のためのクエリチューニング

以前の移植とは異なって、Arproxyを必要とせず、単体で動きます。

何年前の話だよといわれそうですが、未だにスロークエリと戦っていたりするので…

Rails 3以前に搭載されていた、遅かったクエリを自動的にEXPLAINする機能とは異なり、フィルタで選別されたすべてのクエリに対してEXPLAINを実行し、まずそうなキーワードが出現したらログに出力します。

また、EXPLAINの実行先は開発用のDBだけでなく任意のDBに向けられます（例: ステージング環境のDBなど）。

使い方

GemfileにSpringOnionを追加して

group :development, :test do
  gem 'spring_onion'
end

enviroments/*.rbやinitializersにSpringOnionのEXPLAIN実行先DB情報を記述します。

if Rails.env.development? || Rails.env.test?
  # EXPLAINを実行するDB
  SpringOnion.connection = Mysql2::Client.new(host: 'my-host', ...)

  # ActiveRecordの接続先と同じにする場合は↓な感じで
  #SpringOnion.connection = ActiveRecord::Base.connection.raw_connection
end

SpringOnion.enabled = trueにするかSPRING_ONION_ENABLED=1で、遅そうなEPLAINがログ出力されるようになります。

実行例

#!/usr/bin/env ruby
require 'active_record'
require 'spring_onion'

ActiveRecord::Base.establish_connection(
  adapter:  'mysql2',
  host: 'db',
  username: 'root',
  database: 'sakila'
)

SpringOnion.enabled = true # or `SPRING_ONION_ENABLED=1`
SpringOnion.connection = ActiveRecord::Base.connection.raw_connection
SpringOnion.source_filter_re = //

class Actor < ActiveRecord::Base
  self.table_name = 'actor'
  self.primary_key = 'actor_id'
end

Actor.all.to_a

root@d786c737d8a4:/mnt# bundle exec ./test.rb

SpringOnion   INFO  2020-07-19 03:19:05 +0000   {"sql":"SELECT `actor`.* FROM `actor`","explain":[{"line":1,"select_type":"SIMPLE","table":"actor","partitions":null,"type":"ALL","possible_keys":null,"key":null,"key_len":null,"ref":null,"rows":16,"filtered":100.0,"Extra":null}],"warnings":{"line 1":["slow_type"]},"backtrace":["/mnt/lib/spring_onion/explainer.rb:6:in `execute'","/mnt/test.rb:21:in `<top (required)>'"]}

SPRING_ONION_JSON_PRETTY=1で見やすく。

root@d786c737d8a4:/mnt# SPRING_ONION_JSON_PRETTY=1 bundle exec ./test.rb

SpringOnion   INFO  2020-07-19 03:19:43 +0000   {
  "sql": "SELECT `actor`.* FROM `actor`",
  "explain": [
    {
      "line": 1,
      "select_type": "SIMPLE",
      "table": "actor",
      "partitions": null,
      "type": "ALL",
      "possible_keys": null,
      "key": null,
      "key_len": null,
      "ref": null,
      "rows": 16,
      "filtered": 100.0,
      "Extra": null
    }
  ],
  "warnings": {
    "line 1": [
      "slow_type"
    ]
  },
  "backtrace": [
    "/mnt/lib/spring_onion/explainer.rb:6:in `execute'",
    "/mnt/test.rb:21:in `<top (required)>'"
  ]
}

上記の場合、"type": "ALL"が引っかかってwarningが出ています。

warning

https://github.com/winebarrel/spring_onion/blob/d659b2ca4ef2fda68a08179c9a3c8323299f604c/lib/spring_onion/config.rb#L4-L26

warningにはMySQLCasualLog.pmと同じルールを設定していますが、新しく追加することも可能です。

例えば、rowsが10,000行を超えていたら、warningするなど。

SpringOnion.warnings[:too_many_rows] = lambda do |exp|
  exp['rows'] > 10000
end

フィルタ

SQLとbacktraceのソースコードのパスでフィルタリング可能です。

たとえばSPRING_ONION_SQL_FILTER_RE=actor bundle exec ./test.rbと実行すると、actorが含まれるクエリだけEXPLAINします。

また、SPRING_ONION_SOURCE_FILTER_RE=my_path bundle exec ./test.rbと実行すると、パスにmy_pathが含まれるソースコード経由で実行されたクエリだけEXPLAINします。（デフォルトは/app/）

その他

ログ出力先は標準出力がデフォルトですが、ファイルなどに変更可能です。

SpringOnion.logger = Logger.new('/foo/bar/zoo.log')

so what

ndjsonをソートするプログラムを書いた

経緯

sortを作る

ndjsonをソートする

sort_by_cached_keyを使う

さらに速度を上げるためには

追記メモ

sort（たぶんBSD?）

GNU sort

PostgreSQL版のmysqlslapを作った

qlapでAurora MySQLのdb.r6g.largeとdb.r5.largeの性能を比較した

作業手順

結果

mysqlslapのGo版みたいなものを書いた

Usage

RailsでMySQLのEXPLAINのやばそうなキーワードに色をつけるやつ

Aurora/RDS用プロダクション→ステージングレプリケーションツールを書いた

これは何？

Aurora/RDSでの問題

mysql.rds_set_external_masterを使う場合

DMSを使う場合

binrpt

特徴

misc: go-mysqlがすごい

SpringOnion: Railsの遅そうなEXPLAINをログ出力するgem

使い方

実行例

warning

フィルタ

その他