heterodb/pg-strom

確認・GPU Scan Qualsの出力について

Closed this issue · 4 comments

リグレッションテストを実行したところ、2~3回に1回程度失敗が生じることを確認しています。
要因としては、EXPLAIN文の出力結果を確認する場面で、GPU Scan Qualsのrowsに表示される行数が変わってしまう場合があるためです。

例えば、以下のEXPLAIN文。

EXPLAIN (costs off, verbose)
SELECT 
COUNT(a) AS a_count,SUM(a) AS a_sum,AVG(a) AS a_avg,MAX(a) AS a_max,MIN(a) AS a_min,
COUNT(b) AS b_count,SUM(b) AS b_sum,AVG(b) AS b_avg,MAX(b) AS b_max,MIN(b) AS b_min,
COUNT(c) AS c_count,SUM(c) AS c_sum,AVG(c) AS c_avg,MAX(c) AS c_max,MIN(c) AS c_min,
COUNT(d) AS d_count,SUM(d) AS d_sum,AVG(d) AS d_avg,MAX(d) AS d_max,MIN(d) AS d_min,
COUNT(e) AS e_count,SUM(e) AS e_sum,AVG(e) AS e_avg,MAX(e) AS e_max,MIN(e) AS e_min,
COUNT(f) AS f_count,SUM(f) AS f_sum,AVG(f) AS f_avg,MAX(f) AS f_max,MIN(f) AS f_min,
COUNT(g) AS g_count,SUM(g) AS g_sum,AVG(g) AS g_avg,MAX(g) AS g_max,MIN(g) AS g_min
INTO TEMPORARY cached_result FROM cache_test_table WHERE id%3=0;

EXPLAIN (costs off, verbose)

出力は以下のような表示ですが、GPU Scan Qualsのrowsに表示される行数が実行のたびに変わっています。(同じ場合もある)

EXPLAIN (costs off, verbose)
SELECT 
COUNT(a) AS a_count,SUM(a) AS a_sum,AVG(a) AS a_avg,MAX(a) AS a_max,MIN(a) AS a_min,
COUNT(b) AS b_count,SUM(b) AS b_sum,AVG(b) AS b_avg,MAX(b) AS b_max,MIN(b) AS b_min,
COUNT(c) AS c_count,SUM(c) AS c_sum,AVG(c) AS c_avg,MAX(c) AS c_max,MIN(c) AS c_min,
COUNT(d) AS d_count,SUM(d) AS d_sum,AVG(d) AS d_avg,MAX(d) AS d_max,MIN(d) AS d_min,
COUNT(e) AS e_count,SUM(e) AS e_sum,AVG(e) AS e_avg,MAX(e) AS e_max,MIN(e) AS e_min,
COUNT(f) AS f_count,SUM(f) AS f_sum,AVG(f) AS f_avg,MAX(f) AS f_max,MIN(f) AS f_min,
COUNT(g) AS g_count,SUM(g) AS g_sum,AVG(g) AS g_avg,MAX(g) AS g_max,MIN(g) AS g_min
INTO TEMPORARY cached_result FROM cache_test_table WHERE id%3=0;
 Aggregate
   Output: pgstrom.fcount((pgstrom.nrows(a))), pgstrom.sum_int((pgstrom.psum((a)::bigint))), pgstrom.avg_int((pgstrom.pavg((a)::bigint))), pgstrom.max_i1((pgstrom.pmax((a)::integer))), pgstrom.min_i1((pgstrom.pmin((a)::integer))), pgstrom.fcount((pgstrom.nrows(b))), pgstrom.sum_int((pgstrom.psum((b)::bigint))), pgstrom.avg_int((pgstrom.pavg((b)::bigint))), pgstrom.max_i2((pgstrom.pmax((b)::integer))), pgstrom.min_i2((pgstrom.pmin((b)::integer))), pgstrom.fcount((pgstrom.nrows(c))), pgstrom.sum_int((pgstrom.psum((c)::bigint))), pgstrom.avg_int((pgstrom.pavg((c)::bigint))), pgstrom.max_i4((pgstrom.pmax(c))), pgstrom.min_i4((pgstrom.pmin(c))), pgstrom.fcount((pgstrom.nrows(d))), pgstrom.sum_int_num((pgstrom.psum(d))), pgstrom.avg_int((pgstrom.pavg(d))), pgstrom.max_i8((pgstrom.pmax(d))), pgstrom.min_i8((pgstrom.pmin(d))), pgstrom.fcount((pgstrom.nrows(e))), pgstrom.sum_fp64((pgstrom.psum((e)::double precision))), pgstrom.avg_fp((pgstrom.pavg((e)::double precision))), pgstrom.max_f2((pgstrom.pmax((e)::double precision))), pgstrom.min_f2((pgstrom.pmin((e)::double precision))), pgstrom.fcount((pgstrom.nrows(f))), pgstrom.sum_fp32((pgstrom.psum((f)::double precision))), pgstrom.avg_fp((pgstrom.pavg((f)::double precision))), pgstrom.max_f4((pgstrom.pmax((f)::double precision))), pgstrom.min_f4((pgstrom.pmin((f)::double precision))), pgstrom.fcount((pgstrom.nrows(g))), pgstrom.sum_fp64((pgstrom.psum(g))), pgstrom.avg_fp((pgstrom.pavg(g))), pgstrom.max_f8((pgstrom.pmax(g))), pgstrom.min_f8((pgstrom.pmin(g)))
   ->  Custom Scan (GpuPreAgg) on gpu_cache_temp_test.cache_test_table
         Output: (pgstrom.nrows(a)), (pgstrom.psum((a)::bigint)), (pgstrom.pavg((a)::bigint)), (pgstrom.pmax((a)::integer)), (pgstrom.pmin((a)::integer)), (pgstrom.nrows(b)), (pgstrom.psum((b)::bigint)), (pgstrom.pavg((b)::bigint)), (pgstrom.pmax((b)::integer)), (pgstrom.pmin((b)::integer)), (pgstrom.nrows(c)), (pgstrom.psum((c)::bigint)), (pgstrom.pavg((c)::bigint)), (pgstrom.pmax(c)), (pgstrom.pmin(c)), (pgstrom.nrows(d)), (pgstrom.psum(d)), (pgstrom.pavg(d)), (pgstrom.pmax(d)), (pgstrom.pmin(d)), (pgstrom.nrows(e)), (pgstrom.psum((e)::double precision)), (pgstrom.pavg((e)::double precision)), (pgstrom.pmax((e)::double precision)), (pgstrom.pmin((e)::double precision)), (pgstrom.nrows(f)), (pgstrom.psum((f)::double precision)), (pgstrom.pavg((f)::double precision)), (pgstrom.pmax((f)::double precision)), (pgstrom.pmin((f)::double precision)), (pgstrom.nrows(g)), (pgstrom.psum(g)), (pgstrom.pavg(g)), (pgstrom.pmax(g)), (pgstrom.pmin(g))
         GPU Projection: pgstrom.nrows(a), pgstrom.psum((a)::bigint), pgstrom.pavg((a)::bigint), pgstrom.pmax((a)::integer), pgstrom.pmin((a)::integer), pgstrom.nrows(b), pgstrom.psum((b)::bigint), pgstrom.pavg((b)::bigint), pgstrom.pmax((b)::integer), pgstrom.pmin((b)::integer), pgstrom.nrows(c), pgstrom.psum((c)::bigint), pgstrom.pavg((c)::bigint), pgstrom.pmax(c), pgstrom.pmin(c), pgstrom.nrows(d), pgstrom.psum(d), pgstrom.pavg(d), pgstrom.pmax(d), pgstrom.pmin(d), pgstrom.nrows(e), pgstrom.psum((e)::double precision), pgstrom.pavg((e)::double precision), pgstrom.pmax((e)::double precision), pgstrom.pmin((e)::double precision), pgstrom.nrows(f), pgstrom.psum((f)::double precision), pgstrom.pavg((f)::double precision), pgstrom.pmax((f)::double precision), pgstrom.pmin((f)::double precision), pgstrom.nrows(g), pgstrom.psum(g), pgstrom.pavg(g), pgstrom.pmax(g), pgstrom.pmin(g)
         GPU Scan Quals: ((id % 3) = 0) [rows: 6971 -> 35]
         GPU Cache: GPU0 [phase: ready, max_num_rows: 10000]
         GPU Cache Options: gpu_device_id=0,max_num_rows=10000,redo_buffer_size=157286400,gpu_sync_interval=4000000,gpu_sync_threshold=10485760
         KVars-Slot: <slot=0, type='int4', expr='id'>, <slot=1, type='int1', expr='a'>, <slot=2, type='int8', expr='a'>, <slot=3, type='int4', expr='a'>, <slot=4, type='int2', expr='b'>, <slot=5, type='int8', expr='b'>, <slot=6, type='int4', expr='b'>, <slot=7, type='int4', expr='c'>, <slot=8, type='int8', expr='c'>, <slot=9, type='int8', expr='d'>, <slot=10, type='float2', expr='e'>, <slot=11, type='float8', expr='e'>, <slot=12, type='float4', expr='f'>, <slot=13, type='float8', expr='f'>, <slot=14, type='float8', expr='g'>
         KVecs-Buffer: nbytes: 83968, ndims: 2, items=[kvec0=<0x0000-27ff, type='int4', expr='id'>, kvec1=<0x2800-37ff, type='int1', expr='a'>, kvec2=<0x3800-4fff, type='int2', expr='b'>, kvec3=<0x5000-77ff, type='int4', expr='c'>, kvec4=<0x7800-bfff, type='int8', expr='d'>, kvec5=<0xc000-d7ff, type='float2', expr='e'>, kvec6=<0xd800-ffff, type='float4', expr='f'>, kvec7=<0x10000-147ff, type='float8', expr='g'>]
         LoadVars OpCode: {Packed items[0]={LoadVars(depth=0): kvars=[<slot=0, type='int4' resno=1(id)>, <slot=1, type='int1' resno=2(a)>, <slot=4, type='int2' resno=3(b)>, <slot=7, type='int4' resno=4(c)>, <slot=9, type='int8' resno=5(d)>, <slot=10, type='float2' resno=6(e)>, <slot=12, type='float4' resno=7(f)>, <slot=14, type='float8' resno=8(g)>]}}
         MoveVars OpCode: {Packed items[0]={MoveVars(depth=0): items=[<slot=1, offset=0x2800-37ff, type='int1', expr='a'>, <slot=4, offset=0x3800-4fff, type='int2', expr='b'>, <slot=7, offset=0x5000-77ff, type='int4', expr='c'>, <slot=9, offset=0x7800-bfff, type='int8', expr='d'>, <slot=10, offset=0xc000-d7ff, type='float2', expr='e'>, <slot=12, offset=0xd800-ffff, type='float4', expr='f'>, <slot=14, offset=0x10000-147ff, type='float8', expr='g'>]}}}
         Scan Quals OpCode: {Func(bool)::int4eq args=[{Func(int4)::int4mod args=[{Var(int4): slot=0, expr='id'}, {Const(int4): value='3'}]}, {Const(int4): value='0'}]}
         Partial Aggregation OpCode: {AggFuncs <nrows[slot=1, expr='a'], psum::int[slot=2, expr='a'], pavg::int[slot=2, expr='a'], pmax::int32[slot=3, expr='a'], pmin::int32[slot=3, expr='a'], nrows[slot=4, expr='b'], psum::int[slot=5, expr='b'], pavg::int[slot=5, expr='b'], pmax::int32[slot=6, expr='b'], pmin::int32[slot=6, expr='b'], nrows[slot=7, expr='c'], psum::int[slot=8, expr='c'], pavg::int[slot=8, expr='c'], pmax::int32[slot=7, expr='c'], pmin::int32[slot=7, expr='c'], nrows[slot=9, expr='d'], psum::int[slot=9, expr='d'], pavg::int[slot=9, expr='d'], pmax::int64[slot=9, expr='d'], pmin::int64[slot=9, expr='d'], nrows[slot=10, expr='e'], psum::fp[slot=11, expr='e'], pavg::fp[slot=11, expr='e'], pmax::fp64[slot=11, expr='e'], pmin::fp64[slot=11, expr='e'], nrows[slot=12, expr='f'], psum::fp[slot=13, expr='f'], pavg::fp[slot=13, expr='f'], pmax::fp64[slot=13, expr='f'], pmin::fp64[slot=13, expr='f'], nrows[slot=14, expr='g'], psum::fp[slot=14, expr='g'], pavg::fp[slot=14, expr='g'], pmax::fp64[slot=14, expr='g'], pmin::fp64[slot=14, expr='g']> args=[{SaveExpr: <slot=1, type='int1'> arg={Var(int1): kvec=0x2800-3800, expr='a'}}, {SaveExpr: <slot=2, type='int8'> arg={Func(int8)::int8 arg={Var(int1): kvec=0x2800-3800, expr='a'}}}, {SaveExpr: <slot=3, type='int4'> arg={Func(int4)::int4 arg={Var(int1): kvec=0x2800-3800, expr='a'}}}, {SaveExpr: <slot=4, type='int2'> arg={Var(int2): kvec=0x3800-5000, expr='b'}}, {SaveExpr: <slot=5, type='int8'> arg={Func(int8)::int8 arg={Var(int2): kvec=0x3800-5000, expr='b'}}}, {SaveExpr: <slot=6, type='int4'> arg={Func(int4)::int4 arg={Var(int2): kvec=0x3800-5000, expr='b'}}}, {SaveExpr: <slot=7, type='int4'> arg={Var(int4): kvec=0x5000-7800, expr='c'}}, {SaveExpr: <slot=8, type='int8'> arg={Func(int8)::int8 arg={Var(int4): kvec=0x5000-7800, expr='c'}}}, {SaveExpr: <slot=9, type='int8'> arg={Var(int8): kvec=0x7800-c000, expr='d'}}, {SaveExpr: <slot=10, type='float2'> arg={Var(float2): kvec=0xc000-d800, expr='e'}}, {SaveExpr: <slot=11, type='float8'> arg={Func(float8)::float8 arg={Var(float2): kvec=0xc000-d800, expr='e'}}}, {SaveExpr: <slot=12, type='float4'> arg={Var(float4): kvec=0xd800-10000, expr='f'}}, {SaveExpr: <slot=13, type='float8'> arg={Func(float8)::float8 arg={Var(float4): kvec=0xd800-10000, expr='f'}}}, {SaveExpr: <slot=14, type='float8'> arg={Var(float8): kvec=0x10000-14800, expr='g'}}]}
         Partial Function BufSz: 504

実際の数値。6914だったり、6971だったりしています。

GPU Scan Quals: ((id % 3) = 0) [rows: 6914 -> 35]
GPU Scan Quals: ((id % 3) = 0) [rows: 6971 -> 35]

GPU Scan Qualsは、フィルタ前後の行数を示していると理解していますが、認識あっていますでしょうか?
だとすると、実行のたびに数字が変わるのはおかしいので、テストが実行のたびに変わってしまう要素があるものと思います。
乱数の影響の可能性がありそうですが、固定シードで初期化しており。ほかに思い当たらず・・・

GPU Scan Qualsは、フィルタ前後の行数を示していると理解していますが

正しいです。しかもこれは推定値なので、同じ推定のロジックなら同じ値を出してくれるはず。
タイミング問題で変わる可能性があるとすれば、テーブルを生成後、実行計画を立てるまでの間に
autovacuumが走って統計情報をアップデートしている場合か?

ちょっとランダムデータの生成関数も見てみます。seed固定なので同じ値を出すはずですが、
最近見ていないので、知らないうちに変わっていたりしたら嫌なので…。

わかりました。PG16移植を進めつつ、発生条件絞り込めないか確認してみます。

これなのですが、GpuScanのrows:ってPostgreSQLが作成したテーブル情報(RelOptInfo)の統計情報を参照して
出力するものなので、統計情報が毎回変わっているというように見えます。
直前のテーブルセットアップのクエリを見ると、UPDATEDELETEが含まれており、その対象行を絞り込む際に
GpuScanが使われている可能性が高いです。(小さなテーブルですが enable_seqscan=off なので)

そうすると、UPDATEDELETEの順番がランダムになるので、厳密な意味ではテーブルのサイズなどが変わってしまう可能性があります。テーブルサイズの変化は推定行数の変化に繋がるので・・・という論理です。

これを回避するとなると、例えばEXPLAINを実行するようになる段階の前に、VACUUM ANALYZE <TABLE_NAME>;を挟んで統計情報を最新化するなどの方法があるのではと思ったりします。

確認してみましたが、コメント頂いた通り、VACUUM ANALYZE でrows:の行が安定することを確認できました。
これでテストを修正してみます。