HammerDB with PostgreSQLにおけるTPC-Cベンチマークの一部不具合について

ようやくプロ野球が開幕して1プロ野球ファンとしてはうれしい限りです。

無観客試合や過密スケジュールで選手にとってはやりにくいところもあると思いますが、怪我しないよう頑張っていただきたいものです。

そして、今年こそ優勝したい！！

さて、本題へ…

長いのでさっさと結論が知りたい場合は下記目次から「解決策」へジャンプしてください。

TL;DR(3行で)
概要
問題が発生した関数
現状の把握
関数にメッセージを埋め込みデバッグ（もどき）する
原因の把握
解決策
修正の効果の確認
まとめ

TL;DR(3行で)

ベンチマークツールHammerDBにおいてPostgreSQLのTPC-Cベンチマークを行うと一部関数で無限ループが生じ正確なベンチマークスコアが出ない
対象の関数はnewordで特定の条件下でのみ問題が生じる
簡単な修正で問題を解決できる(解決策は目次の「解決策」を参照)

概要

HammerDBとは各種DBMSのベンチマークを測るためのオープンソースツールです。対応DBMSはOracle, SQL Server, DB2といった一般的な商用DBMSからMySQL, PostgreSQLといったオープンソースのDBMSまでと非常に幅広いDBMSのベンチマークツールとして利用されています。（Redisにも対応）

今回HammerDBを利用してPostgreSQLにおけるTPC-Cベンチマークを計測していたら特定の条件下で問題が生じるケースがあったのでその内容を確認していこうと思います。

なお、HammerDBの使い方については丁寧にまとめている方がいらっしゃいますので、次の記事をぜひご覧ください。こちらの記事では詳細な使い方には言及しません。

HammerDB atsuizo.hatenadiary.jp

そもそもTPC-Cって何ぞや？って方はこちらをご参考ください。

www.tpc.org

環境

OS : CentOS8
DBMS : PostgreSQL12.3
HammerDB3.3

問題が発生した関数

buildschemaでスキーマを作成すると6つのストアドファンクションが作成されるのですが、そのうちneword関数で問題が発生していました。

現状の把握

PostgreSQLのスケーラビリティを調査するためにvuser(ベンチマーク中同時実行されるプロセスの数)を固定にしてscale factor(データベースの規模を表す、以下sfと記述)を増やしながらベンチマークを測定していたのですが、どうもsf=2の時のパフォーマンスが著しく悪いことに気づきました。

print dictおよびprint vuconfの状態は次の通りです。

hammerdb>print dict
Dictionary Settings for PostgreSQL
connection {
 pg_host = localhost
 pg_port = 5432
}
tpcc       {
 pg_count_ware       = 2
 pg_num_vu           = 2
 pg_superuser        = postgres
 pg_superuserpass    = postgres
 pg_defaultdbase     = postgres
 pg_user             = tpcc
 pg_pass             = tpcc
 pg_dbase            = tpcc
 pg_vacuum           = false
 pg_dritasnap        = false
 pg_oracompat        = false
 pg_storedprocs      = false
 pg_total_iterations = 1000000
 pg_raiseerror       = false
 pg_keyandthink      = false
 pg_driver           = timed
 pg_rampup           = 2
 pg_duration         = 5
 pg_allwarehouse     = false
 pg_timeprofile      = true
 pg_async_scale      = false
 pg_async_client     = 10
 pg_async_verbose    = false
 pg_async_delay      = 1000
}

hammerdb>print vuconf
Virtual Users = 32
User Delay(ms) = 500
Repeat Delay(ms) = 500
Iterations = 1
Show Output = 1
Log Output = 1
Unique Log Name = 1
No Log Buffer = 0
Log Timestamps = 1

その時、現在実行中のプロセスを調査した様子を下記に示します。

postgres@[local]:[tpcc]# SELECT
  pid, 
  query, 
  now() - query_start AS duration 
FROM
  pg_stat_activity
WHERE
  state = 'active' 
AND
  pid <> pg_backend_pid()
ORDER BY 
  duration DESC 
LIMIT 20;
 pid  |                           query                           |    duration     
------+-----------------------------------------------------------+-----------------
 3750 | select neword(1,2,1,1088,11,0)                            | 00:09:50.238494
 3752 | select neword(1,2,4,654,12,0)                             | 00:09:49.345656
 3754 | select neword(1,2,4,1563,12,0)                            | 00:09:48.07795
 3755 | select payment(1,1,1,1,1065,1,2138,'EINGABLEABLE','0',0)  | 00:09:47.703862
 3757 | select payment(1,8,1,8,2631,0,452,'','0',0)               | 00:09:46.869483
 3759 | select payment(1,8,1,8,1107,1,564,'BARPRESOUGHT','0',0)   | 00:09:46.220633
 3777 | select neword(1,2,4,499,11,0)                             | 00:09:41.237832
 3778 | select neword(1,2,4,2124,9,0)                             | 00:09:40.750588
 3782 | select neword(1,2,10,1723,13,0)                           | 00:09:38.718276
 3783 | select neword(1,2,8,2242,14,0)                            | 00:09:38.15616
 3784 | select payment(1,8,1,8,892,1,1462,'ESEBARANTI','0',0)     | 00:09:37.736515
 3785 | select payment(1,10,1,10,41,0,4165,'','0',0)              | 00:09:37.197611
 3787 | select payment(1,7,1,7,873,1,720,'ATIONESEBAR','0',0)     | 00:09:36.03109
 3789 | select payment(1,6,2,3,1842,1,782,'OUGHTATIONPRES','0',0) | 00:09:35.152986
 3790 | select payment(1,7,2,1,1674,0,1231,'','0',0)              | 00:09:34.561076
(15 行)

本来であればこれらの関数は数ミリ秒で完了するはずなのですが、いくつかのプロセスで非常に長い間実行されていることがわかります。

ちなみにlock_timeoutやstatment_timeoutを0に設定しているので何もしなければ延々とこのプロセスは完了しません。

なお、この時のスコアは以下のようになりました。

Vuser 1:TEST RESULT : System achieved 5129 PostgreSQL TPM at 2239 NOPM

いったんこれらのプロセスをKILLして単一のクエリとして実行してみます。

postgres@[local]:[tpcc]# select neword(1,2,1,1088,11,0);
 neword 
--------
     74
(1 行)

時間: 26.284 ミリ秒

普通に実行できてしまいました。ということは特定の条件下で問題が生じてしまうようです。ちなみにdead_locktimeoutは1秒に設定してあるのでデッドロックは発生していないと考えられます。

関数にメッセージを埋め込みデバッグ（もどき）する

本来であればpgAdmin4などでストアドファンクションのデバッグをするのがスマートな方法なんでしょうが、セットアップとかで時間が必要そうだったので愚直に関数内にメッセージを埋め込んでみます。（プログラムにひたすらprintf()を埋め込むみたいな…）

さてこの状態で再びベンチマークを計測してみます。

この時のプロセスの状態は次の通りです。

postgres@[local]:[tpcc]# SELECT
  pid, 
  query, 
  now() - query_start AS duration 
FROM
  pg_stat_activity
WHERE
  state = 'active' 
AND
  pid <> pg_backend_pid()
ORDER BY 
  duration DESC 
LIMIT 20;
 pid  |                           query                           |    duration     
------+-----------------------------------------------------------+-----------------
 4595 | select neword(1,2,2,1206,10,0)                            | 00:02:18.864693
 4597 | select payment(1,2,1,2,1049,1,2383,'OUGHTPRICALLY','0',0) | 00:02:17.86534
 4598 | select payment(1,5,1,5,732,0,1918,'','0',0)               | 00:02:17.547823
 4603 | select payment(1,4,1,4,1035,1,4445,'BAROUGHTATION','0',0) | 00:02:16.049094
 4605 | select payment(1,8,1,8,335,1,381,'ANTIPRIPRES','0',0)     | 00:02:15.055553
 4614 | select payment(1,9,1,9,965,1,4508,'PRIPRIESE','0',0)      | 00:02:13.488821
 4621 | select payment(1,2,1,2,1363,1,881,'PRIESEPRES','0',0)     | 00:02:11.918619
 4624 | select neword(1,2,2,2339,15,0)                            | 00:02:10.53389
 4626 | select payment(1,3,1,3,1381,0,3533,'','0',0)              | 00:02:09.983187
 4628 | select payment(1,5,1,5,384,1,4147,'PRICALLYATION','0',0)  | 00:02:09.031679
 4630 | select payment(1,4,1,4,310,1,302,'PRICALLYPRI','0',0)     | 00:02:07.981425
 4632 | select payment(1,10,2,9,1159,0,3640,'','0',0)             | 00:02:07.467798
 4633 | select payment(1,6,1,6,2135,1,1583,'PRIPRESPRES','0',0)   | 00:02:06.942631
 4634 | select payment(1,10,1,10,2439,0,3001,'','0',0)            | 00:02:06.357712
 4636 | select payment(1,8,2,8,142,1,440,'ANTIEINGPRI','0',0)     | 00:02:05.467253
 4637 | select neword(1,2,3,683,14,0)                             | 00:02:04.927283
 4600 | select payment(2,4,2,4,2445,1,3456,'PRICALLYATION','0',0) | 00:00:00.659776
 4594 | select payment(2,6,2,6,2895,0,2092,'','0',0)              | 00:00:00.636579
 4620 | select payment(2,10,2,10,345,0,1797,'','0',0)             | 00:00:00.094892
 4622 | select payment(2,1,2,1,2104,0,2624,'','0',0)              | 00:00:00.088328
(20 行)

ここでは特定のプロセスID(4595)に関するイベントを確認します。

$ tail -f postgresql-Sat.log | stdbuf -oL grep WARNING | grep 4595

上記のコマンドで確認すると同じ処理が何回も実行されていることに気づきました。

2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1, 
2020-06-20 20:14:57.564 JST [4595] WARNING:  func_name = neword() loop_counter = 7 no_max_w_id = 2 now_ol_supply_w_id = 1,

この部分の処理は次のようになっています。

--#2.4.1.5.2
x := round(DBMS_RANDOM(1,100));
IF ( x > 1 )
THEN
no_ol_supply_w_id := no_w_id;
ELSE
no_ol_supply_w_id := no_w_id;
--no_all_local is actually used before this point so following not beneficial
no_o_all_local := 0;
WHILE ((no_ol_supply_w_id = no_w_id) AND (no_max_w_id != 1))
LOOP
no_ol_supply_w_id := round(DBMS_RANDOM(1,no_max_w_id));
RAISE WARNING 'func_name = neword() loop_counter = % no_max_w_id = % now_ol_supply_w_id = %, ', loop_counter, no_max_w_id, no_ol_supply_w_id;
END LOOP;
END IF;

RAISE～の部分がログに出力されるメッセージの内容になります。

このメッセージが何回も出力されているということは、LOOPの中身が何回も実行されているということです。

原因の把握

このLOOPは変数xがx > 1の否定すなわちx <= 1の場合に実行されます。なおかつxの定義部分を見るとx := round(DBMS_RANDOM(1, 100)です。

DBMS_RANDOM(int, int)とはbuildschema実行時に作成されるストアドファンクションのうちの1つで定義は次の通りです。

DECLARE
    start_int ALIAS FOR $1;
    end_int ALIAS FOR $2;
BEGIN
    RETURN trunc(random() * (end_int-start_int) + start_int);
END;

すなわちDBMS_RANDOM(a, b)はa, bの関係によって整数値nを返します。

a < bの場合、nはa以上b未満
a > bの場合、nはb以上a未満
a = bの場合、nはaおよびbに等しい

ここでポイントとなるのはDBMS_RANDOM(a, b)(ただしここではa < bとする)はa以上、b未満の値を返すということです。そう、b未満なんです。

つまり、DBMS_RANDOM(1, 2)は常に1を返します。もう一度問題となるループ箇所を確認してみます。

ELSE
no_ol_supply_w_id := no_w_id;
--no_all_local is actually used before this point so following not beneficial
no_o_all_local := 0;
WHILE ((no_ol_supply_w_id = no_w_id) AND (no_max_w_id != 1))
LOOP
no_ol_supply_w_id := round(DBMS_RANDOM(1,no_max_w_id));
no_max_w_id = % now_ol_supply_w_id = %, ', loop_counter, no_max_w_id, no_ol_supply_w_id;
END LOOP;

このELSEはxが1の時のみ実行されます。（確率でいえば1%程度です） WHILEの1つ目の条件は1回目には必ず満足します。そしてno_max_w_idが1以外の場合ループの中身が処理されます。（no_max_w_idはneword()の2つ目の引数として与えられます）問題となるのはno_max_w_idが2の時です。

この時、ループの中身は次のようになります。

no_ol_supply_w_id := round(DBMS_RANDOM(1, 2));

上述した通り、ここでno_ol_supply_w_idは常に1となります。

もしここでno_w_idが1だった場合このループ処理は一向に終わりません。（no_w_idはneword()の1つ目の引数として与えられます）

つまり、次の条件を満たした時のみ無限ループが生じるわけです。

no_w_id = 1
no_max_w_id = 2
x = 1(確率でいうと1%ほど)

no_max_w_idはsfの値になるのでsf=2の時に発生する率が高かったわけです。（sf > 1で発生する確率が高いがsf = 2の時が最も発生頻度が高くなる）また、x = 1のときしか発生しないので単発で実行したときは正常に完了したわけです。

もう1度問題が生じたコマンドを確認してみると、select neword(1,2,2,1206,10,0)なので確かに条件を満たしていることがわかります。(no_w_id, no_max_w_idはそれぞれ第1、2引数)

解決策

そんなわけで原因は分かったので関数を修正します。

-- 修正前
LOOP
no_ol_supply_w_id := round(DBMS_RANDOM(1,no_max_w_id));
END LOOP;

-- 修正後
LOOP
no_ol_supply_w_id := round(DBMS_RANDOM(1,no_max_w_id + 1));
END LOOP;

さすがにDBMS_RANDOM()を修正すると影響範囲が広そうだったので引数の方をいじりました。no_max_w_idが1の時はそもそもループの中身が処理されないので、特に問題はないでしょう。

修正の効果の確認

この状態でもう一度ベンチマークを計測してみます。

postgres@[local]:[tpcc]# SELECT
  pid, 
  query, 
  now() - query_start AS duration 
FROM
  pg_stat_activity
WHERE
  state = 'active' 
AND
  pid <> pg_backend_pid()
ORDER BY 
  duration DESC 
LIMIT 20;
 pid  |                           query                            |    duration     
------+------------------------------------------------------------+-----------------
 6507 | select payment(1,7,2,5,278,0,2842,'','0',0)                | 00:00:00.162705
 6475 | select payment(1,4,1,4,1648,1,1264,'ABLEESEBAR','0',0)     | 00:00:00.123258
 6480 | select payment(2,7,2,7,296,1,728,'ATIONATIONABLE','0',0)   | 00:00:00.116108
 6482 | select payment(2,10,2,10,1697,1,4870,'ATIONEINGBAR','0',0) | 00:00:00.085873
 6514 | select payment(1,4,1,4,217,0,597,'','0',0)                 | 00:00:00.082254
 6489 | select payment(2,2,2,2,622,0,4366,'','0',0)                | 00:00:00.078973
 6509 | select payment(1,1,1,1,153,0,1481,'','0',0)                | 00:00:00.077174
 6498 | select payment(2,2,2,2,2577,0,4940,'','0',0)               | 00:00:00.075871
 6511 | select payment(2,2,1,3,1957,0,2928,'','0',0)               | 00:00:00.072178
 6515 | select payment(2,1,2,1,1355,0,4555,'','0',0)               | 00:00:00.066718
 6513 | select payment(1,3,2,4,821,0,455,'','0',0)                 | 00:00:00.066245
 6478 | select payment(1,10,1,10,2315,0,3310,'','0',0)             | 00:00:00.064978
 6487 | select payment(1,10,1,10,2286,1,1711,'ANTIABLEANTI','0',0) | 00:00:00.063686
 6484 | select payment(1,6,1,6,693,0,3374,'','0',0)                | 00:00:00.058054
 6485 | select payment(2,7,2,7,2723,0,4016,'','0',0)               | 00:00:00.046386
 6492 | select payment(2,8,2,8,410,0,2638,'','0',0)                | 00:00:00.043635
 6496 | select payment(1,3,2,3,807,1,3419,'PRIBARBAR','0',0)       | 00:00:00.040828
 6483 | select payment(2,5,2,5,2476,0,1313,'','0',0)               | 00:00:00.040383
 6510 | select payment(1,6,1,6,114,1,508,'BARESECALLY','0',0)      | 00:00:00.035579
 6479 | select payment(2,7,2,7,893,1,2810,'CALLYPRIBAR','0',0)     | 00:00:00.034886

プロセスを確認してみると詰まっているプロセスがないことがわかります。

この時のスコアは次のようになりました。

Vuser 1:TEST RESULT : System achieved 42273 PostgreSQL TPM at 18392 NOPM

修正前と比べて9倍ほどスコアが伸びましたね。（なお、ベンチマークのスコアは今回の趣旨とは離れるためくれぐれも参考にはしないでください）

ちなみに修正前はpayment()も詰まっていましたが、これはneword()内で特定のテーブルに対して更新をかけているのですが、payment()でも同じテーブルに対して更新をかけようとするからです。

neword()が終わらないため、延々にそのテーブルのロックを保持し続ける→payment()がロック待ちを行うという悪循環が発生していました。(lock_timeout=0なのでロック待ちを延々と行う)

なお、今回問題となるneword()を生成する部分のソースは次のリンクから確認できます。

HammerDB/pgoltp.tcl at master · TPC-Council/HammerDB · GitHub

2020/06/24 追記リンクが誤っていたため、修正いたしましたmm

まとめ

ということで今回はHammerDBにおいて特定の条件下で発生する問題を把握して解決しました。

今回みたいな原因を究明してそれを解決するフローというのは楽しいですね。（今回の修正が最善だったかどうかは不明なのですが・・・）

そして、いまだにPostgreSQLの操作に慣れません…

それでは、今回はこのあたりで

2020/07/01 追記

遅ればせながらIssueを出したところバグ認定されました。問題はDBMS_RANDOM()の方にあったようで（つまり今回僕が行った修正は最善ではありません）、次回リリース時に修正されるようです。

PostgreSQL's neword() function often causes infinite loop · Issue #134 · TPC-Council/HammerDB · GitHub

三流エンジニアの落書き帳

さあ、今日も未知という扉を開けてみよう