PostgreSQL 14がやってくる(5) - COPYの進捗どうでしょう

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

#COPY処理
PostgreSQLには大昔[^1]から、COPYというバルクロードを行うコマンドがある。
PostgreSQLサーバにファイルを置かないといけない、特定の権限がないと実行できない、といったいくつかの運用上の制約はあるけど、高速に大量データをロードできるありがたい機能だ。
とはいえ、何百GB～TB級のデータをCOPYコマンドでロードするとそれなりに時間もかかる。ロードがどのくらいの時間で終わるのか分からないのは、やっぱりやきもきするもの。
# PostgreSQL 14での改善
これまでも、VACUUM(CLUSTER)やANALYZE、CREATE INDEX用の進捗を管理するシステムビューが実装されていたが、PostgreSQL 14ではそのCOPY版が追加された。

## pg_stat_progress_copy
COPYコマンドの進捗状況を示すビュー [pg_stat_progress_copy](https://www.postgresql.org/docs/14/progress-reporting.html#COPY-PROGRESS-REPORTING) の内容はこんな感じ。

|列名|型|内容|
|:--|:--|:--|
|pid |integer|COPYコマンドを実行中のバックエンドプロセスのPID|
|datid|oid|COPYコマンドを実行中のバックエンドプロセスが接続しているデータベースのoid|
|datname|name|COPYコマンドを実行中のバックエンドプロセスが接続しているデータベース名|
|relid|oid|COPYコマンドが実行されるテーブルのOID。<br>SELECTクエリからコピーする場合は0に設定される。 |
|command|text|実行中のコマンド。``COPY FROM``または``COPY TO``<br>てっきり、``COPY FROM``だけ対応かと思っていたけど、``COPY TO``も対応するのかー。 |
|type|text|データの読み取りまたは書き込みが行われるI/Oタイプ。<br>``FILE``、``PROGRAM``、``PIPE``（``COPY FROM STDIN``および``COPY TO STDOUT``の場合）、またはCALLBACK（たとえば、論理レプリケーションでの初期テーブル同期中に使用される）。<br>論理レプリケーション同期の進捗も見れるというのは意外だった。|
|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文字のランダムな文字列[^2]からなるタプルを10万件生成して、`/data/test.dat`というファイルに書き込む。

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

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

```sql
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`を実行したターミナルを監視する。

```sql
                                     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``のコマンドを準備しておく。
```sql
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を実行したターミナルを監視する。

```sql
                                    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``文を用意しておく。

```sql
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を実行したターミナルを監視する。

```sql
                                    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``を実行した場合にも使用できる。

```sql
\copy (SELECT generate_series(1, 100000), generate_random_text(400)) TO '/data/test.dat';
```
\copyを使った場合には、TYPEが``PIPE``として表示される。

```sql
                                      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<br>(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`指定や、論理レプリケーション時の挙動の確認が残っているので、別途検証しようと思う。

[^1]: [PostgreSQL 7.2](https://www.postgresql.jp/document/7.2/reference/sql-copy.html)の頃から実装されている。なおPostgreSQL 7.2のリリースは今(2021年)から19年前。
[^2]: ``generate_random_text()``はPostgreSQLの標準関数ではなく、自作のPL/pgSQL関数。指定された引数分のランダムな英数字文字列を生成する。[→ソース](https://github.com/nuko-yokohama/pg_scripts/blob/master/generate_random_text.sql)