pgreplayを利用しデータベースで実行されたワークロードを再実行する

pgreplay概要

pgreplayは、PostgreSQLのログファイルに記録されたSQLを抽出し、実行された時と同じ順番でSQLを発行するソフトウェアです。

pgreplay: https://github.com/laurenz/pgreplay

pgreplayを利用することで実際にデータベースで実行されたワークロードを任意の環境で再生(再実行)可能となり、ハードウェアやOS、各種パラメータ値等を変更した場合のワークロードへの性能影響を測定できるようになります。

利用目的

1年ほど前に性能改善を目的としたPostgreSQLパラメータ値の最適化を機械学習を用いて自動化したいと考え、実験用のソフトウェア(postgres_opttune)を作成しました。ベンチマークツール(pgbench、oltpbenchなど)に搭載されたワークロードを利用し性能評価を行い、機械学習を利用した最適化は従来の人手によるチューニングより、容易によい結果が得られる可能性が高いことを確認できました。

postgres_opttune: https://github.com/ssl-oyamata/postgres_opttune

そこでベンチマークツールで用意されているワークロードのみに限らず、PostgreSQLを利用する任意のアプリケーションで実行されるワークロードにおいても、PostgreSQLパラメータ値の最適化を自動化したいと考えるようになりました。

任意のアプリケーションにおいてPostgreSQLパラメータの最適化を行う場合、まずアプリケーションにて実行されるワークロードを何らかの方法で抽出し、再実行可能な状態にする必要があります。

今回はパラメータ最適化に必要であるワークロードの抽出、再生(再実行)をpgreplayを利用して実施する方法を確認しました。

インストール

pgreplayは以下の手順でインストールしました。

pgreplayレポジトリをクローン

$ git clone https://github.com/laurenz/pgreplay.git

configureスクリプト実行

$ cd pgreplay/
$ ./configure --with-postgres=/usr/pgsql-12/bin/

コンパイル

$ make
gcc -c -Wall -g -O2 -I/usr/pgsql-12/include -DVERSION='"1.4.0"' parse.c
gcc -c -Wall -g -O2 -I/usr/pgsql-12/include -DVERSION='"1.4.0"' replayitem.c
gcc -c -Wall -g -O2 -I/usr/pgsql-12/include -DVERSION='"1.4.0"' main.c
gcc -c -Wall -g -O2 -I/usr/pgsql-12/include -DVERSION='"1.4.0"' replayfile.c
gcc -c -Wall -g -O2 -I/usr/pgsql-12/include -DVERSION='"1.4.0"' database.c
gcc -o pgreplay -Wall -g -O2 -I/usr/pgsql-12/include  parse.o replayitem.o main.o replayfile.o database.o  -L/usr/pgsql-12/lib -Wl,-rpath,/usr/pgsql-12/lib -lpq

インストール

$ su
# make install
/bin/install -c -d /usr/pgsql-12/bin
/bin/install -c -m 0755 pgreplay /usr/pgsql-12/bin/pgreplay
/bin/install -c -d /usr/pgsql-12/share/man/man1
/bin/install -c -m 0644 pgreplay.1 /usr/pgsql-12/share/man/man1/pgreplay.1

pgreplayのバージョン確認

# pgreplay -v
pgreplay 1.4.0

テスト用データベース作成

今回の確認では、pgbenchが実行するワークロードをpgreplayで再生(再実行)します。
まずテスト用データベースを作成し、pgbenchのデータを投入しています。

$ createdb testdb

$ pgbench -i -s 10 testdb

バックアップ用のデータベースを作成します。

$ psql
=# CREATE DATABASE testdb_backup template testdb;

ワークロード記録

PostgreSQLログファイルにワークロードを記録するため以下の手順で設定変更を行いました。

ログ格納ディレクトリの作成

$ mkdir $PGDATA/pgreplay_log

ログ出力設定
pgreplayのREADME.mdに記載された設定を参考に以下のように設定しました。

$ psql
=# ALTER SYSTEM SET log_directory='pgreplay_log';
=# ALTER SYSTEM SET log_min_messages = 'error';
=# ALTER SYSTEM SET log_min_error_statement = log;
=# ALTER SYSTEM SET log_connections = on;
=# ALTER SYSTEM SET log_disconnections = on;
=# ALTER SYSTEM SET log_line_prefix = '%m|%u|%d|%c|';
=# ALTER SYSTEM SET log_statement = 'all';
=# SELECT pg_reload_conf();
=# \q

テスト用のワークロード実行

クライアント数:5、各クライアントが実行するトランザクション数:10の条件でpgbenchを実行しました。
(50トランザクション実行しています)

$ pgbench testdb -c 5 -t 10
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 1
query mode: simple
number of clients: 5
number of threads: 1
number of transactions per client: 10
number of transactions actually processed: 50/50
latency average = 14.276 ms
tps = 350.249526 (including connections establishing)
tps = 368.724758 (excluding connections establishing)

ログファイルの確認

pgbenchで実行されたSQLがログファイルに出力されていることを確認します。

$ tail -n 3 $PGDATA/pgreplay_log/postgresql-Sun.log
2021-04-04 22:10:55.880 JST|postgres|testdb|6069badf.2b44|LOG:  statement: END;
2021-04-04 22:10:55.882 JST|postgres|testdb|6069badf.2b53|LOG:  disconnection: session time: 0:00:00.106 user=postgres database=testdb host=[local]
2021-04-04 22:10:55.884 JST|postgres|testdb|6069badf.2b44|LOG:  disconnection: session time: 0:00:00.128 user=postgres database=testdb host=[local]

ワークロードが記録されたPostgreSQLログファイルをコピーします。

$ cp -p $PGDATA/pgreplay_log/postgresql-Sun.log $PGDATA/pgreplay_log/workload.log 

ワークロードが記録されたファイルからトランザクションなどを削除します。

 cat $PGDATA/pgreplay_log/workload.log  \
| grep -v "LOG:  statement: BEGIN" \
| grep -v "LOG:  statement: COMMIT" \
| grep -v "LOG:  statement: ROLLBACK TO SAVEPOINT" \
| grep -v "LOG:  statement: SAVEPOINT" \
| grep -v "LOG:  statement: RELEASE SAVEPOINT" \
| grep -v "LOG:  statement: SET LOCAL" \
> $PGDATA/pgreplay_log/workload-filtered.log

ワークロード再実行

ワークロードの再実行は以下の手順で実施しました。

ログ出力設定変更

ワークロードの記録のため、変更したパラメータを元の値に戻します。
以下ではデフォルト値に戻していますが、元の値が異なる場合には元の値を明示的に指定する必要があります。

$ psql
=# ALTER SYSTEM SET log_directory TO DEFAULT ;
=# ALTER SYSTEM SET log_min_messages TO DEFAULT ;
=# ALTER SYSTEM SET log_min_error_statement TO DEFAULT ;
=# ALTER SYSTEM SET log_destination TO DEFAULT ;
=# ALTER SYSTEM SET log_statement TO DEFAULT ;
=# ALTER SYSTEM SET log_statement TO DEFAULT ;
=# SELECT pg_reload_conf();
=# \q

テスト用データベースを削除

ワークロードを実行した際に更新SQLでデータが変更されているため、データベースを削除します。

$ psql
=# DROP DATABASE testdb;
=# \q

テスト用データベースをバックアップから作成

ワークロード実行前に作成したバックアップ用のデータベースを利用し、データベースを再作成します。

$ psql
=# CREATE DATABASE testdb template testdb_backup;
=# \q

ワークロード再実行

$ pgreplay  \
  -b "2021-04-04 22:10:10.000 JST" \
  -e "2021-04-04 22:10:55.884 JST" \
  -D testdb \
  -j \
  $PGDATA/pgreplay_log/workload-filtered.log

Parse statistics
================

Log lines read: 1339
Total SQL statements processed: 304
Simple SQL statements processed: 304
Parametrized SQL statements processed: 0
Named prepared SQL statements executions processed: 0
Cancel requests processed: 0
Fast-path function calls ignored: 0
Duration of recorded workload: 0.173 seconds

Replay statistics
=================

Speed factor for replay: 1.000
Total run time: 0.269 seconds
Maximum lag behind schedule: 0 seconds
Calls to the server: 316
(1175.049 calls per second)
Total number of connections: 6
Maximum number of concurrent connections: 5
Average number of concurrent connections: 3.577
Average session idle percentage: 62.559%
SQL statements executed: 304
(0 or 0.000% of these completed with error)
Maximum number of concurrent SQL statements: 4
Average number of concurrent SQL statements: 1.339
Average SQL statement duration: 0.001 seconds -> SQLの平均実行時間
Maximum SQL statement duration: 0.011 seconds
Statement duration histogram:
  0    to 0.02 seconds: 100.000%
  0.02 to 0.1  seconds: 0.000%
  0.1  to 0.5  seconds: 0.000%
  0.5  to 2    seconds: 0.000%
     over 2    seconds: 0.000%

補足

pgreplayのオプション

$ pgreplay -h

pgreplay 1.4.0
==============

Usage: pgreplay [<parse options>] [<replay options>] [<infile>]
       pgreplay -f [<parse options>] [-o <outfile>] [<infile>]
       pgreplay -r [<replay options>] [<infile>]

 The first form parses a PostgreSQL log file and replays the
statements against a database.
 The second form parses a PostgreSQL log file and writes the
contents to a "replay file" that can be replayed with -r.
 The third form replays a file generated with -f.

Parse options:
   -c             (assume CSV logfile)
   -b <timestamp> (start time for parsing logfile)
   -e <timestamp> (end time for parsing logfile)
   -q             ( \' in string literal is a single quote)

   -D <database>  (database name to use as filter for parsing logfile)
   -U <username>  (username to use as filter for parsing logfile)
Replay options:
   -h <hostname>
   -p <port>
   -W <password>  (must be the same for all users)
   -s <factor>    (speed factor for replay)
   -E <encoding>  (server encoding)
   -j             (skip idle time during replay)
   -X <options>   (extra libpq connect options)

   -n             (dry-run, will replay file without running queries)

Debugging:
   -d <level>     (level between 1 and 3)
   -v             (prints version and exits)

おわり

pgreplayを利用することで、実行されたワークロードを抽出し、再実行できることを確認できました。

また、pgreplayによるワークロードの再実行において、「Average SQL statement duration」(SQLの平均実行時間)などの情報を出力されれます。「Average SQL statement duration」などを最小化することを目的としたパラメータ最適化を試行し、任意のアプリケーションが実行するワークロードにおけるパラメータ最適化の自動化を実現したいと考えています。

参考URL