Log full with gigabyes of CurTransactionContex

From: Iñigo Martinez Lasala <imartinez(at)vectorsf(dot)com>
To: pgsql-admin(at)postgresql(dot)org
Subject: Log full with gigabyes of CurTransactionContex
Date: 2009-06-15 09:54:00
Message-ID: 1245059640.16064.26.camel@coyote
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-admin

Hi Everybody.

We have a problem with an insert query in one of our clients. This query
is launched in a night batch process. We have observed that if change
set is big (more than 50.000 updates) our database log starts growing
with thousands and thousands of lines until the server is out of space
and database freezes.

This is the query.

set statement_timeout=0;
delete from fnac.alta_stock_precio;
insert into fnac.alta_stock_precio
select
asp_id_fnac,asp_stock,asp_stock_local,asp_pmp,asp_pe,asp_pmv,asp_ventas,asp_id_ean,asp_stock_local_2,asp_stock_almacen_central
from fnac.articulo a , fnac.v_alta_s_p va
where ((asp_id_fnac)::text = (asp_id_fnac)::text) and
(art_descatalogado = 0 or (art_descatalogado=1 and
nvl(va.asp_stock_local_2,0)>0) ) and
lpad(a.art_id_ean,13,0) = lpad(va.asp_id_ean,13,0) and
(nvl(a.art_stock,0) <> nvl(va.asp_stock,0) or
nvl(a.art_stock_local,0) <> nvl(va.asp_stock_local,0) or
nvl(a.art_stock_local_2,0) <> nvl(va.asp_stock_local_2,0) or
nvl(a.art_stock_almacen_central,0) <>
nvl(va.asp_stock_almacen_central,0) or nvl(a.art_pmv,0) <>
nvl(va.asp_pmv,0) or nvl(a.art_precio_fnac_web,0) <> nvl(va.asp_pmv,0)
or nvl(a.art_pe,0) <> nvl(va.asp_pe,0) or nvl(a.art_pmp,0) <>
nvl(va.asp_pmp,0) );

nvl is a simple function (coalesce). This application was translated
from Oracle, so instead of replace nvl with colaesce, developers created
a function called nvl that is a wrapper to coalesce.

Our database server runs under RedHat ES 5.3, with PAE enabled, 16GB and
postgres 8.2.13 32bit.

Postgresql main parameters:
shared_buffers = 2000MB
temp_buffers = 100MB
max_prepared_transactions =10
work_mem = 2000MB
maintenance_work_mem = 1024M
effective_cache_size = 13GB

Well. If count from select is higher that 50.000, log gets writing this:

TopMemoryContext: 9764864 total in 1191 blocks; 27968 free (1195
chunks); 9736896 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 7168 total in 3 blocks; 3288 free (0 chunks); 3880 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 3072 total in 2 blocks; 1360 free (0 chunks); 1712 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 7168 total in 3 blocks; 3248 free (0 chunks); 3920 used
--More--
SPI Plan: 7168 total in 3 blocks; 2568 free (0 chunks); 4600 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 3072 total in 2 blocks; 1408 free (1 chunks); 1664 used
SPI Plan: 7168 total in 3 blocks; 3704 free (0 chunks); 3464 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 3072 total in 2 blocks; 1296 free (0 chunks); 1776 used
SPI Plan: 3072 total in 2 blocks; 2000 free (0 chunks); 1072 used
SPI Plan: 3072 total in 2 blocks; 672 free (0 chunks); 2400 used
SPI Plan: 3072 total in 2 blocks; 1328 free (0 chunks); 1744 used
SPI Plan: 7168 total in 3 blocks; 3896 free (0 chunks); 3272 used
SPI Plan: 7168 total in 3 blocks; 3896 free (0 chunks); 3272 used
SPI Plan: 3072 total in 2 blocks; 56 free (0 chunks); 3016 used
SPI Plan: 3072 total in 2 blocks; 1872 free (0 chunks); 1200 used
SPI Plan: 3072 total in 2 blocks; 1872 free (0 chunks); 1200 used
SPI Plan: 3072 total in 2 blocks; 1872 free (0 chunks); 1200 used
SPI Plan: 1024 total in 1 blocks; 0 free (0 chunks); 1024 used
SPI Plan: 1024 total in 1 blocks; 0 free (0 chunks); 1024 used
SPI Plan: 1024 total in 1 blocks; 0 free (0 chunks); 1024 used
PL/PgSQL function context: 24576 total in 2 blocks; 10592 free (6
chunks); 13984 used
SPI Plan: 31744 total in 6 blocks; 5392 free (0 chunks); 26352 used
SPI Plan: 3072 total in 2 blocks; 1840 free (0 chunks); 1232 used
SPI Plan: 3072 total in 2 blocks; 1840 free (0 chunks); 1232 used
SPI Plan: 3072 total in 2 blocks; 1408 free (1 chunks); 1664 used
SPI Plan: 3072 total in 2 blocks; 1840 free (0 chunks); 1232 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 3072 total in 2 blocks; 1408 free (1 chunks); 1664 used
SPI Plan: 7168 total in 3 blocks; 3248 free (0 chunks); 3920 used
SPI Plan: 7168 total in 3 blocks; 2568 free (0 chunks); 4600 used
SPI Plan: 3072 total in 2 blocks; 1136 free (0 chunks); 1936 used
SPI Plan: 1024 total in 1 blocks; 64 free (0 chunks); 960 used
PL/PgSQL function context: 8192 total in 1 blocks; 7712 free (4 chunks);
480 used
SPI Plan: 3072 total in 2 blocks; 1360 free (0 chunks); 1712 used
SPI Plan: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
--More--
SPI Plan: 3072 total in 2 blocks; 1408 free (1 chunks); 1664 used
SPI Plan: 3072 total in 2 blocks; 1840 free (0 chunks); 1232 used
SPI Plan: 1024 total in 1 blocks; 192 free (0 chunks); 832 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 192 free (0 chunks); 832 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 3072 total in 2 blocks; 1120 free (0 chunks); 1952 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 192 free (0 chunks); 832 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 192 free (0 chunks); 832 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 192 free (0 chunks); 832 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 192 free (0 chunks); 832 used
SPI Plan: 1024 total in 1 blocks; 256 free (0 chunks); 768 used
SPI Plan: 1024 total in 1 blocks; 192 free (0 chunks); 832 used
SPI Plan: 15360 total in 4 blocks; 912 free (0 chunks); 14448 used
PL/PgSQL function context: 57344 total in 3 blocks; 30376 free (23
chunks); 26968 used
SPI Plan: 1024 total in 1 blocks; 32 free (0 chunks); 992 used
PL/PgSQL function context: 8192 total in 1 blocks; 7256 free (3 chunks);
936 used
CFuncHash: 8192 total in 1 blocks; 4936 free (0 chunks); 3256 used
Rendezvous variable hash: 8192 total in 1 blocks; 3848 free (0 chunks);
4344 used
PLpgSQL function cache: 24328 total in 2 blocks; 5904 free (0 chunks);
18424 used
Type information cache: 8192 total in 1 blocks; 1800 free (0 chunks);
6392 used
TopTransactionContext: 2088960 total in 8 blocks; 873576 free (0
chunks); 1215384 used
SPI Exec: 8192 total in 1 blocks; 7992 free (0 chunks); 200 used
ExecutorState: 8192 total in 1 blocks; 3080 free (0 chunks); 5112 used
ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
SPI Proc: 8192 total in 1 blocks; 7848 free (11 chunks); 344 used
CurTransactionContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
AfterTriggerEvents: 8192 total in 1 blocks; 8136 free (0 chunks); 56
used
ExecutorState: 122880 total in 4 blocks; 40264 free (9 chunks); 82616
used
ExprContext: 8192 total in 1 blocks; 8176 free (0 chunks); 16 used
SPI Exec: 8192 total in 1 blocks; 7760 free (0 chunks); 432 used
AfterTriggerTupleContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
ExecutorState: 159908 total in 8 blocks; 56920 free (8 chunks); 102988
used
ExprContext: 8192 total in 1 blocks; 8176 free (0 chunks); 16 used
TIDBitmap: 8192 total in 1 blocks; 3912 free (0 chunks); 4280 used
ExprContext: 8192 total in 1 blocks; 8136 free (0 chunks); 56 used
ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
ExprContext: 8192 total in 1 blocks; 8176 free (0 chunks); 16 used
SPI Proc: 8192 total in 1 blocks; 4960 free (1 chunks); 3232 used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
CurTransactionContext: 8192 total in 1 blocks; 8176 free (5 chunks); 16
used
FOREVER UNTIL OUT OF SPACE....

Any hints?
Increasing temp buffers could help?

Thanks in advance.

Responses

Browse pgsql-admin by date

  From Date Subject
Next Message Suresh Borse 2009-06-15 10:07:32 Re: Log full with gigabyes of CurTransactionContex
Previous Message Michael Monnerie 2009-06-14 18:36:42 Re: HW recommendatons