Percona Playback で 本番 MySQLに流れているクエリを試験環境でリプレイする
データベースのバージョンアップの際、アプリケーションの網羅的なテストが可能であれば良いのですが、どうしても難しいケースがあります。 そのような場合、リプレイツールで本番環境に流れているクエリを、試験環境でリプレイ（再現）し、動作確認を取る方法もあります。
リプレイツールを探す
MySQL の クエリ リプレイができるツールを探してみました。
Percona Tookit に pt-log-player というツールが含まれていたのですが、いつのまにか、なくなってました。。。 2013年にリリースされた、percona tookit 2.2 で削除されてしまったようです。
We removed pt-query-advisor, pt-tcp-model, pt-trend, and pt-log-player. Granted, no tool is ever really gone: if you need one of these tools, get it from 2.1. pt-log-player is now superseded by Percona Playback (http://www.percona.com/doc/percona-playback/). pt-query-advisor was removed so that we can focus our efforts on its online counterpart instead: https://tools.percona.com/query-advisor. The other tools were special projects that were not widely used.
https://www.percona.com/doc/percona-toolkit/LATEST/release_notes.html
pt-log-player is now superseded by Percona Playback とあるように Percona Playback が代替のツールとなるようです。
このツールも、最後のコミットが3年前と、メンテされてない雰囲気が漂っていますが・・・試してみます。
Percona Playback を インストールする
MySQL 8.0 環境でも問題なくビルドできました。セーフ。
$ git clone https://github.com/Percona-Lab/query-playback.git $ sudo yum -y install tbb tbb-devel cmake boost boost-devel gcc gcc-c++ doxygen mysql-community-devel mysql-community-libs-compat $ cd query-playback $ mkdir build_dir $ cd build_dir $ cmake -DMYSQL_LIB=/usr/lib64/mysql/libmysqlclient.so -DCMAKE_BUILD_TYPE=RelWithDebInfo .. $ make $ make test $ make install
$ ls /usr/local/bin/percona-playback /usr/local/bin/percona-playback
動かしてみる
Percona Playback はスロークエリログか一般クエリログをもとにリプレイします。 とりあえず、クエリを１つだけ含んだ、スロークエリログを食わせてみます。
$ sudo cat /var/lib/mysql/localhost-slow.log /usr/sbin/mysqld, Version: 8.0.21 (MySQL Community Server - GPL). started with: Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock Time Id Command Argument # Time: 2020-08-30T08:15:17.706789Z # User@Host: root[root] @ localhost [] Id: 16 # Query_time: 0.002868 Lock_time: 0.000708 Rows_sent: 1 Rows_examined: 559 SET timestamp=1598775317; SELECT COUNT(*) FROM information_schema.tables; # Time: 2020-08-30T08:15:18.795306Z # User@Host: root[root] @ localhost [] Id: 16 # Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 559 SET timestamp=1598775318; # administrator command: Quit;
リプレイ先とユーザ、パスワード等をシンプルに指定するだけです。
$ sudo /usr/local/bin/percona-playback --query-log-file /var/lib/mysql/localhost-slow.log --mysql-host 192.168.123.12 --mysql-user appuser --mysql-password Pass@123 --mysql-schema mysql --mysql-max-retries=0 Database Plugin: libmysqlclient Running... Finished reading log entries Start sorting log entries Finished sorting log entries Finished preprocessing - starting playback... thread 16 slower query was run in 35623 microseconds instead of 2868 <-- SELECT COUNT(*) FROM information_schema.tables; --> Error Report finished Detailed Report ---------------- SELECTs : 1 queries (0 faster, 1 slower) INSERTs : 0 queries (0 faster, 0 slower) UPDATEs : 0 queries (0 faster, 0 slower) DELETEs : 0 queries (0 faster, 0 slower) REPLACEs : 0 queries (0 faster, 0 slower) DROPs : 0 queries (0 faster, 0 slower) Report ------ Executed 1 queries Spent 00:00:00.035623 executing queries versus an expected 00:00:00.002868 time. 0 queries were quicker than expected, 1 were slower A total of 0 queries had errors. Expected 1 rows, got 1 (a difference of 0) Number of queries where number of rows differed: 0. Average of 1.00 queries per connection (1 connections).
SELECTs : 1 queries (0 faster, 1 slower) とリプレイ先で遅くなったクエリの数をレポートしてくれます。
その他、Expected 1 rows, got 1 (a difference of 0) 結果セットの件数比較もあります。
わざとエラーにしてみる
リプレイ先でわざとエラーになるようなクエリを投げて、エラーが検知できることを確認してみます。
リプレイ先では sql_mode に ONLY_FULL_GROUP_BY を設定して、SQLがエラーになるようにしています。
$ sudo /usr/local/bin/percona-playback --query-log-file /var/lib/mysql/localhost-slow.log --mysql-host 192.168.123.12 --mysql-user appuser --mysql-password Pass@123 --mysql-schema mysql --mysql-max-retries=0 Database Plugin: libmysqlclient Running... Finished reading log entries Start sorting log entries Finished sorting log entries Finished preprocessing - starting playback... Error during query: Expression #2 of SELECT list is not in GROUP BY clause and contains nonaggregated column 'tables.TABLE_NAME' which is not functionally dependent on columns in GROUP BY clause; this is incompatible with sql_mode=only_full_group_by, number of tries 1 of 1 thread 24 slower query was run in 60973 microseconds instead of 13559 <-- SELECT COUNT(*), table_name FROM information_schema.tables GROUP BY table_schema; --> Error query: SELECT COUNT(*), table_name FROM information_schema.tables GROUP BY table_schema; Connection 24 Rows Sent: 0 != expected 5 for query: SELECT COUNT(*), table_name FROM information_schema.tables GROUP BY table_schema; Error Report finished Detailed Report ---------------- SELECTs : 1 queries (0 faster, 1 slower) INSERTs : 0 queries (0 faster, 0 slower) UPDATEs : 0 queries (0 faster, 0 slower) DELETEs : 0 queries (0 faster, 0 slower) REPLACEs : 0 queries (0 faster, 0 slower) DROPs : 0 queries (0 faster, 0 slower) Report ------ Executed 1 queries Spent 00:00:00.060973 executing queries versus an expected 00:00:00.013559 time. 0 queries were quicker than expected, 1 were slower A total of 1 queries had errors. Expected 5 rows, got 0 (a difference of 5) Number of queries where number of rows differed: 1. Average of 1.00 queries per connection (1 connections).
A total of 1 queries had errors. としっかりエラーが補足できています。
デフォルトでは、10回リトライする設定になっています。エラーがたくさん出て、出力が見にくいので、--mysql-max-retries=0 で無効化したほうが良いです。
実行タイミングも考慮したリプレイ
相互に関係するクエリのロックの挙動やタイミング依存の問題も含めて、精度の高いリプレイをしたいと考えると、クエリの実行タイミングも可能な限り再現できるとベターです。
--query-log-accurate-mode を指定すれば、クエリの実行タイミングも含めて再現してくれそうです。
5秒間隔で INSERT INTO t (d) VALUES(NOW()) を実行し、それがリプレイ先で再現されるか確認してみます。タイミングも含めたリプレイが成功すれば、d の値の差が5秒あるレコードが再現されるはずです。
mysql> select * from test.t; +----+---------------------+ | pk | d | +----+---------------------+ | 1 | 2020-08-30 08:30:15 | | 2 | 2020-08-30 08:30:20 | +----+---------------------+ 2 rows in set (0.01 sec)
$ sudo /usr/local/bin/percona-playback --query-log-file /var/lib/mysql/localhost-slow.log --mysql-host 192.168.123.12 --mysql-user appuser --mysql-password Pass@123 --mysql-schema mysql --mysql-max-retries=0 --query-log-accurate-mode Database Plugin: libmysqlclient Running... WARNING: did not find a timestamp for the first query. Disabling accurate mode.
WARNING: did not find a timestamp for the first query. Disabling accurate mode. とタイムスタンプがログに見つからないと言われてしまいました・・・ぐぬぬぬ。ログにはしっかりタイムスタンプが出力されています。
ソースコードを見ると、MySQL 8.0 のタイムスタンプの形式（# Time: 2020-08-30T08:29:48.563737Z） に対応できていない状態でした。
query_log/query_log.cc
static bool parse_time(boost::string_ref s, QueryLogData::TimePoint& start_time) {
// Time can look like this
// # Time: 090402 9:23:36
// or like this if microseconds granularity is configured.
// # Time: 090402 9:23:36.123456
long long msecs = 0;
std::tm td;
memset(&td, 0, sizeof(td));
std::string line(s.begin(), s.end());
int num_read = sscanf(line.c_str(), "# Time: %02d%02d%02d %2d:%02d:%02d.%06lld",
&td.tm_year, &td.tm_mon, &td.tm_mday, &td.tm_hour, &td.tm_min, &td.tm_sec, &msecs);
MySQL 8.0のスロークエリログのタイムスタンプ形式にあわせて書き換えます。
int num_read = sscanf(line.c_str(), "# Time: %04d-%02d-%02dT%2d:%02d:%02d.%06lld",
&td.tm_year, &td.tm_mon, &td.tm_mday, &td.tm_hour, &td.tm_min, &td.tm_sec, &msecs);
ソースを微修正すれば動きました。
リプレイ先に作られたレコード）
mysql> select * from test.t; +----+---------------------+ | pk | d | +----+---------------------+ | 1 | 2020-08-30 08:46:21 | | 2 | 2020-08-30 08:46:26 | +----+---------------------+ 2 rows in set (0.00 sec)
当たり前ですが、このオプションを使うと、実際の時間と同じぐらいリプレイに時間がかかります。１時間分のスロークエリログを食わせたら、リプレイに１時間かかります。
Percona Playback まとめ
- リプレイ先でのエラーの有無、性能劣化の有無のチェックが出来る
- スロークエリログに記録されている結果セットの件数とリプレイ先での結果セットの件数に差異がないかチェック出来る
- クエリの実行タイミングも再現したリプレイが可能
tombo さんの mysql-query-replayer も試したい
tombo さんが、リプレイツールを作っています。 大規模なリプレイが出来そうです。こちらも、いつか試してみたいと思います。
