pg.ddx.io pgsql-bugs@postgresql.org mailing list archive
help / color / mirror / Atom feedpg_restore deadlocks with itself
5+ messages / 2 participants
[nested] [flat]
* pg_restore deadlocks with itself
@ 2022-08-25 12:44 hubert depesz lubaczewski <depesz@depesz.com>
0 siblings, 1 reply; 5+ messages in thread
From: hubert depesz lubaczewski @ 2022-08-25 12:44 UTC (permalink / raw)
To: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
Hi,
I have Pg 14.4 on arm64, and I'm loading schema dump from pg12.
Specifically, command to run it is:
sudo -u postgres pg_restore -j 64 -d database -L /tmp/schema-post-data.nopkey.list /tmp/schema-post-data.dump
where /tmp/schema-post-data.dump is dump made using:
sudo -u postgres pg_dump --schema-only --compress=9 --format=c --section='post-data' --schema='*(something|else|xxx)*' database
and /tmp/schema-post-data.nopkey.list is made using:
#v+
pkey_regexp='^\d+; \d+ \d+ CONSTRAINT \S+ \S+ \S+_pkey '
pg_restore -l "${local_dump_dir}/schema-post-data.dump" | grep -vP "${pkey_regexp}" > "${local_dump_dir}/schema-post-data.nopkey.list"
#v-
The thing is that the list file has 7676 lines, out of which 2313 are
foreign keys.
database has basically 3 schemas, and fkeys NEVER cross schema.
When loading the dump I got reported 4 errors, but log shows 2 deadlocks.
perhaps all sides got cancelled, not sure, will investigate further, but logs
show:
2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,42,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1932,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.647 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_a_o
ADD CONSTRAINT table_a_o_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
",,,"pg_restore","client backend",,3355460102417501954
2022-08-24 20:01:50.291 UTC,"postgres","database",3343477,"[local]",630624ad.330475,46,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1933,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.030 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_a
ADD CONSTRAINT fk_rails_46718e626a FOREIGN KEY (migrate_from_id) REFERENCES some_schema.table_q(id);
",,,"pg_restore","client backend",,-2548896815899838768
Now, I know I can fix the situation by adding missing fkeys myself, but
I don't think pg_restore should be putting itself in deadlock.
Best regards,
depesz
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg_restore deadlocks with itself
@ 2022-08-30 09:06 Alvaro Herrera <alvherre@alvh.no-ip.org>
parent: hubert depesz lubaczewski <depesz@depesz.com>
0 siblings, 1 reply; 5+ messages in thread
From: Alvaro Herrera @ 2022-08-30 09:06 UTC (permalink / raw)
To: hubert depesz lubaczewski <depesz@depesz.com>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On 2022-Aug-25, hubert depesz lubaczewski wrote:
> Specifically, command to run it is:
> sudo -u postgres pg_restore -j 64 -d database -L /tmp/schema-post-data.nopkey.list /tmp/schema-post-data.dump
> 2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,42,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1932,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.647 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_a_o
> ADD CONSTRAINT table_a_o_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
> ",,,"pg_restore","client backend",,3355460102417501954
>
>
> 2022-08-24 20:01:50.291 UTC,"postgres","database",3343477,"[local]",630624ad.330475,46,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1933,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.030 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_a
> ADD CONSTRAINT fk_rails_46718e626a FOREIGN KEY (migrate_from_id) REFERENCES some_schema.table_q(id);
> ",,,"pg_restore","client backend",,-2548896815899838768
>
> Now, I know I can fix the situation by adding missing fkeys myself, but
> I don't think pg_restore should be putting itself in deadlock.
You're right, it shouldn't. Parallel restore shouldn't run DDL commands
in parallel that would deadlock, but I suppose there must be holes in
that.
What was process 3587718 doing at the time? Some DDL in
some_schema.table_q, I suspect, right? Are any of these tables
partitioned?
The "Wait queue: ." bit is ugly.
--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
"The problem with the facetime model is not just that it's demoralizing, but
that the people pretending to work interrupt the ones actually working."
(Paul Graham)
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg_restore deadlocks with itself
@ 2022-08-30 09:16 hubert depesz lubaczewski <depesz@depesz.com>
parent: Alvaro Herrera <alvherre@alvh.no-ip.org>
0 siblings, 1 reply; 5+ messages in thread
From: hubert depesz lubaczewski @ 2022-08-30 09:16 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Tue, Aug 30, 2022 at 11:06:34AM +0200, Alvaro Herrera wrote:
> On 2022-Aug-25, hubert depesz lubaczewski wrote:
>
> > Specifically, command to run it is:
> > sudo -u postgres pg_restore -j 64 -d database -L /tmp/schema-post-data.nopkey.list /tmp/schema-post-data.dump
>
> > 2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,42,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1932,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.647 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_a_o
> > ADD CONSTRAINT table_a_o_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
> > ",,,"pg_restore","client backend",,3355460102417501954
> >
> >
> > 2022-08-24 20:01:50.291 UTC,"postgres","database",3343477,"[local]",630624ad.330475,46,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1933,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.030 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_a
> > ADD CONSTRAINT fk_rails_46718e626a FOREIGN KEY (migrate_from_id) REFERENCES some_schema.table_q(id);
> > ",,,"pg_restore","client backend",,-2548896815899838768
> >
> > Now, I know I can fix the situation by adding missing fkeys myself, but
> > I don't think pg_restore should be putting itself in deadlock.
>
> You're right, it shouldn't. Parallel restore shouldn't run DDL commands
> in parallel that would deadlock, but I suppose there must be holes in
> that.
>
> What was process 3587718 doing at the time? Some DDL in
> some_schema.table_q, I suspect, right? Are any of these tables
> partitioned?
So, more info from logs:
2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,43,"ALTER TABLE",2022-08-24 13:16:29 UTC,21/1932,0,ERROR,40P01,"deadlock detected","Process 3343477 waits for ShareRowExclusiveLock on relation 742617610 of database 16641; blocked by process 3587718.
Process 3587718 waits for RowExclusiveLock on relation 742615338 of database 16641; blocked by process 3343477.
Process 3343477: ALTER TABLE ONLY some_schema.table_ao
ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
Process 3587718: <command string not enabled>","See server log for query details.",,,,"ALTER TABLE ONLY some_schema.table_ao
ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
",,,"pg_restore","client backend",,3355460102417501954
Which is weird, as it seems that they both were trying to do the same fkey?!
Neither table_ao nor table_q are partitioned, and used restore-list contained this fkey only once.
Best regards,
depesz
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg_restore deadlocks with itself
@ 2022-08-30 09:29 Alvaro Herrera <alvherre@alvh.no-ip.org>
parent: hubert depesz lubaczewski <depesz@depesz.com>
0 siblings, 1 reply; 5+ messages in thread
From: Alvaro Herrera @ 2022-08-30 09:29 UTC (permalink / raw)
To: hubert depesz lubaczewski <depesz@depesz.com>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On 2022-Aug-30, hubert depesz lubaczewski wrote:
> 2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,43,"ALTER TABLE",2022-08-24 13:16:29 UTC,21/1932,0,ERROR,40P01,"deadlock detected","Process 3343477 waits for ShareRowExclusiveLock on relation 742617610 of database 16641; blocked by process 3587718.
> Process 3587718 waits for RowExclusiveLock on relation 742615338 of database 16641; blocked by process 3343477.
> Process 3343477: ALTER TABLE ONLY some_schema.table_ao
> ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
>
>
>
> Process 3587718: <command string not enabled>","See server log for query details.",,,,"ALTER TABLE ONLY some_schema.table_ao
> ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
>
>
> ",,,"pg_restore","client backend",,3355460102417501954
>
> Which is weird, as it seems that they both were trying to do the same fkey?!
>
> Neither table_ao nor table_q are partitioned, and used restore-list contained this fkey only once.
Hmm, you said table_a_o and table_a first, but now you say table_ao. I
suspect that's just a typo resulting from anonymizing table names. Right?
OK, so no partitioning. But are there any inheritance relationship
between these tables?
--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
"No es bueno caminar con un hombre muerto"
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: pg_restore deadlocks with itself
@ 2022-08-30 09:58 hubert depesz lubaczewski <depesz@depesz.com>
parent: Alvaro Herrera <alvherre@alvh.no-ip.org>
0 siblings, 0 replies; 5+ messages in thread
From: hubert depesz lubaczewski @ 2022-08-30 09:58 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: PostgreSQL mailing lists <pgsql-bugs@lists.postgresql.org>
On Tue, Aug 30, 2022 at 11:29:37AM +0200, Alvaro Herrera wrote:
> On 2022-Aug-30, hubert depesz lubaczewski wrote:
>
> > 2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,43,"ALTER TABLE",2022-08-24 13:16:29 UTC,21/1932,0,ERROR,40P01,"deadlock detected","Process 3343477 waits for ShareRowExclusiveLock on relation 742617610 of database 16641; blocked by process 3587718.
> > Process 3587718 waits for RowExclusiveLock on relation 742615338 of database 16641; blocked by process 3343477.
> > Process 3343477: ALTER TABLE ONLY some_schema.table_ao
> > ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
> >
> >
> >
> > Process 3587718: <command string not enabled>","See server log for query details.",,,,"ALTER TABLE ONLY some_schema.table_ao
> > ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
> >
> >
> > ",,,"pg_restore","client backend",,3355460102417501954
> >
> > Which is weird, as it seems that they both were trying to do the same fkey?!
> >
> > Neither table_ao nor table_q are partitioned, and used restore-list contained this fkey only once.
>
> Hmm, you said table_a_o and table_a first, but now you say table_ao. I
> suspect that's just a typo resulting from anonymizing table names. Right?
>
> OK, so no partitioning. But are there any inheritance relationship
> between these tables?
There were two deadlocks, I might have copy/pasted info from another
case.
These are *all* deadlock related messages from the log, all where
anonymized using regexps, no manual intervention, so the changes should
be consistent.
======================================================
2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,42,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1932,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.647 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_ao
ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
",,,"pg_restore","client backend",,3355460102417501954
======================================================
2022-08-24 20:01:04.466 UTC,"postgres","database",3343477,"[local]",630624ad.330475,43,"ALTER TABLE",2022-08-24 13:16:29 UTC,21/1932,0,ERROR,40P01,"deadlock detected","Process 3343477 waits for ShareRowExclusiveLock on relation 742617610 of database 16641; blocked by process 3587718.
Process 3587718 waits for RowExclusiveLock on relation 742615338 of database 16641; blocked by process 3343477.
Process 3343477: ALTER TABLE ONLY some_schema.table_ao
ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
Process 3587718: <command string not enabled>","See server log for query details.",,,,"ALTER TABLE ONLY some_schema.table_ao
ADD CONSTRAINT table_ao_q_id_fk FOREIGN KEY (q_id) REFERENCES some_schema.table_q(id);
",,,"pg_restore","client backend",,3355460102417501954
======================================================
2022-08-24 20:01:50.291 UTC,"postgres","database",3343477,"[local]",630624ad.330475,46,"ALTER TABLE waiting",2022-08-24 13:16:29 UTC,21/1933,0,LOG,00000,"process 3343477 detected deadlock while waiting for ShareRowExclusiveLock on relation 742617610 of database 16641 after 1000.030 ms","Process holding the lock: 3587718. Wait queue: .",,,,,"ALTER TABLE ONLY some_schema.table_a
ADD CONSTRAINT fk_rails_46718e626a FOREIGN KEY (migrate_from_id) REFERENCES some_schema.table_q(id);
",,,"pg_restore","client backend",,-2548896815899838768
======================================================
2022-08-24 20:01:50.291 UTC,"postgres","database",3343477,"[local]",630624ad.330475,47,"ALTER TABLE",2022-08-24 13:16:29 UTC,21/1933,0,ERROR,40P01,"deadlock detected","Process 3343477 waits for ShareRowExclusiveLock on relation 742617610 of database 16641; blocked by process 3587718.
Process 3587718 waits for RowExclusiveLock on relation 742615348 of database 16641; blocked by process 3343477.
Process 3343477: ALTER TABLE ONLY some_schema.table_a
ADD CONSTRAINT fk_rails_46718e626a FOREIGN KEY (migrate_from_id) REFERENCES some_schema.table_q(id);
Process 3587718: <command string not enabled>","See server log for query details.",,,,"ALTER TABLE ONLY some_schema.table_a
ADD CONSTRAINT fk_rails_46718e626a FOREIGN KEY (migrate_from_id) REFERENCES some_schema.table_q(id);
",,,"pg_restore","client backend",,-2548896815899838768
======================================================
As for inheritance - none of table_a, table_ao, table_q has any
inheritance. There are tables with inheritance in this db, but not
these.
It is, though, possible that one of table_a/ao/q has fkey pointing to
some inherited table, or some inherited table has fkey to _a/_ao/_q
- would that matter? i can dig details if it would be interesting.
Best regards,
depesz
^ permalink raw reply [nested|flat] 5+ messages in thread
end of thread, other threads:[~2022-08-30 09:58 UTC | newest]
Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2022-08-25 12:44 pg_restore deadlocks with itself hubert depesz lubaczewski <depesz@depesz.com>
2022-08-30 09:06 ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2022-08-30 09:16 ` hubert depesz lubaczewski <depesz@depesz.com>
2022-08-30 09:29 ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2022-08-30 09:58 ` hubert depesz lubaczewski <depesz@depesz.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox