はじめに

にゃーん。
今回はPostgreSQL 14 beta1を使ってCOPYコマンドの進捗状況を示すビューについて調べてみた。

COPY処理

PostgreSQLには大昔¹から、COPYというバルクロードを行うコマンドがある。
PostgreSQLサーバにファイルを置かないといけない、特定の権限がないと実行できない、といったいくつかの運用上の制約はあるけど、高速に大量データをロードできるありがたい機能だ。
とはいえ、何百GB～TB級のデータをCOPYコマンドでロードするとそれなりに時間もかかる。ロードがどのくらいの時間で終わるのか分からないのは、やっぱりやきもきするもの。

PostgreSQL 14での改善

これまでも、VACUUM(CLUSTER)やANALYZE、CREATE INDEX用の進捗を管理するシステムビューが実装されていたが、PostgreSQL 14ではそのCOPY版が追加された。

pg_stat_progress_copy

COPYコマンドの進捗状況を示すビュー pg_stat_progress_copy の内容はこんな感じ。

列名	型	内容
pid	integer	COPYコマンドを実行中のバックエンドプロセスのPID
datid	oid	COPYコマンドを実行中のバックエンドプロセスが接続しているデータベースのoid
datname	name	COPYコマンドを実行中のバックエンドプロセスが接続しているデータベース名
relid	oid	COPYコマンドが実行されるテーブルのOID。 SELECTクエリからコピーする場合は0に設定される。
command	text	実行中のコマンド。`COPY FROM`または`COPY TO` てっきり、`COPY FROM`だけ対応かと思っていたけど、`COPY TO`も対応するのかー。
type	text	データの読み取りまたは書き込みが行われるI/Oタイプ。 `FILE`、`PROGRAM`、`PIPE`（`COPY FROM STDIN`および`COPY TO STDOUT`の場合）、またはCALLBACK（たとえば、論理レプリケーションでの初期テーブル同期中に使用される）。論理レプリケーション同期の進捗も見れるというのは意外だった。
bytes_processed	bigint	COPYコマンドによってすでに処理されたバイト数。
bytes_total	bigint	COPY FROMコマンドのソースファイルのサイズ（バイト単位）。ソースがファイルじゃない場合には0が設定されるのかな。
tuples_processed	bigint	COPYコマンドによってすでに処理されたタプル数。
tuples_excluded	bigint	COPYコマンドのWHERE句によって除外されたために処理されなかったタプルの数。

処理したバイト数またはタプル数を表示して進捗を示すもののようだ。どちらの指標で進捗を把握するのかはケースバイケース、ってことかな。

試してみた

COPYと一言で言ってもいろいろなパターンがあるけれど、まずは基本的な例として、クエリ内容をファイルに書き出し(COPY TO)と、ファイルから読み込み(COPY FROM)を試してみる。

COPY クエリ TO ファイル名

以下のようなクエリを実行してみる。
この例では、idに相当する数値と、400文字のランダムな文字列²からなるタプルを10万件生成して、/data/test.datというファイルに書き込む。

COPY (SELECT generate_series(1, 100000), generate_random_text(400)) TO '/data/test.dat';

別ターミナルから、pg_stat_progress_copyテーブルを参照するSELECT文をpsqlの\watchメタコマンドで繰り返し実行するように準備しておく。

testdb=# SELECT * FROM pg_stat_progress_copy ;
 pid | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-----+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
(0 rows)

testdb=# \watch 1

で、watch 1を実行して、別ターミナルからCOPY文を実行し、\watchを実行したターミナルを監視する。

                                     Sun 13 Jun 2021 02:51:24 PM JST (every 1s)

 pid | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-----+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
(0 rows)

                                      Sun 13 Jun 2021 02:51:25 PM JST (every 1s)

  pid  | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
 12724 | 16384 | testdb  |     0 | COPY TO | FILE |           77648 |           0 |              190 |               0
(1 row)

                                      Sun 13 Jun 2021 02:51:26 PM JST (every 1s)

  pid  | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
 12724 | 16384 | testdb  |     0 | COPY TO | FILE |         3907983 |           0 |             9529 |               0
(1 row)

中略

                                      Sun 13 Jun 2021 02:51:35 PM JST (every 1s)

  pid  | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
 12724 | 16384 | testdb  |     0 | COPY TO | FILE |        38456702 |           0 |            93549 |               0
(1 row)

                                     Sun 13 Jun 2021 02:51:36 PM JST (every 1s)

 pid | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-----+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
(0 rows)

COPY クエリ TO ファイル名のケースでは、

relidは0のまま。
commandはCOPT TO
typeはFILE
となる。また、
bytes_processed と tuples_processed は処理経過によって増加していく。
bytes_total と tuples_excluded は0のまま。

という挙動になっていることがわかる。
今回のケースでは自分で10万タプル挿入することが分かっているので、tuples_processed で状況を確認するのがわかりやすそうだ。

そしてCOPY処理自体が完了すると、pg_stat_progress_copy から該当の処理に関する行はすぐに消えてしまう。

COPY テーブル名 FROM ファイル名

次に、さっきのCOPY TOの処理で生成したファイルを、COPY FROMの処理でロードしてみて、そのロード処理の進捗を確認してみる。

以下のようにCOPY FROMのコマンドを準備しておく。

testdb=# CREATE TABLE test (id int, data text);
testdb=# COPY test FROM '/data/test.dat' ;

そして別ターミナルで。pg_stat_progress_copyを検索するSELECT文と、\watchを実行しておく（このCOPY FROMの処理はかなり早いため、\watchの間隔は0.1秒にする）。
\watch実行後に、COPYコマンドを実行して、\watchを実行したターミナルを監視する。

                                    Sun 13 Jun 2021 03:08:36 PM JST (every 0.1s)

 pid | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-----+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
(0 rows)

                                      Sun 13 Jun 2021 03:08:37 PM JST (every 0.1s)

  pid  | datid | datname | relid |  command  | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+-----------+------+-----------------+-------------+------------------+-----------------
 12724 | 16384 | testdb  | 16386 | COPY FROM | FILE |         1441792 |    41109590 |             3404 |               0
(1 row)

                                      Sun 13 Jun 2021 03:08:37 PM JST (every 0.1s)

  pid  | datid | datname | relid |  command  | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+-----------+------+-----------------+-------------+------------------+-----------------
 12724 | 16384 | testdb  | 16386 | COPY FROM | FILE |         7929855 |    41109590 |            19260 |               0
(1 row)

中略

                                      Sun 13 Jun 2021 03:08:37 PM JST (every 0.1s)

  pid  | datid | datname | relid |  command  | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+-----------+------+-----------------+-------------+------------------+-----------------
 12724 | 16384 | testdb  | 16386 | COPY FROM | FILE |        37748729 |    41109590 |            91740 |               0
(1 row)

                                    Sun 13 Jun 2021 03:08:37 PM JST (every 0.1s)

 pid | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-----+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
(0 rows)

COPY テーブル名 FROM ファイル名のケースでは、

relidにはロードされるテーブルのrelidが設定される。
commandはCOPT FROM
typeはFILE
となる。また、
bytes_processed と tuples_processed と bytes_total は処理経過によって増加していく。
tuples_excluded は0のまま。

COPY テーブル名 FROM ファイル名 WHERE句

さっき実施したCOPY テーブル名 FROM ファイル名の応用として、WHERE句つきで実行した場合の挙動を確認する。
こんなCOPY FROM文を用意しておく。

COPY test FROM '/data/test.dat' WHERE (id % 100) != 1 ;

このCOPY文では10万件のテキストデータのうち、1000件が除外された99000件がtestテーブルにロードされる。

そして別ターミナルで。pg_stat_progress_copyを検索するSELECT文と、\watchを実行しておく（このCOPY FROMの処理はかなり早いため、\watchの間隔は0.1秒にする）。
\watch実行後に、COPYコマンドを実行して、\watchを実行したターミナルを監視する。

                                    Sun 13 Jun 2021 03:36:10 PM JST (every 0.1s)

 pid | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-----+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
(0 rows)

                                      Sun 13 Jun 2021 03:36:10 PM JST (every 0.1s)

  pid  | datid | datname | relid |  command  | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+-----------+------+-----------------+-------------+------------------+-----------------
 15973 | 16384 | testdb  | 16386 | COPY FROM | FILE |         3538943 |    41109590 |             8532 |              87
(1 row)

                                      Sun 13 Jun 2021 03:36:10 PM JST (every 0.1s)

  pid  | datid | datname | relid |  command  | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+-----------+------+-----------------+-------------+------------------+-----------------
 15973 | 16384 | testdb  | 16386 | COPY FROM | FILE |        15400958 |    41109590 |            37020 |             374
(1 row)

                                      Sun 13 Jun 2021 03:36:10 PM JST (every 0.1s)

  pid  | datid | datname | relid |  command  | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+-----------+------+-----------------+-------------+------------------+-----------------
 15973 | 16384 | testdb  | 16386 | COPY FROM | FILE |        22216701 |    41109590 |            53500 |             541
(1 row)

                                      Sun 13 Jun 2021 03:36:10 PM JST (every 0.1s)

  pid  | datid | datname | relid |  command  | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+-----------+------+-----------------+-------------+------------------+-----------------
 15973 | 16384 | testdb  | 16386 | COPY FROM | FILE |        34340858 |    41109590 |            82546 |             834
(1 row)

                                    Sun 13 Jun 2021 03:36:10 PM JST (every 0.1s)

 pid | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-----+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
(0 rows)

WHERE句をつけたCOPY FROMの場合、tuples_excluded の列も増加しているのがわかる。

\copyの挙動

このCOPYの進捗機能は、サーバサイドのCOPYコマンドだけではなく、psqlのメタコマンドの\copyを実行した場合にも使用できる。

\copy (SELECT generate_series(1, 100000), generate_random_text(400)) TO '/data/test.dat';

\copyを使った場合には、TYPEがPIPEとして表示される。

                                      Sun 13 Jun 2021 03:51:43 PM JST (every 1s)

  pid  | datid | datname | relid | command | type | bytes_processed | bytes_total | tuples_processed | tuples_excluded
-------+-------+---------+-------+---------+------+-----------------+-------------+------------------+-----------------
 15973 | 16384 | testdb  |     0 | COPY TO | PIPE |         1116699 |           0 |             2725 |               0
(1 row)

後略

\copy テーブル名 FROM ファイル名のパターンも同様である。（省略）

COPY処理のパターンと各列の表示内容のまとめ

今回検証した代表的な4パターンについて、各列の表示内容をまとめると以下のようになる。

列名	COPY TO	COPY FROM	COPY FROM (WHERE句つき)	\copy TO
pid	設定される	設定される	設定される	設定される
datid	設定される	設定される	設定される	設定される
datname	設定される	設定される	設定される	設定される
relid	0のまま	設定される	設定される	0のまま
command	COPY TO	COPY FROM	COPY FROM	COPY TO
type	FILE	FILE	FILE	PIPE
bytes_processed	設定される	設定される	設定される	設定される
bytes_total	0のまま	設定される	設定される	0のまま
tuples_processed	設定される	設定される	設定される	設定される
tuples_excluded	0のまま	0のまま	設定される	0のまま

おわりに

今回はCOPYと\copyの代表的な実行パターンによる、COPYの進捗ビューの状況を確認してみた。
まだ、PROGRAM指定や、論理レプリケーション時の挙動の確認が残っているので、別途検証しようと思う。

PostgreSQL 7.2の頃から実装されている。なおPostgreSQL 7.2のリリースは今(2021年)から19年前。 ↩
generate_random_text()はPostgreSQLの標準関数ではなく、自作のPL/pgSQL関数。指定された引数分のランダムな英数字文字列を生成する。→ソース ↩