0

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

1
  • It's exactly 5 minutes between entries in log, so I trust that they are triggered by checkpoint_timeout – Lennart Oct 6 '20 at 14:43
1

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.

7
  • Thanks a lot. It turned out that an older restore was still in play. What I don't understand is what caused the first restore to hang, no one beside me is using the system. Anyhow, you have provided me with the tools that I needed. I'll repeat the process and see if I can repeat the problem. – Lennart Oct 6 '20 at 16:44
  • I'll add some additional info in the question, it becomes too long for a comment – Lennart Oct 6 '20 at 17:20
  • That was the good thing to do - add the information to the question. Generated columns have to be calculated when the row is created, that's the idea. It may well be that an ill-chosen generated column may lock with something else. Also, what is visible in pg_locks when processing hangs? – Laurenz Albe Oct 7 '20 at 5:55
  • The column is generated as: mind.uuid_2_path(dokument_uuid) || rtrim(filnamn) The function splits the uuid in parts, looks up the mount point and concatenates (see question) – Lennart Oct 7 '20 at 6:00
  • I think I understand the problem. See my extended answer. – Laurenz Albe Oct 7 '20 at 6:02

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.