PG-Stromにプロファイラをつけてみた

1月6日(金)に書いた『しゅとろ〜む、しゅとろ〜む』の記事は割と反響が大きかったようだ。
コメント欄に次のような質問を頂いたので、試してみることにする。

通りすがりさん wrote:
すばらしい成果ですね.
カラム指向的にデータを持っていること自体が性能向上に寄与しているということはないですか?
(通常 + CPU) vs (カラム指向+GPU)で比較をされていますが,
(通常 + CPU) vs (カラム指向+CPU) vs (カラム指向+GPU) の評価にも興味があります.

plan.c 内の is_device_executable_qual() 関数が常に false を返すようにすれば、条件句の処理をCPUだけで行うようになる。これは (カラム指向+CPU) と同等である。

1,000万件のレコードを持つ、通常のテーブル t1 と、PG-Strom管理下のテーブル t2 に対してそれぞれ以下のクエリを実行してみた。

■ 1回目(バッファにデータが乗っていない状態)

(通常 + CPU)
Timing is on.
postgres=# SELECT COUNT(*) FROM t1 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
 count
-------
  6718
(1 row)

Time: 8041.237 ms

(カラム指向 + CPU)
postgres=# SELECT COUNT(*) FROM t2 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
 count
-------
  6718
(1 row)

Time: 8660.486 ms

(カラム指向 + GPU)
postgres=# SELECT COUNT(*) FROM t2 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
 count
-------
  6718
(1 row)

Time: 4667.643 ms

■ 2回目(バッファにデータが乗っている状態)

(通常 + CPU)
postgres=# SELECT COUNT(*) FROM t1 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
 count
-------
  6718
(1 row)

Time: 7016.732 ms

(カラム指向 + CPU)
postgres=# SELECT COUNT(*) FROM t2 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
 count
-------
  6718
(1 row)

Time: 6733.771 ms

(カラム指向 + GPU)
postgres=# SELECT COUNT(*) FROM t2 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
 count
-------
  6718
(1 row)

Time: 173.351 ms

(通常+CPU)と(カラム指向+CPU)の比較で、ディスクからの読み出しが発生する場合にカラム指向の方が8%程度遅いという結果になっている。
複雑な条件句を設定したために、I/OよりもCPUバウンドな処理になっている事、xとyにはランダムな値を入れているために、全く圧縮が効いていないのが一因かもしれない。
(カラム指向 + GPU)で2回目の方が早くなっているのは、主にGPUコードのJITコンパイルの処理時間の違いによるものだろう。JITコンパイルにここまで時間がかかることは稀だが、確実にI/Oを発生させるために Linux の Page Cache をクリアしてから測定を行ったため、nvccコマンドもOSのキャッシュから弾き出されたという事だろう。

ただ、psql の \timing ではトータルの実行時間を表示するだけで、何が要因で時間を食っているのかは分からない。PG-Stromは性能改善を目的とするモジュールなので、どの辺を改善したら良いのか探るには先ず、どの辺にボトルネックがあるのかを探る必要がある。

という訳で、PG-StromのGUCパラメータ pg_strom.exec_profile を追加してみた。
これに "on" をセットすると、各々コンポーネントで消費した時間を表示してくれる。

postgres=# SET pg_strom.exec_profile = ON;
SET

(カラム指向 + GPU; 1回目)

postgres=# SELECT COUNT(*) FROM t2 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
INFO:  PG-Strom Exec Profile on "t2"
INFO:  Total PG-Strom consumed time: 4367.067 ms
INFO:  Time to JIT Compile GPU code: 1741.505 ms
INFO:  Time to initialize devices:   345.353 ms
INFO:  Time to Load column-stores:   2119.669 ms
INFO:  Time to Scan column-stores:   3.566 ms
INFO:  Time to Fetch virtual tuples: 110.920 ms
INFO:  Time of GPU Synchronization:  31.244 ms
INFO:  Time of Async memcpy:         31.320 ms
INFO:  Time of Async kernel exec:    27.906 ms
INFO:  Num of registers/thread [0]:  25
INFO:  Constant memory usage [0]:    40 byte
INFO:  Max device memory usage[0]:   536 KB
 count
-------
  6718
(1 row)

Time: 4514.738 ms

\timing で計測した応答時間 4514.738ms のうち、PG-Strom モジュール内の処理時間は 4367.067 msで、そのうち、大部分を占めるのが、GPUコードのJITコンパイル(1741.505ms)と、カラムストアからのロード(2119.669ms)になる。これと比べると、GPUでの処理時間・メモリ転送は桁が違う。

(カラム指向 + GPU; 2回目)

postgres=# SELECT COUNT(*) FROM t2 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
INFO:  PG-Strom Exec Profile on "t2"
INFO:  Total PG-Strom consumed time: 183.302 ms
INFO:  Time to JIT Compile GPU code: 0.043 ms
INFO:  Time to initialize devices:   1.134 ms
INFO:  Time to Load column-stores:   54.883 ms
INFO:  Time to Scan column-stores:   3.425 ms
INFO:  Time to Fetch virtual tuples: 96.384 ms
INFO:  Time of GPU Synchronization:  27.462 ms
INFO:  Time of Async memcpy:         30.737 ms
INFO:  Time of Async kernel exec:    27.906 ms
INFO:  Num of registers/thread [0]:  25
INFO:  Constant memory usage [0]:    40 byte
INFO:  Max device memory usage[0]:   536 KB
 count
-------
  6718
(1 row)

Time: 186.867 ms

1回目で時間を食っていた、GPUコードのJITコンパイル処理時間が消え、カラムストアからのロード時間も大幅に減っている。また、地味にデバイスの初期化にも345.353 ms要していたが、これがほぼ無くなっている。
この結果、トータルの処理時間が4514.738 ms⇒186.867msに減少。
カラムストアのロード/スキャンと、タプルをフェッチする処理(これはFDWの仕様なので減らすのが難しい)、それにGPUの処理の同期で合わせて 182.154 ms が消費されている。

1/6(金)の時点から少しアルゴリズムを変更しているが、メモリ使用量はほとんど問題になっていない。
これは、I/O周りで時間がかかっているために、2個、3個とチャンクを非同期に処理しようとしても、次のチャンクを読み込んでGPUに渡す頃には、前のチャンクの処理が既に終わっているからという事だろう。
この辺、もっと足回りの良いマシンなら変わってくるのだろうか。

なお、Time to scan... というのは、条件句を評価した結果に基づいてカラムストアをスキャンする処理で、条件句には使われていないものの、Target-listに含まれるカラムが存在する場合に発生する。今回のクエリは COUNT(*) を返すだけなので、追加のスキャンは発生していない。


おまけ。(カラム指向 + CPU)の実行結果だとこうなる。

postgres=# SELECT COUNT(*) FROM t2 WHERE sqrt((x-25.6)^2 + (y-12.8)^2) < 15;
INFO:  PG-Strom Exec Profile on "t2"
INFO:  Total PG-Strom consumed time: 2314.374 ms
INFO:  Time to JIT Compile GPU code: 0.000 ms
INFO:  Time to initialize devices:   0.000 ms
INFO:  Time to Load column-stores:   6.881 ms
INFO:  Time to Scan column-stores:   1435.570 ms
INFO:  Time to Fetch virtual tuples: 871.891 ms
INFO:  Time of GPU Synchronization:  0.000 ms
INFO:  Time of Async memcpy:         0.000 ms
INFO:  Time of Async kernel exec:    0.000 ms
 count
-------
  6718
(1 row)

Time: 8063.461 ms

トータル 8063ms のうち、PS-Strom内の処理は 2314 ms。つまり、必死こいてPG-Stromから本体側にメモリコピーの後、CPUで条件句を処理という流れが見える。PG-Strom内での結果の絞込みができないので、Fetch virtual tuplesの時間が大幅に増加しているのが分かる。
それと、Scan column-store の時間もやや気がかり。足回りとして、この辺は改善の余地があるやも。