Thread: Log full with gigabyes of CurTransactionContex

Log full with gigabyes of CurTransactionContex

From

Iñigo Martinez Lasala

Date:

15 June 2009, 09:54:13

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.

Re: Log full with gigabyes of CurTransactionContex

From

Suresh Borse

Date:

15 June 2009, 10:18:01

Hi,

You could stop the query logging on the postgres server.

Disable the query logging parameter in the postgresql.conf file on postgres server.

On Mon, 2009-06-15 at 11:54 +0200, Iñigo Martinez Lasala wrote:

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.

Thanks & Regards,

Suresh Borse
(DBA)
_________________________________________________________________________________________
DIRECTION SOFTWARE SOLUTIONS
5, Brady Gladys Plaza, 1/447, Senapati Bapat Marg, Lower Parel, Mumbai - 400 013
Tel. : 91 22 66615000 (Ext: 350) Fax : 91 22 24911046
Cell : 91 9422 239338 Site : www.direction.biz
_________________________________________________________________________________________

Re: Log full with gigabyes of CurTransactionContex

From

Suresh Borse

Date:

15 June 2009, 10:20:53

Please ignore my previous comment..

Try by increasing the shared_buffer size

On Mon, 2009-06-15 at 11:54 +0200, Iñigo Martinez Lasala wrote:

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.

Re: Log full with gigabyes of CurTransactionContex

From

Tom Lane

Date:

15 June 2009, 14:02:30

=?ISO-8859-1?Q?I=F1igo?= Martinez Lasala <imartinez@vectorsf.com> writes:
> 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.

You're running out of memory.

> work_mem = 2000MB
> maintenance_work_mem = 1024M

These two settings are probably the cause.  With shared_buffers at 2GB,
you do not have anywhere near 1GB to play around with in a 32-bit
environment.  Try something like 200M and 500M.

> Increasing temp buffers could help?

I can hardly think of anything more counterproductive.  You don't
have enough address space.

            regards, tom lane

Re: Log full with gigabyes of CurTransactionContex

From

Iñigo Martinez Lasala

Date:

15 June 2009, 15:13:00

Thank you very much, Tom.

We have increased shared buffers to 2.5GB (linux kernels allows us reach this level) and lowered work_mem to 500MB.
Let's see tonight. :-)

-----Original Message-----
From: Tom Lane <tgl@sss.pgh.pa.us>
To: Iñigo Martinez Lasala <imartinez@vectorsf.com>
Cc: pgsql-admin@postgresql.org
Subject: Re: [ADMIN] Log full with gigabyes of CurTransactionContex
Date: Mon, 15 Jun 2009 10:02:26 -0400

Iñigo Martinez Lasala <imartinez@vectorsf.com> writes:
> 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.

You're running out of memory.

> work_mem = 2000MB
> maintenance_work_mem = 1024M

These two settings are probably the cause.  With shared_buffers at 2GB,
you do not have anywhere near 1GB to play around with in a 32-bit
environment.  Try something like 200M and 500M.

> Increasing temp buffers could help?

I can hardly think of anything more counterproductive.  You don't
have enough address space.
		regards, tom lane

Re: Log full with gigabyes of CurTransactionContex

From

Tom Lane

Date:

15 June 2009, 15:24:00

=?ISO-8859-1?Q?I=F1igo?= Martinez Lasala <imartinez@vectorsf.com> writes:
> We have increased shared buffers to 2.5GB (linux kernels allows us reach
> this level) and lowered work_mem to 500MB.

You are apparently unclear on the concept.  Pushing the database to the
limit of the available address space is probably going to result in
failures.  Redistributing a set of overoptimistic parameters into a
different set of overoptimistic parameters will not fix this.

            regards, tom lane

Re: Log full with gigabyes of CurTransactionContex

From

Gurjeet Singh

Date:

15 June 2009, 15:25:46

On Mon, Jun 15, 2009 at 8:42 PM, Iñigo Martinez Lasala <imartinez@vectorsf.com> wrote:

Thank you very much, Tom.

We have increased shared buffers to 2.5GB (linux kernels allows us reach this level) and lowered work_mem to 500MB.
Let's see tonight. :-)

If you want to increase shared buffers beyond this value, you should look at increasing shmmax in sysctl.conf.

Best regards,
--
Lets call it Postgres

EnterpriseDB http://www.enterprisedb.com

gurjeet[.singh]@EnterpriseDB.com
singh.gurjeet@{ gmail | hotmail | indiatimes | yahoo }.com
Mail sent from my BlackLaptop device

Re: Log full with gigabyes of CurTransactionContex

From

Iñigo Martinez Lasala

Date:

15 June 2009, 15:51:42

Hmmm... OK.

In parallel we have changed the procedure in order to process insert queries in smaller chunks. In our preproduction environment has solved the problem.

-----Original Message-----
From: Tom Lane <tgl@sss.pgh.pa.us>
To: Iñigo Martinez Lasala <imartinez@vectorsf.com>
Cc: pgsql-admin@postgresql.org
Subject: Re: [ADMIN] Log full with gigabyes of CurTransactionContex
Date: Mon, 15 Jun 2009 11:23:45 -0400

Iñigo Martinez Lasala <imartinez@vectorsf.com> writes:
> We have increased shared buffers to 2.5GB (linux kernels allows us reach
> this level) and lowered work_mem to 500MB.

You are apparently unclear on the concept.  Pushing the database to the
limit of the available address space is probably going to result in
failures.  Redistributing a set of overoptimistic parameters into a
different set of overoptimistic parameters will not fix this.
		regards, tom lane

Re: Log full with gigabyes of CurTransactionContex

From

Michael Monnerie

Date:

15 June 2009, 20:19:00

On Montag 15 Juni 2009 Tom Lane wrote:
> These two settings are probably the cause.  With shared_buffers at
> 2GB, you do not have anywhere near 1GB to play around with in a
> 32-bit environment.  Try something like 200M and 500M.

Wouldn't a recommendation to switch to 64bit PostgreSQL be a good idea
also? Maybe his servers can't do that, I don't know.

Also, I've heard that using shared_buffers = 500MB is enough (even in
64bit), and the rest will be cached by Linux cache alone. Is that true?

mfg zmi
--
// Michael Monnerie, Ing.BSc    -----      http://it-management.at
// Tel: 0660 / 415 65 31                      .network.your.ideas.
// PGP Key:         "curl -s http://zmi.at/zmi.asc | gpg --import"
// Fingerprint: AC19 F9D5 36ED CD8A EF38  500E CE14 91F7 1C12 09B4
// Keyserver: wwwkeys.eu.pgp.net                  Key-ID: 1C1209B4

Re: Log full with gigabyes of CurTransactionContex

From

Tom Lane

Date:

15 June 2009, 20:29:08

Michael Monnerie <michael.monnerie@is.it-management.at> writes:
> On Montag 15 Juni 2009 Tom Lane wrote:
>> These two settings are probably the cause. �With shared_buffers at
>> 2GB, you do not have anywhere near 1GB to play around with in a
>> 32-bit environment. �Try something like 200M and 500M.

> Wouldn't a recommendation to switch to 64bit PostgreSQL be a good idea
> also? Maybe his servers can't do that, I don't know.

If he wants numbers that high, he'd need to go to a 64bit build.
It's not clear from here whether any actual benefit would ensue, though.

> Also, I've heard that using shared_buffers = 500MB is enough (even in
> 64bit), and the rest will be cached by Linux cache alone. Is that true?

Yeah, the existence of kernel disk cache tends to negate the benefit of
very large shared_buffer settings.  See the pgsql-performance archives
for many many discussions about such matters.

            regards, tom lane