Обсуждение: OOM killer while pg_restore

Hello,

We have a pg_restore which fails due to RAM over-consumption of the corresponding PG backend, which ends-up with OOM killer.

The table has one PK, one index, and 3 FK constraints, active while restoring.
The dump contains over 200M rows for that table and is in custom format, which corresponds to 37 GB of total relation size in the original DB.

While importing, one can see the RSS + swap increasing linearly for the backend (executing the COPY)

On my machine (quite old PC), it failed after 16 hours, while the disk usage was reaching 26 GB and memory usage was 9.1g (RSS+swap)

If we do the same test, suppressing firstly the 5 constraints on the table, the restore takes less than 15 minutes !

This was tested on both PG 14.2 and PG 13.6 (linux 64-bit machines).

It there a memory leak or that is normal that a bacend process may exhaust the RAM to such an extent ?

Thanks

Regards

Em qui., 3 de mar. de 2022 às 05:59, Marc Rechté <marc4@rechte.fr> escreveu:
>
>     Hello,
>
>     We have a pg_restore which fails due to RAM over-consumption of
>     the corresponding PG backend, which ends-up with OOM killer.
>
>     The table has one PK, one index, and 3 FK constraints, active
>     while restoring.
>     The dump contains over 200M rows for that table and is in custom
>     format, which corresponds to 37 GB of total relation size in the
>     original DB.
>
>     While importing, one can see the RSS + swap increasing linearly
>     for the backend (executing the COPY)
>
>     On my machine (quite old PC), it failed after 16 hours, while the
>     disk usage was reaching 26 GB and memory usage was 9.1g (RSS+swap)
>
>     If we do the same test, suppressing firstly the 5 constraints on
>     the table, the restore takes less than 15 minutes !
>
>     This was tested on both PG 14.2 and PG 13.6 (linux 64-bit machines).
>
>     It there a memory leak or that is normal that a bacend process may
>     exhaust the RAM to such an extent ?
>
> Hi Marc,
> Can you post the server logs?
>
> regards,
> Ranier Vilela

Will it help ?

2022-02-25 12:01:29.306 GMT [1468:24] user=,db=,app=,client= LOG:  
server process (PID 358995) was terminated by signal 9: Killed
2022-02-25 12:01:29.306 GMT [1468:25] user=,db=,app=,client= DETAIL:  
Failed process was running: COPY simulations_ecarts_relatifs_saison 
(idpoint, annee, saison, idreferentiel, ecartreltav, ecartreltnav, 
ecartreltxav, ecartreltrav, ecartreltxq90, ecartreltxq10, ecartreltnq10, 
ecartreltnq90, ecartreltxnd, ecartreltnnd, ecartreltnht, ecartreltxhwd, 
ecartreltncwd, ecartreltnfd, ecartreltxfd, ecartrelsd, ecartreltr, 
ecartrelhdd, ecartrelcdd, ecartrelpav, ecartrelpint, ecartrelrr, 
ecartrelpfl90, ecartrelrr1mm, ecartrelpxcwd, ecartrelpn20mm, 
ecartrelpxcdd, ecartrelhusav, ecartreltx35, ecartrelpq90, ecartrelpq99, 
ecartrelrr99, ecartrelffav, ecartrelff3, ecartrelffq98, ecartrelff98) 
FROM stdin;

2022-02-25 12:01:29.306 GMT [1468:26] user=,db=,app=,client= LOG: 
terminating any other active server processes
2022-02-25 12:01:29.311 GMT [1468:27] user=,db=,app=,client= LOG: all 
server processes terminated; reinitializing
2022-02-25 12:01:29.311 GMT [1468:27] user=,db=,app=,client= LOG: all 
server processes terminated; reinitializing
2022-02-25 12:01:29.326 GMT [360309:1] user=,db=,app=,client= LOG:  
database system was interrupted; last known up at 2022-02-25 12:01:12 GMT
2022-02-25 12:01:29.362 GMT [360310:1] 
user=[unknown],db=[unknown],app=[unknown],client=[local] LOG: connection 
received: host=[local]
2022-02-25 12:01:29.363 GMT [360310:2] 
user=postgres,db=drias,app=[unknown],client=[local] FATAL:  the database 
system is in recovery mode
2022-02-25 12:01:29.365 GMT [360309:2] user=,db=,app=,client= LOG:  
database system was not properly shut down; automatic recovery in progress
2022-02-25 12:01:29.367 GMT [360309:3] user=,db=,app=,client= LOG:  redo 
starts at C3/1E0D31F0
2022-02-25 12:01:40.845 GMT [360309:4] user=,db=,app=,client= LOG:  redo 
done at C3/6174BC00 system usage: CPU: user: 4.15 s, system: 1.40 s, 
elapsed: 11.47 s
2022-02-25 12:01:40.847 GMT [360309:5] user=,db=,app=,client= LOG:  
checkpoint starting: end-of-recovery immediate
2022-02-25 12:01:41.806 GMT [360309:6] user=,db=,app=,client= LOG:  
checkpoint complete: wrote 125566 buffers (100.0%); 0 WAL file(s) added, 
54 removed, 13 recycled; write=0.915 s, sync=0.001 s, total=0.960 s; 
sync files=10, longest=0.001 s, average=0.001 s; distance=1104355 kB, 
estimate=1104355 kB
2022-02-25 12:01:41.810 GMT [1468:28] user=,db=,app=,client= LOG: 
database system is ready to accept connections

On Thu, Mar 03, 2022 at 09:59:03AM +0100, Marc Rechté wrote:
> Hello,
> 
> We have a pg_restore which fails due to RAM over-consumption of the
> corresponding PG backend, which ends-up with OOM killer.
> 
> The table has one PK, one index, and 3 FK constraints, active while restoring.

Send the schema for the table, index, and constraints (\d in psql).

What are the server settings ?
https://wiki.postgresql.org/wiki/Server_Configuration

What OS/version ?

> The dump contains over 200M rows for that table and is in custom format,
> which corresponds to 37 GB of total relation size in the original DB.
> 
> While importing, one can see the RSS + swap increasing linearly for the
> backend (executing the COPY)
> 
> On my machine (quite old PC), it failed after 16 hours, while the disk usage
> was reaching 26 GB and memory usage was 9.1g (RSS+swap)

=?UTF-8?Q?Marc_Recht=c3=a9?= <marc4@rechte.fr> writes:
> We have a pg_restore which fails due to RAM over-consumption of the 
> corresponding PG backend, which ends-up with OOM killer.
> The table has one PK, one index, and 3 FK constraints, active while 
> restoring.
> The dump contains over 200M rows for that table and is in custom format, 
> which corresponds to 37 GB of total relation size in the original DB.

The FKs would result in queueing row trigger events, which would occupy
some memory.  But those should only need ~12 bytes per FK per row,
which works out to less than 10GB for this number of rows, so it may
be that you've hit something else that we would consider a leak.

Does memory consumption hold steady if you drop the FK constraints?

If not, as others have noted, we'd need more info to investigate
this.  The leak is probably independent of the specific data in
the table, so maybe you could make a small self-contained example
using a script to generate dummy data.

            regards, tom lane

Le 03/03/2022 à 16:31, Tom Lane a écrit :
> =?UTF-8?Q?Marc_Recht=c3=a9?= <marc4@rechte.fr> writes:
>> We have a pg_restore which fails due to RAM over-consumption of the
>> corresponding PG backend, which ends-up with OOM killer.
>> The table has one PK, one index, and 3 FK constraints, active while
>> restoring.
>> The dump contains over 200M rows for that table and is in custom format,
>> which corresponds to 37 GB of total relation size in the original DB.
> The FKs would result in queueing row trigger events, which would occupy
> some memory.  But those should only need ~12 bytes per FK per row,
> which works out to less than 10GB for this number of rows, so it may
> be that you've hit something else that we would consider a leak.
>
> Does memory consumption hold steady if you drop the FK constraints?
>
> If not, as others have noted, we'd need more info to investigate
> this.  The leak is probably independent of the specific data in
> the table, so maybe you could make a small self-contained example
> using a script to generate dummy data.
>
>             regards, tom lane
>
>
Actually the number of rows is 232735712.

Accordingly the RAM consumption would be x12 x3 = 7.8 GiB.

This is close to the 8,1g I reported earlier (actually it was closer to 
7.8 GB, due to GiB vs. GB confusion).

So there is no memory leak.

It took 16 hours on my box to reach that RAM consumption, and then the 
COPY failed when checking the first FK (as the referenced table was empty).

I dropped the FK, index, and 3 FK constraints and started over the 
pg_restore:

11 minutes to load the table (I did not have time to note RAM consumption)

I then created the PK and index:

24 minutes

For FK, I don't know because the referenced table are empty (but I'll be 
able to test next week, if deemed necessary).

16 hours vs. 35 minutes to reach the same state.

This is the data structure:

=================

--
-- Name: simulations_ecarts_relatifs_saison; Type: TABLE; Schema: 
donnees2019; Owner: drias; Tablespace:
--

CREATE TABLE simulations_ecarts_relatifs_saison (
     idpoint integer NOT NULL,
     annee integer NOT NULL,
     saison integer NOT NULL,
     idreferentiel integer NOT NULL,
     ecartreltav real,
     ecartreltnav real,
     ecartreltxav real,
     ecartreltrav real,
     ecartreltxq90 real,
     ecartreltxq10 real,
     ecartreltnq10 real,
     ecartreltnq90 real,
     ecartreltxnd smallint,
     ecartreltnnd smallint,
     ecartreltnht smallint,
     ecartreltxhwd smallint,
     ecartreltncwd smallint,
     ecartreltnfd smallint,
     ecartreltxfd smallint,
     ecartrelsd smallint,
     ecartreltr smallint,
     ecartrelhdd real,
     ecartrelcdd real,
     ecartrelpav real,
     ecartrelpint real,
     ecartrelrr real,
     ecartrelpfl90 real,
     ecartrelrr1mm real,
     ecartrelpxcwd smallint,
     ecartrelpn20mm smallint,
     ecartrelpxcdd smallint,
     ecartrelhusav real,
     ecartreltx35 real,
     ecartrelpq90 real,
     ecartrelpq99 real,
     ecartrelrr99 real,
     ecartrelffav real,
     ecartrelff3 real,
     ecartrelffq98 real,
     ecartrelff98 real
);

--
-- Name: pk_simulations_ecarts_relatifs_saison_2019; Type: CONSTRAINT; 
Schema: donnees2019; Owner: drias; Tablespace:
--

ALTER TABLE ONLY simulations_ecarts_relatifs_saison
     ADD CONSTRAINT pk_simulations_ecarts_relatifs_saison_2019 PRIMARY 
KEY (idpoint, annee, saison, idreferentiel);

--
-- Name: i_expe_annee_saison_simulations_ecarts_relatifs_saison_2019; 
Type: INDEX; Schema: donnees2019; Owner: drias; Tablespace:
--

CREATE INDEX i_expe_annee_saison_simulations_ecarts_relatifs_saison_2019 
ON simulations_ecarts_relatifs_saison USING btree (idreferentiel, annee, 
saison);

--
-- Name: fk_id_point_ecarts_relatifs_saison_2019; Type: FK CONSTRAINT; 
Schema: donnees2019; Owner: drias
--

ALTER TABLE ONLY simulations_ecarts_relatifs_saison
     ADD CONSTRAINT fk_id_point_ecarts_relatifs_saison_2019 FOREIGN KEY 
(idpoint) REFERENCES grilles.points_grille(id);


--
-- Name: fk_id_referentiel_ecarts_relatifs_saison_2019; Type: FK 
CONSTRAINT; Schema: donnees2019; Owner: drias
--

ALTER TABLE ONLY simulations_ecarts_relatifs_saison
     ADD CONSTRAINT fk_id_referentiel_ecarts_relatifs_saison_2019 
FOREIGN KEY (idreferentiel) REFERENCES 
referentiel.referentiel_simulations(id);

--
-- Name: fk_saison_ecarts_relatifs_saison_2019; Type: FK CONSTRAINT; 
Schema: donnees2019; Owner: drias
--

ALTER TABLE ONLY simulations_ecarts_relatifs_saison
     ADD CONSTRAINT fk_saison_ecarts_relatifs_saison_2019 FOREIGN KEY 
(saison) REFERENCES donnees.liste_saison(code_saison);

This is how is init / started the test instance:

=============================

$ initdb -D $MYDIR
$ pg_ctl -D $MYDIR -o "-p 5432 -c unix_socket_directories=. -c 
shared_buffers=981MB -c work_mem=20MB -c maintenance_work_mem=98MB" start

=?UTF-8?Q?Marc_Recht=c3=a9?= <marc4@rechte.fr> writes:
> Le 03/03/2022 à 16:31, Tom Lane a écrit :
>> Does memory consumption hold steady if you drop the FK constraints?

> Actually the number of rows is 232735712.
> Accordingly the RAM consumption would be x12 x3 = 7.8 GiB.
> This is close to the 8,1g I reported earlier (actually it was closer to 
> 7.8 GB, due to GiB vs. GB confusion).

> So there is no memory leak.

> It took 16 hours on my box to reach that RAM consumption, and then the 
> COPY failed when checking the first FK (as the referenced table was empty).

I'm guessing it was swapping like mad :-(

We've long recommended dropping FK constraints during bulk data loads,
and then re-establishing them later.  That's a lot cheaper than retail
validity checks, even without the memory-consumption angle.  Ideally
that sort of behavior would be automated, but nobody's gotten that
done yet.  (pg_restore does do it like that during a full restore,
but not for a data-only restore, so I guess you were doing the latter.)

            regards, tom lane

Le 03/03/2022 à 19:43, Tom Lane a écrit :
> =?UTF-8?Q?Marc_Recht=c3=a9?= <marc4@rechte.fr> writes:
>> Le 03/03/2022 à 16:31, Tom Lane a écrit :
>>> Does memory consumption hold steady if you drop the FK constraints?
>> Actually the number of rows is 232735712.
>> Accordingly the RAM consumption would be x12 x3 = 7.8 GiB.
>> This is close to the 8,1g I reported earlier (actually it was closer to
>> 7.8 GB, due to GiB vs. GB confusion).
>> So there is no memory leak.
>> It took 16 hours on my box to reach that RAM consumption, and then the
>> COPY failed when checking the first FK (as the referenced table was empty).
> I'm guessing it was swapping like mad :-(
>
> We've long recommended dropping FK constraints during bulk data loads,
> and then re-establishing them later.  That's a lot cheaper than retail
> validity checks, even without the memory-consumption angle.  Ideally
> that sort of behavior would be automated, but nobody's gotten that
> done yet.  (pg_restore does do it like that during a full restore,
> but not for a data-only restore, so I guess you were doing the latter.)
>
>             regards, tom lane
>
>
Did the test without the 3 FK, but with PK and index:

I took 9.5 hours and consumed 1GB of RAM (vs. 16 hours and 8 GB).

Thanks you for the explanations.

I  assume there is currently no GUC to limit RAM consumption of a backend ?

Marc