PostgreSQL – How to Resolve pg_restore Stuck on Table

postgresql

I'm creating a backup/restore script for a small postgres 12.2 database, running inside a docker container. Backup looks like:

docker exec -e PGPASSWORD=${passwd} ${container} \
   pg_dump -h ${host} -U ${username} ${db} \
   -Fc > ${backupdir}${db}_$(date +"%Y-%m-%d-%H.%M.%S.%N").pgdump

Then I create a new database, and try to restore into it as:

docker exec -i ${container} pg_restore -Fc --verbose --clean \
   --no-acl --no-owner -U ${username} \
   -d ${testdb} < ${backupdir}${db}_ ...

This seems to work for a number of tables and then it freezes at one particular table, every time. Nothing seems to happen, though Postgres is using 80% CPU. I left it running for 10 hours without finishing.

The table in question contains ~ 1E6 rows, a table 3 times bigger restores in about 10 seconds. The table contains a generated column:

CREATE TABLE MIND.FILER
( DOKUMENT_UUID UUID NOT NULL   -- document_uuid
, SIDNUMMER INTEGER NOT NULL    -- page number
, FILTYP TEXT NOT NULL          -- file type
, TILLSTAND SMALLINT NOT NULL   -- state 
, FILNAMN TEXT NOT NULL         -- name of file
, FULLSTANDIGT_FILNAMN TEXT GENERATED ALWAYS AS -- complete file name including path 
    (mind.uuid_2_path(dokument_uuid) || rtrim(filnamn)) STORED
,   CONSTRAINT PK_FILER PRIMARY KEY (DOKUMENT_UUID, SIDNUMMER, FILTYP)
,   CONSTRAINT FK_SIDOR
        FOREIGN KEY (DOKUMENT_UUID, SIDNUMMER)
            REFERENCES MIND.SIDOR (DOKUMENT_UUID, SIDNUMMER)
                ON DELETE CASCADE
                ON UPDATE CASCADE
,   CONSTRAINT FK_FILTYPER
        FOREIGN KEY (FILTYP)
            REFERENCES MIND.FILTYPER (FILTYP)
                ON DELETE CASCADE
                ON UPDATE CASCADE
);

but I get the impression that that should not affect the restore, at least not to this extent.

The function MIND.UUID_2_PATH locates the mount point in the file system, dependent on the UUID version used.

CREATE OR REPLACE FUNCTION MIND.UUID_2_PATH(DUID UUID)
    RETURNS TEXT AS $$
    DECLARE s text;
    DECLARE ss text;
    DECLARE uuid_v int;
BEGIN
    SELECT substr(DUID::text,15,1) into uuid_v;
    IF uuid_v = 4 THEN
        SELECT REPLACE(CAST(DUID AS TEXT),'-','') INTO s;
        SELECT monteringspunkt
                  ||SUBSTR(s,1,4)||'/'
                  ||SUBSTR(s,5,4)||'/'
                  ||SUBSTR(s,9,4)||'/'
                  ||SUBSTR(s,13,4)||'/'
                  ||SUBSTR(s,17,4)||'/'
                  ||SUBSTR(s,21,4)||'/'
                  ||SUBSTR(s,25,4)||'/'
                  ||SUBSTR(s,29,4)||'/' INTO ss
        FROM mind.filsystemsmonteringar
        WHERE uuid_version = 4;
    ELSE -- uuid_v = 3
        SELECT lpad(dokument_id::text, 10,'0') into s FROM MIND.DOKUMENT where dokument_uuid = DUID;
        SELECT monteringspunkt
                  ||SUBSTR(s,1,3)||'/'
                  ||SUBSTR(s,4,3)||'/'
                  ||SUBSTR(s,7,2)||'/'
                  ||s||'/' INTO ss
        FROM mind.filsystemsmonteringar
        WHERE uuid_version = 3;
    END IF;
    RETURN ss;
end;
$$
LANGUAGE plpgsql
IMMUTABLE
RETURNS NULL ON NULL INPUT;

It may not be the most efficient way to do it, but loading millions of rows into the table using \copy performs decently.

Every now and then there are entries like:

2020-10-06 12:36:17.078 UTC [27] LOGG:  checkpoint starting: time
2020-10-06 12:38:47.123 UTC [27] LOGG:  checkpoint complete: wrote 689 buffers (4.2%); 0 WAL file(s) added, 0 removed, 10 recycled; write=149.943 s, sync=0.000 s, total=150.045 s; sync files=79, longest=0.000 s, average=0.000 s; distance=163338 kB, estimate=163338 kB
2020-10-06 12:41:17.223 UTC [27] LOGG:  checkpoint starting: time
2020-10-06 12:41:17.743 UTC [27] LOGG:  checkpoint complete: wrote 5 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.503 s, sync=0.013 s, total=0.519 s; sync files=4, longest=0.012 s, average=0.003 s; distance=369 kB, estimate=147041 kB

in the log. From what I can tell, nothing much has been done with the Postgres config. I had to increase shm, but other than that it's plain vanilla. I'm not sure what memory areas/config that may improve performance of pg_restore. As you can tell I'm new to postgres (being an imbecile on docker does not seem to help either ;-). So any hints on what may cause this "freeze", or where to look for more info would be appreciated.

EDIT: with the help that @laurenz-albe provided, I could cancel an older restore, and voila the remaining restore was finished in minutes.

I then dropped the db, created it again and checked the following query which resulted in 0 rows:

select pid, application_name, backend_start, state_change, backend_type 
from pg_stat_activity 
where datname = 'testdb';

Then I started a new restore as before and checked the query again. The result is 1 client backend and 2 parallel workers, the workers seems to restart every now and then but the restore seems stuck.

Looking at the query:

select backend_type, query 
from pg_stat_activity 
where datname = 'testdb';

shows that:

client backend  | COPY mind.filer (dokument_uuid, sidnummer, filtyp, tillstand, filnamn) FROM stdin;         +
                 | 
 parallel worker | SELECT lpad(dokument_id::text, 10,'0')        FROM MIND.DOKUMENT where dokument_uuid = DUID
 parallel worker | SELECT lpad(dokument_id::text, 10,'0')        FROM MIND.DOKUMENT where dokument_uuid = DUID

so the workers are running a query from the function used in the generated column. Is it possible that pg_restore is locking itself due to the dependency to another table?

Is it possible to have pg_restore turn of the generated expression during \copy? I got the impression that this was the default after all the value exists already in the dump.

After killing the workers:

postgres=# select pg_cancel_backend(pid) 
    from pg_stat_activity 
    where datname = 'testdb' and backend_type = 'parallel worker';
 pg_cancel_backend 
-------------------
 t
 t
(2 rader)

Restore continues, but the table is then empty after restore

Best Answer

You are stuck behind a lock held by a long running transaction. Examine pg_stat_activity to find long running transactions and look at pg_locks for details about who locks what.

If you find no better way kill the blocking transactions with the pg_cancel_backend function.

I think the problem at the heart of this is the function thst generates the column, which selects from another table. That seems strange - doesn't that mean that the generated column becomes wrong when filsystemsmonteringar is modified? Anyway, I can easily imagine a deadlock between pg_restore jobs if one selects from a table rhat another ALTERs.