8.4devel out of memory

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> wrote:

ERROR: out of memory
DETAIL: Failed on request of size 8.

What would be the reasonable next step here?

I bet the log would be of interest. :-)

-Kevin

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:

PortalHeapMemory: 1620992 total in 200 blocks; 5856 free (8 chunks); 1615136 used
ExecutorState: 2787288448 total in 364 blocks; 328 free (5 chunks); 2787288120 used

Ouch. We have created a memory leak someplace, but it's hard to tell
where from this info. Can you boil this down into a self-contained test
case? I doubt it depends at all on the specific data, so the table &
view definitions plus some dummy data would probably be enough to
reproduce it.

Is this a 32-bit or 64-bit build? Also, does the leak still occur if
you just run the query as-is rather than EXPLAIN ANALYZE it?

regards, tom lane

Tom Lane <tgl@sss.pgh.pa.us> wrote:

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:

PortalHeapMemory: 1620992 total in 200 blocks; 5856 free (8

chunks);

1615136 used

ExecutorState: 2787288448 total in 364 blocks; 328 free (5

chunks);

2787288120 used

Ouch. We have created a memory leak someplace, but it's hard to

tell

where from this info. Can you boil this down into a self-contained

test

case? I doubt it depends at all on the specific data, so the table

&

view definitions plus some dummy data would probably be enough to
reproduce it.

The tables and views aren't that hard; finding a way to generate
enough fake data may be a challenge. (I assume that since it took
over a half hour to run out of memory, the volume of data needs to be
sufficient to get there.)

Is this a 32-bit or 64-bit build?

32-bit PostgreSQL on 32-bit Linux.

Also, does the leak still occur if
you just run the query as-is rather than EXPLAIN ANALYZE it?

I will find out.

-Kevin

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:

The tables and views aren't that hard; finding a way to generate
enough fake data may be a challenge. (I assume that since it took
over a half hour to run out of memory, the volume of data needs to be
sufficient to get there.)

We don't really need 2GB of leakage to find the problem ... a query
that generates a couple hundred meg of bloat would be plenty.

Since we don't know how much space the query would have needed to run to
completion, it's likely that something involving much less than a tenth
as much data would still be enough to make the leak obvious.

regards, tom lane

Tom Lane <tgl@sss.pgh.pa.us> wrote:

Also, does the leak still occur if
you just run the query as-is rather than EXPLAIN ANALYZE it?

The machine became unresponsive similar to the early symptoms of the
apparent memory leak cited in this post:

http://archives.postgresql.org/pgsql-bugs/2008-07/msg00105.php

It was impossible to kill the offending process, since the connections
were unresponsive; we didn't wait for the OOM killer, but rebooted the
machine.

-Kevin

Tom Lane <tgl@sss.pgh.pa.us> wrote:

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:

The tables and views aren't that hard; finding a way to generate
enough fake data may be a challenge. (I assume that since it took
over a half hour to run out of memory, the volume of data needs to

be

sufficient to get there.)

We don't really need 2GB of leakage to find the problem ... a query
that generates a couple hundred meg of bloat would be plenty.

Since we don't know how much space the query would have needed to run

to

completion, it's likely that something involving much less than a

tenth

as much data would still be enough to make the leak obvious.

I've got the database down to the minimum database objects needed for
the query (three tables, five views on them, and a bunch of domains),
and gotten those tables down to 10% of their original size, with all
confidential data turned to meaningless literals. The problem still
happens on today's snapshot.

kgrittn@OLR-DEV-PG:~> cat /proc/version
Linux version 2.6.5-7.286-bigsmp (geeko@buildhost) (gcc version 3.3.3
(SuSE Linux)) #1 SMP Thu May 31 10:12:58 UTC 2007
kgrittn@OLR-DEV-PG:~> cat /etc/SuSE-release
SUSE LINUX Enterprise Server 9 (i586)
VERSION = 9
PATCHLEVEL = 3
kgrittn@OLR-DEV-PG:~> /usr/local/pgsql-8.4dev-20081008/bin/pg_config
BINDIR = /usr/local/pgsql-8.4dev-20081008/bin
DOCDIR = /usr/local/pgsql-8.4dev-20081008/share/doc
HTMLDIR = /usr/local/pgsql-8.4dev-20081008/share/doc
INCLUDEDIR = /usr/local/pgsql-8.4dev-20081008/include
PKGINCLUDEDIR = /usr/local/pgsql-8.4dev-20081008/include
INCLUDEDIR-SERVER = /usr/local/pgsql-8.4dev-20081008/include/server
LIBDIR = /usr/local/pgsql-8.4dev-20081008/lib
PKGLIBDIR = /usr/local/pgsql-8.4dev-20081008/lib
LOCALEDIR = /usr/local/pgsql-8.4dev-20081008/share/locale
MANDIR = /usr/local/pgsql-8.4dev-20081008/share/man
SHAREDIR = /usr/local/pgsql-8.4dev-20081008/share
SYSCONFDIR = /usr/local/pgsql-8.4dev-20081008/etc
PGXS = /usr/local/pgsql-8.4dev-20081008/lib/pgxs/src/makefiles/pgxs.mk
CONFIGURE = '--prefix=/usr/local/pgsql-8.4dev-20081008'
'--enable-integer-datetimes' '--enable-debug' '--disable-nls'
CC = gcc
CPPFLAGS = -D_GNU_SOURCE
CFLAGS = -O2 -Wall -Wmissing-prototypes -Wpointer-arith -Wendif-labels
-fno-strict-aliasing -g
CFLAGS_SL = -fpic
LDFLAGS = -Wl,-rpath,'/usr/local/pgsql-8.4dev-20081008/lib'
LDFLAGS_SL =
LIBS = -lpgport -lz -lreadline -lcrypt -ldl -lm
VERSION = PostgreSQL 8.4devel

listen_addresses = '*'
port = 5666
max_connections = 200
shared_buffers = 256MB
temp_buffers = 10MB
max_prepared_transactions = 0
work_mem = 16MB
maintenance_work_mem = 400MB
bgwriter_lru_maxpages = 1000
bgwriter_lru_multiplier = 4.0
wal_buffers = 256kB
checkpoint_segments = 50
seq_page_cost = 0.1
random_page_cost = 0.1
effective_cache_size = 3GB
geqo = off
default_statistics_target = 100
from_collapse_limit = 20
join_collapse_limit = 20
logging_collector = on
log_connections = on
log_disconnections = on
log_line_prefix = '[%m] %p %q<%u %d %r> '
autovacuum_naptime = 1min
autovacuum_vacuum_threshold = 10
autovacuum_analyze_threshold = 10
datestyle = 'iso, mdy'
lc_messages = 'C'
lc_monetary = 'C'
lc_numeric = 'C'
lc_time = 'C'
default_text_search_config = 'pg_catalog.english'
escape_string_warning = off
sql_inheritance = off
standard_conforming_strings = on

vmstat 1 output at start and end of process
(process interrupted by ^C)

procs -----------memory---------- ---swap-- -----io---- --system--
----cpu----
r b swpd free buff cache si so bi bo in cs us
sy id wa
0 0 31620 426432 11876 2363148 0 0 2 1 1 7 4
0 96 0
0 0 31620 426432 11876 2363148 0 0 0 0 1016 680 0
0 100 0
0 0 31620 426432 11876 2363148 0 0 0 0 1034 787 3
0 98 0
0 0 31620 426432 11884 2363140 0 0 0 12 1017 702 0
0 99 1
0 0 31620 426308 11884 2363140 0 0 0 27 1019 704 0
0 100 0
0 0 31620 426308 11884 2363140 0 0 0 0 1023 777 0
0 99 0
0 0 31620 426324 11884 2363140 0 0 0 0 1017 677 0
0 100 0
0 0 31620 426324 11884 2363140 0 0 0 0 1007 716 3
0 97 0
0 0 31620 426324 11884 2363140 0 0 0 0 1011 705 0
0 100 0
0 0 31620 426316 11884 2363140 0 0 0 30 1017 715 0
0 100 0
0 0 31620 426308 11884 2363140 0 0 0 0 1020 812 0
1 99 0
0 0 31620 426308 11884 2363140 0 0 0 0 1016 686 0
0 100 0
0 0 31620 426308 11884 2363140 0 0 0 0 1013 717 0
0 100 0
0 0 31620 426308 11884 2363140 0 0 0 0 1013 712 0
0 100 0
0 0 31620 426340 11884 2363140 0 0 0 6 1013 693 0
0 100 0
0 0 31620 426340 11884 2363140 0 0 0 8 1028 773 0
0 100 0
0 0 31620 426340 11884 2363140 0 0 0 0 1014 728 0
0 100 0
0 0 31620 426200 11884 2363140 0 0 0 8 1047 787 2
0 99 0
0 0 31620 426200 11884 2363140 0 0 0 0 1021 729 0
0 100 0
0 0 31620 426200 11884 2363140 0 0 0 26 1017 718 0
0 100 0
0 0 31620 426200 11884 2363140 0 0 0 4 1018 792 0
0 100 0
0 0 31620 426200 11884 2363140 0 0 0 8 1026 717 0
0 100 0
0 0 31620 426200 11884 2363140 0 0 0 9 1026 747 9
0 92 0
0 0 31620 426200 11884 2363140 0 0 0 8 1013 681 0
0 100 0
0 0 31620 426200 11884 2363140 0 0 0 18 1018 679 0
0 100 0
0 0 31620 426192 11884 2363140 0 0 0 0 1021 759 0
0 100 0
0 0 31620 426192 11884 2363140 0 0 0 0 1009 670 0
0 100 0
0 0 31620 426192 11884 2363140 0 0 0 0 1018 679 0
0 100 0
0 0 31620 426192 11884 2363140 0 0 0 0 1020 711 0
0 100 0
0 0 31620 426192 11884 2363140 0 0 0 86 1025 710 0
0 100 0
1 0 31620 426168 11884 2363140 0 0 0 0 1020 754 0
0 100 0
1 0 31620 419968 11884 2366224 0 0 0 0 1042 714 38
1 61 0
1 0 31620 418480 11884 2366224 0 0 0 13 1036 870 66
25 10 0
1 0 31620 416992 11884 2366224 0 0 0 0 1016 745 49
1 50 0
1 0 31620 415520 11884 2366224 0 0 0 24 1020 755 49
1 50 0
2 0 31620 414032 11884 2366224 0 0 0 13 1029 831 50
1 50 0
1 0 31620 412544 11884 2366224 0 0 0 0 1012 716 50
1 50 0
1 0 31620 411180 11884 2366224 0 0 0 0 1012 742 49
1 50 0
1 0 31620 409692 11884 2366224 0 0 0 0 1009 755 49
1 50 0
1 0 31620 408204 11884 2366224 0 0 0 84 1020 730 49
1 50 0
1 0 31620 406592 11884 2366224 0 0 0 0 1019 801 49
1 50 0
1 0 31620 405104 11884 2366224 0 0 0 0 1010 735 49
3 49 0
1 0 31620 403756 11884 2366224 0 0 0 0 1011 748 49
1 50 0
1 0 31620 402268 11884 2366224 0 0 0 0 1019 712 49
1 50 0
1 0 31620 400780 11884 2366224 0 0 0 22 1021 731 49
1 50 0
1 0 31620 399268 11884 2366224 0 0 0 0 1017 789 49
1 50 0
1 0 31620 397780 11884 2366224 0 0 0 0 1015 705 49
1 50 0
1 0 31620 396292 11884 2366224 0 0 0 0 1038 749 50
1 49 0
2 0 31620 394680 11884 2366224 0 0 0 0 1019 767 49
1 50 0
1 0 31620 393192 11884 2366224 0 0 0 109 1028 716 49
1 50 0
1 0 31620 391704 11884 2366224 0 0 0 4 1021 775 49
1 50 0
1 0 31620 390216 11884 2366224 0 0 0 4 1017 699 50
1 50 0

procs -----------memory---------- ---swap-- -----io---- --system--
----cpu----
r b swpd free buff cache si so bi bo in cs us
sy id wa
3 0 31860 136604 4348 2183840 0 0 0 4 1016 665 49
1 50 0
2 0 31860 137844 4348 2181784 0 0 0 7 1031 739 49
1 50 0
2 0 31860 137596 4348 2180756 0 0 0 19 1016 669 49
1 50 0
2 0 31860 137348 4348 2178700 0 0 0 4 1013 670 49
1 50 0
2 0 31860 137240 4356 2177664 0 0 0 27 1023 709 49
1 49 1
2 0 31860 136992 4356 2176636 0 0 0 105 1034 680 49
1 50 0
2 0 31860 136744 4356 2175608 0 0 0 4 1017 724 49
2 50 0
3 0 31860 136620 4356 2173552 0 0 0 19 1018 665 49
1 50 0
2 0 31860 137380 4356 2171496 0 0 0 7 1014 662 50
1 50 0
2 0 31860 137256 4356 2170468 0 0 0 4 1022 653 49
1 50 0
2 0 31860 137008 4356 2169440 0 0 0 28 1017 669 49
1 50 0
2 0 31860 136860 4356 2168412 0 0 0 23 1026 742 50
1 50 0
2 0 31860 318396 4356 2167384 0 0 0 25 1016 732 51
3 47 0
1 0 31860 639556 4356 2167384 0 0 0 11 1016 686 0
2 98 0
1 0 31860 639556 4356 2167384 0 0 0 19 1039 757 2
1 98 0
1 0 31860 639556 4356 2167384 0 0 0 36 1019 639 0
0 100 0
1 0 31860 639060 4356 2167384 0 0 0 8240 1125 779 0
0 98 1
1 0 31860 639680 4356 2167384 0 0 0 104 1091 767 0
0 78 22
2 0 31860 639680 4356 2167384 0 0 0 0 1011 637 0
0 100 0
1 0 31860 639680 4356 2167384 0 0 0 0 1017 652 0
0 100 0
1 0 31860 639696 4356 2167384 0 0 0 29 1021 666 0
0 100 0
1 0 31860 639696 4356 2167384 0 0 0 0 1034 739 0
0 100 0
1 0 31860 643416 4356 2167384 0 0 0 0 1018 677 0
0 99 0
1 0 31860 643416 4356 2167384 0 0 0 5 1012 649 0
0 100 0
1 0 31860 643416 4356 2167384 0 0 0 0 1013 655 0
0 100 0
1 0 31860 643416 4356 2167384 0 0 0 41 1017 637 0
0 100 0
1 0 31860 643416 4356 2167384 0 0 0 0 1023 724 0
0 100 0
2 0 31860 643284 4364 2167376 0 0 0 44 1023 698 2
1 96 1
1 0 31860 643408 4364 2167376 0 0 0 0 1014 643 7
0 93 0
1 0 31860 643408 4364 2167376 0 0 0 26 1046 741 1
0 99 0

The query:

SELECT
"MS"."sMatterNo",
CAST(COUNT(*) AS int) AS "count"
FROM
"MatterSearch" "MS"
JOIN "MatterDateStat" "S" ON
(
"S"."matterNo" = "MS"."sMatterNo" AND
"S"."isOnHold" = FALSE
)
WHERE
(
"MS"."matterStatusCode" IN ('OP', 'RO')
)
GROUP BY "MS"."sMatterNo"
;

The pg_dump tarball is 20MB. Should I email it directly to you?

-Kevin

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:

I've got the database down to the minimum database objects needed for
the query (three tables, five views on them, and a bunch of domains),
and gotten those tables down to 10% of their original size, with all
confidential data turned to meaningless literals. The problem still
happens on today's snapshot.

Excellent.

The pg_dump tarball is 20MB. Should I email it directly to you?

Works for me.

regards, tom lane

Hah, got it. The reason the leak only manifests on 32-bit is that it
only manifests if int8 is a pass-by-reference datatype. The new API
for amgetbitmap causes a query-lifespan leak of one palloc(sizeof(int8))
per bitmap index scan. The distinguishing feature of your query seems
to be just that it does enough repeated bitmapscans to notice ...

The attached patch cures the leak for me, but I find it a tad ugly.
I'm tempted to think that it would be better if we changed the call
signature for amgetbitmap so that it returned the count through an
"int64 *" output parameter. Thoughts anyone?

regards, tom lane

Index: src/backend/access/index/indexam.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/access/index/indexam.c,v
retrieving revision 1.110
diff -c -r1.110 indexam.c
*** src/backend/access/index/indexam.c	11 Sep 2008 14:01:09 -0000	1.110
--- src/backend/access/index/indexam.c	9 Oct 2008 22:47:54 -0000
***************
*** 655,660 ****
--- 655,661 ----
  {
  	FmgrInfo   *procedure;
  	int64		ntids;
+ 	Datum		d;

SCAN_CHECKS;
GET_SCAN_PROCEDURE(amgetbitmap);
***************
*** 665,673 ****
/*
* have the am's getbitmap proc do all the work.
*/
! ntids = DatumGetInt64(FunctionCall2(procedure,
! PointerGetDatum(scan),
! PointerGetDatum(bitmap)));

pgstat_count_index_tuples(scan->indexRelation, ntids);

--- 666,680 ----
  	/*
  	 * have the am's getbitmap proc do all the work.
  	 */
! 	d = FunctionCall2(procedure,
! 					  PointerGetDatum(scan),
! 					  PointerGetDatum(bitmap));
! 
! 	ntids = DatumGetInt64(d);
! 
! #ifndef USE_FLOAT8_BYVAL
! 	pfree(DatumGetPointer(d));
! #endif

pgstat_count_index_tuples(scan->indexRelation, ntids);

Tom Lane <tgl@sss.pgh.pa.us> wrote:

The attached patch cures the leak for me

I see that the patch was applied. A CVS checkout from this morning
fixes the leak for me, too; the vmstat output stayed rock steady
during the run.

Thanks!

-Kevin