Thread: Out of memory

I have a client that experienced several Out Of Memory errors a few
weeks ago (March 10 & 11), and I'd like to figure out the cause.  In the
logs it's showing that they were getting out of memory errors for about
0.5-1 hour, after which one of the processes would crash and take the
whole database down.  After they restarted the server it would
eventually start giving out of memory messages and crash again.  This
happened a total of five times over a 24 hour period.  After that we did
not see these errors again.  They did upgrade to 8.1.11 on the 14th, and
have also moved some of the databases to different servers afterwards.

First some background information:

Software (at the time of the memory errors): CentOS 4.5 (x86_64) running
its 2.6.9-55.ELsmp Linux kernel, PostgreSQL 8.1.9 (from RPMs provided on
the PostgreSQL web site: postgresql-8.1.9-1PGDG.x86_64).

Hardware: 4 dual-core Opterons.  16GB physical RAM, 2GB swap.

Database: they use persistent connections, and usually have around 1000
open database connections.  The vast majority of those are usually
idle.  They do run a lot of queries though.  The total size of the
databases in this cluster is 36GB, with the largest database being 21GB,
and the largest table being 2.5GB (having 20 million tuples).

Highlights of postgresql.conf settings:
max_connections = 2000
shared_buffers = 120000
work_mem = 4096
maintenance_work_mem = 268435
max_fsm_pages = 1500000
max_fsm_relations = 2000
checkpoint_segments = 8
effective_cache_size = 1400000
stats_start_collector = on
stats_command_string = off
stats_block_level = on
stats_row_level = on
stats_reset_on_server_start = off
autovacuum = on
lc_* = 'en_US.UTF-8'
Note that not all of these settings may have been in effect during the
first crash since the server hadn't been restarted for quite some time.
However, during the second and third crash these settings were in effect.

ulimit settings:
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
file size               (blocks, -f) unlimited
pending signals                 (-i) 1024
max locked memory       (kbytes, -l) 32
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
stack size              (kbytes, -s) 10240
cpu time               (seconds, -t) unlimited
max user processes              (-u) 137216
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

Miscellaneous facts:
Before the crashes there were a lot of "duplicate key violates unique
constraint ..." errors as well as some syntax errors in some of the
queries.  A lot of these errors were fixed after the crashes.  I don't
think these would be related to the problem unless there's a memory leak
somewhere.

This server does not have any other processes running that could consume
a significant amount of memory.  Some of the other processes that run
are SSH, cupsd, snmpd, sendmail, portsentry, xinetd, and Dell
OpenManage.  This server has no cronjobs.

These errors usually seemed to occur right after autovacuum started
vacuuming a database, although I'm not sure if autovacuum is the cause here.

Here are some of the relevant portions from the logs (some of the
database/relation names are obfuscated to protect confidentiality):
2008-03-10 18:42:58 EDT LOG:  autovacuum: processing database
"database1" [this database is 4GB in size]
TopMemoryContext: 401632 total in 11 blocks; 12832 free (12 chunks);
388800 used
TopTransactionContext: 8192 total in 1 blocks; 7352 free (11 chunks);
840 used
Operator class cache: 8192 total in 1 blocks; 1680 free (0 chunks); 6512
used
Autovacuum context: 253952 total in 5 blocks; 131152 free (147 chunks);
122800 used
smgr relation table: 24576 total in 2 blocks; 15968 free (4 chunks);
8608 used
Portal hash: 8192 total in 1 blocks; 1680 free (0 chunks); 6512 used
PortalMemory: 0 total in 0 blocks; 0 free (0 chunks); 0 used
Relcache by OID: 24576 total in 2 blocks; 7632 free (3 chunks); 16944 used
CacheMemoryContext: 2157568 total in 10 blocks; 941176 free (0 chunks);
1216392 used
some_pkey: 1024 total in 1 blocks; 312 free (0 chunks); 712 used [note:
this index is currently about 41MB but only has 129 small tuples - it's
currently very bloated]
pg_index_indrelid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_constraint_conrelid_index: 1024 total in 1 blocks; 312 free (0
chunks); 712 used
pg_attrdef_adrelid_adnum_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_autovacuum_vacrelid_index: 1024 total in 1 blocks; 312 free (0
chunks); 712 used
pg_database_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_type_typname_nsp_index: 1024 total in 1 blocks; 216 free (0 chunks);
808 used
pg_type_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_trigger_tgrelid_tgname_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_statistic_relid_att_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_auth_members_member_role_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_auth_members_role_member_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_rewrite_rel_rulename_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_proc_proname_args_nsp_index: 1024 total in 1 blocks; 208 free (0
chunks); 816 used
pg_proc_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_operator_oprname_l_r_n_index: 1024 total in 1 blocks; 16 free (0
chunks); 1008 used
pg_operator_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_opclass_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_opclass_am_name_nsp_index: 1024 total in 1 blocks; 208 free (0
chunks); 816 used
pg_namespace_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712
used
pg_namespace_nspname_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_language_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_language_name_index: 1024 total in 1 blocks; 312 free (0 chunks); 712
used
pg_inherits_relid_seqno_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_index_indexrelid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_authid_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_authid_rolname_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_database_datname_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_conversion_oid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_conversion_name_nsp_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_conversion_default_index: 1024 total in 1 blocks; 16 free (0 chunks);
1008 used
pg_class_relname_nsp_index: 1024 total in 1 blocks; 216 free (0 chunks);
808 used
pg_class_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_cast_source_target_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_attribute_relid_attnum_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_attribute_relid_attnam_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_amproc_opc_proc_index: 1024 total in 1 blocks; 208 free (0 chunks);
816 used
pg_amop_opr_opc_index: 1024 total in 1 blocks; 216 free (0 chunks); 808 used
pg_amop_opc_strat_index: 1024 total in 1 blocks; 208 free (0 chunks);
816 used
pg_aggregate_fnoid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
Per-database table: 57344 total in 3 blocks; 26096 free (10 chunks);
31248 used
Per-database table: 57344 total in 3 blocks; 34320 free (10 chunks);
23024 used
Per-database table: 24576 total in 2 blocks; 5696 free (4 chunks); 18880
used
Per-database table: 122880 total in 4 blocks; 9344 free (13 chunks);
113536 used
Per-database table: 122880 total in 4 blocks; 21680 free (13 chunks);
101200 used
Per-database table: 57344 total in 3 blocks; 34320 free (10 chunks);
23024 used
Per-database table: 24576 total in 2 blocks; 5696 free (4 chunks); 18880
used
Per-database table: 122880 total in 4 blocks; 23744 free (14 chunks);
99136 used
Per-database table: 122880 total in 4 blocks; 21680 free (13 chunks);
101200 used
Per-database table: 24576 total in 2 blocks; 13920 free (4 chunks);
10656 used
Per-database table: 122880 total in 4 blocks; 21680 free (13 chunks);
101200 used
Databases hash: 8192 total in 1 blocks; 1680 free (0 chunks); 6512 used
MdSmgr: 8192 total in 1 blocks; 7936 free (0 chunks); 256 used
LockTable (locallock hash): 24576 total in 2 blocks; 15984 free (5
chunks); 8592 used
Timezones: 52560 total in 2 blocks; 3744 free (0 chunks); 48816 used
Postmaster: 2328624 total in 3 blocks; 18048 free (86 chunks); 2310576 used
ErrorContext: 8192 total in 1 blocks; 8160 free (3 chunks); 32 used
2008-03-10 18:42:58 EDT ERROR:  out of memory
2008-03-10 18:42:58 EDT DETAIL:  Failed on request of size 274877436.
TopMemoryContext: 458976 total in 18 blocks; 12528 free (53 chunks);
446448 used
TopTransactionContext: 8192 total in 1 blocks; 7648 free (0 chunks); 544
used
SPI Plan: 15360 total in 4 blocks; 584 free (0 chunks); 14776 used
SPI Plan: 7168 total in 3 blocks; 952 free (0 chunks); 6216 used
SPI Plan: 3072 total in 2 blocks; 1112 free (0 chunks); 1960 used
SPI Plan: 3072 total in 2 blocks; 1112 free (0 chunks); 1960 used
SPI Plan: 7168 total in 3 blocks; 952 free (0 chunks); 6216 used
SPI Plan: 3072 total in 2 blocks; 1576 free (0 chunks); 1496 used
SPI Plan: 3072 total in 2 blocks; 1576 free (0 chunks); 1496 used
SPI Plan: 3072 total in 2 blocks; 1256 free (0 chunks); 1816 used
SPI Plan: 3072 total in 2 blocks; 1192 free (0 chunks); 1880 used
SPI Plan: 3072 total in 2 blocks; 1192 free (0 chunks); 1880 used
SPI Plan: 3072 total in 2 blocks; 1192 free (0 chunks); 1880 used
SPI Plan: 1024 total in 1 blocks; 72 free (0 chunks); 952 used
PL/PgSQL function context: 24576 total in 2 blocks; 15096 free (4
chunks); 9480 used
SPI Plan: 15360 total in 4 blocks; 776 free (0 chunks); 14584 used
SPI Plan: 3072 total in 2 blocks; 1112 free (0 chunks); 1960 used
SPI Plan: 3072 total in 2 blocks; 1192 free (0 chunks); 1880 used
SPI Plan: 3072 total in 2 blocks; 1192 free (0 chunks); 1880 used
SPI Plan: 3072 total in 2 blocks; 1192 free (0 chunks); 1880 used
PL/PgSQL function context: 24576 total in 2 blocks; 1024 free (4
chunks); 23552 used
SPI Plan: 3072 total in 2 blocks; 1448 free (0 chunks); 1624 used
SPI Plan: 7168 total in 3 blocks; 192 free (0 chunks); 6976 used
PL/PgSQL function context: 8192 total in 1 blocks; 6016 free (3 chunks);
2176 used
SPI Plan: 3072 total in 2 blocks; 1064 free (0 chunks); 2008 used
SPI Plan: 3072 total in 2 blocks; 1208 free (0 chunks); 1864 used
SPI Plan: 3072 total in 2 blocks; 1712 free (0 chunks); 1360 used
SPI Plan: 3072 total in 2 blocks; 1256 free (0 chunks); 1816 used
SPI Plan: 3072 total in 2 blocks; 1688 free (0 chunks); 1384 used
SPI Plan: 7168 total in 3 blocks; 1952 free (0 chunks); 5216 used
SPI Plan: 3072 total in 2 blocks; 1064 free (0 chunks); 2008 used
SPI Plan: 3072 total in 2 blocks; 1208 free (0 chunks); 1864 used
SPI Plan: 3072 total in 2 blocks; 1208 free (0 chunks); 1864 used
SPI Plan: 3072 total in 2 blocks; 1664 free (0 chunks); 1408 used
PL/PgSQL function context: 24576 total in 2 blocks; 13080 free (8
chunks); 11496 used
SPI Plan: 7168 total in 3 blocks; 4056 free (0 chunks); 3112 used
SPI Plan: 3072 total in 2 blocks; 952 free (0 chunks); 2120 used
SPI Plan: 3072 total in 2 blocks; 936 free (0 chunks); 2136 used
SPI Plan: 3072 total in 2 blocks; 952 free (0 chunks); 2120 used
SPI Plan: 3072 total in 2 blocks; 952 free (0 chunks); 2120 used
SPI Plan: 3072 total in 2 blocks; 952 free (0 chunks); 2120 used
SPI Plan: 7168 total in 3 blocks; 3864 free (0 chunks); 3304 used
SPI Plan: 3072 total in 2 blocks; 936 free (0 chunks); 2136 used
PL/PgSQL function context: 8192 total in 1 blocks; 896 free (4 chunks);
7296 used
Type information cache: 24576 total in 2 blocks; 11888 free (5 chunks);
12688 used
SPI Plan: 3072 total in 2 blocks; 352 free (0 chunks); 2720 used
PL/PgSQL function context: 8192 total in 1 blocks; 3552 free (6 chunks);
4640 used
PLpgSQL function cache: 24224 total in 2 blocks; 3744 free (0 chunks);
20480 used
Operator class cache: 8192 total in 1 blocks; 1680 free (0 chunks); 6512
used
MessageContext: 1063832 total in 8 blocks; 19088 free (6 chunks);
1044744 used
CFuncHash: 8192 total in 1 blocks; 1680 free (0 chunks); 6512 used
smgr relation table: 24576 total in 2 blocks; 3584 free (4 chunks);
20992 used
Portal hash: 8192 total in 1 blocks; 1680 free (0 chunks); 6512 used
PortalMemory: 8192 total in 1 blocks; 8160 free (1 chunks); 32 used
Relcache by OID: 24576 total in 2 blocks; 8672 free (3 chunks); 15904 used
CacheMemoryContext: 4267376 total in 11 blocks; 1835032 free (1 chunks);
2432344 used
[139 user indexes skipped - the biggest item was:187392 total in 25
blocks; 8024 free (0 chunks); 179368 used]
pg_index_indrelid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_constraint_conrelid_index: 1024 total in 1 blocks; 312 free (0
chunks); 712 used
pg_attrdef_adrelid_adnum_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_type_typname_nsp_index: 1024 total in 1 blocks; 216 free (0 chunks);
808 used
pg_type_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_trigger_tgrelid_tgname_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_statistic_relid_att_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_auth_members_member_role_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_auth_members_role_member_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_rewrite_rel_rulename_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_proc_proname_args_nsp_index: 1024 total in 1 blocks; 208 free (0
chunks); 816 used
pg_proc_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_operator_oprname_l_r_n_index: 1024 total in 1 blocks; 16 free (0
chunks); 1008 used
pg_operator_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_opclass_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_opclass_am_name_nsp_index: 1024 total in 1 blocks; 208 free (0
chunks); 816 used
pg_namespace_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712
used
pg_namespace_nspname_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_language_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_language_name_index: 1024 total in 1 blocks; 312 free (0 chunks); 712
used
pg_inherits_relid_seqno_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_index_indexrelid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_authid_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_authid_rolname_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_database_datname_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_conversion_oid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
pg_conversion_name_nsp_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_conversion_default_index: 1024 total in 1 blocks; 16 free (0 chunks);
1008 used
pg_class_relname_nsp_index: 1024 total in 1 blocks; 216 free (0 chunks);
808 used
pg_class_oid_index: 1024 total in 1 blocks; 312 free (0 chunks); 712 used
pg_cast_source_target_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_attribute_relid_attnum_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_attribute_relid_attnam_index: 1024 total in 1 blocks; 216 free (0
chunks); 808 used
pg_amproc_opc_proc_index: 1024 total in 1 blocks; 208 free (0 chunks);
816 used
pg_amop_opr_opc_index: 1024 total in 1 blocks; 216 free (0 chunks); 808 used
pg_amop_opc_strat_index: 1024 total in 1 blocks; 208 free (0 chunks);
816 used
pg_aggregate_fnoid_index: 1024 total in 1 blocks; 312 free (0 chunks);
712 used
MdSmgr: 8192 total in 1 blocks; 2208 free (0 chunks); 5984 used
LockTable (locallock hash): 24576 total in 2 blocks; 15984 free (5
chunks); 8592 used
Timezones: 52560 total in 2 blocks; 3744 free (0 chunks); 48816 used
ErrorContext: 8192 total in 1 blocks; 8160 free (3 chunks); 32 used
2008-03-10 18:43:30 EDT ERROR:  out of memory
2008-03-10 18:43:30 EDT DETAIL:  Failed on request of size 16.
[A bunch more memory errors skipped]
2008-03-10 18:43:33 EDT LOG:  could not fork new process for connection:
Cannot allocate memory
2008-03-10 18:43:33 EDT LOG:  could not fork new process for connection:
Cannot allocate memory
2008-03-10 18:43:33 EDT LOG:  could not fork new process for connection:
Cannot allocate memory
2008-03-10 18:43:33 EDT LOG:  could not fork new process for connection:
Cannot allocate memory
[...]
2008-03-10 18:51:08 EDT LOG:  archive command "..." failed: return code -1
[...]
2008-03-10 19:20:39 EDT ERROR:  out of memory
2008-03-10 19:20:39 EDT DETAIL:  Failed on request of size 32.
2008-03-10 19:20:39 EDT LOG:  server process (PID 5609) was terminated
by signal 11
2008-03-10 19:20:39 EDT LOG:  terminating any other active server processes
2008-03-10 19:20:39 EDT WARNING:  terminating connection because of
crash of another server process
2008-03-10 19:20:39 EDT DETAIL:  The postmaster has commanded this
server process to roll back the current transaction and exit, because
another server process exited abnormally and possibly corrupted shared
memory.
2008-03-10 19:20:39 EDT HINT:  In a moment you should be able to
reconnect to the database and repeat your command.

I also saw the following lines in the kernel logs during this 24 hour
period:
Mar 10 19:20:39 servername kernel: postmaster[5609]: segfault at
0000007fbffedfe8 rip 000000000049ea35 rsp 0000007fbffedff0 error 6
Mar 10 20:44:15 servername kernel: postmaster[26808]: segfault at
0000007fbffeafe8 rip 000000000049ea00 rsp 0000007fbffeb018 error 6
Mar 11 10:10:59 servername kernel: postmaster[19984]: segfault at
fffffffffffffff0 rip 00000000005e7b13 rsp 0000007fbfffe178 error 4
Mar 11 11:52:07 servername kernel: postmaster[27309]: segfault at
0000007fbffedfe8 rip 000000000049ea00 rsp 0000007fbffee018 error 6
Mar 11 12:39:18 servername kernel: postmaster[30301]: segfault at
fffffffffffffff0 rip 00000000005e7b13 rsp 0000007fbfffe158 error 4

Each of these five segfaults correspond to when the database crashed.

vm.overcommit_memory was set to 0, but I do not see any memory errors in
the kernel logs so I don't believe the OOM killer was used.

Current output of free:
             total       used       free     shared    buffers     cached
Mem:      16479276   16441000      38276          0      26612    8633316
-/+ buffers/cache:    7781072    8698204
Swap:      2031608       1180    2030428

The client is using Zenoss to monitor the servers, and it always shows
that free memory is pretty low, which tells me that this setup doesn't
differentiate memory that's used by the OS buffers/cache, which is
unfortunate.  I did see free memory going up to about 1GB around each
time PostgreSQL crashed, presumably because PostgreSQL got killed and
released its memory.  Free swap remained at 2GB free before, during, and
after the crashes.  I did not see any abnormal changes in the loads and
CPU utilization during the crashes.  Note that these measurements were
taking once every other hour so it's not very granular.

Any ideas as to what could have caused this?

Thank you,

Alex

On Fri, Mar 28, 2008 at 12:38 PM, Alex Adriaanse
<alex@innovacomputing.com> wrote:
> I have a client that experienced several Out Of Memory errors a few
>  weeks ago (March 10 & 11), and I'd like to figure out the cause.  In the
>  logs it's showing that they were getting out of memory errors for about
>  0.5-1 hour, after which one of the processes would crash and take the
>  whole database down.  After they restarted the server it would
>  eventually start giving out of memory messages and crash again.  This
>  happened a total of five times over a 24 hour period.  After that we did
>  not see these errors again.  They did upgrade to 8.1.11 on the 14th, and
>  have also moved some of the databases to different servers afterwards.
>
>  First some background information:
>
>  Software (at the time of the memory errors): CentOS 4.5 (x86_64) running
>  its 2.6.9-55.ELsmp Linux kernel, PostgreSQL 8.1.9 (from RPMs provided on
>  the PostgreSQL web site: postgresql-8.1.9-1PGDG.x86_64).
>
>  Hardware: 4 dual-core Opterons.  16GB physical RAM, 2GB swap.
>
>  Database: they use persistent connections, and usually have around 1000
>  open database connections.  The vast majority of those are usually
>  idle.  They do run a lot of queries though.  The total size of the
>  databases in this cluster is 36GB, with the largest database being 21GB,
>  and the largest table being 2.5GB (having 20 million tuples).
>
>  Highlights of postgresql.conf settings:
>  max_connections = 2000
>  shared_buffers = 120000
>  work_mem = 4096

SNIP

Just because you can set max_connections to 2000 doesn't mean it's a
good idea.  If your client needs 1000 persistent connections, then put
a connection pooler between your app (I'm guessing php since it
operates this way) and the database.

Running 1000 connections is a LOT, and you need 1000 active
connections, then you're likely gonna need a bigger machine than one
with 8 cores and 16 gig of rams.  OTOH, if you are actively servicing
less than 10% of those connections at a time, then you're wasting
memory on the number of backends that are started up and doing
nothing.  each one consumes some amount of memory on its own, usually
in the 5 to 10 meg range, just to sit there and do nothing.

Plus you've got issues with thundering herd type situations that can
show up as you increase connections.

Pooling is the answer here.

Scott Marlowe wrote:
> Just because you can set max_connections to 2000 doesn't mean it's a
> good idea.  If your client needs 1000 persistent connections, then put
> a connection pooler between your app (I'm guessing php since it
> operates this way) and the database.
>
> Running 1000 connections is a LOT, and you need 1000 active
> connections, then you're likely gonna need a bigger machine than one
> with 8 cores and 16 gig of rams.  OTOH, if you are actively servicing
> less than 10% of those connections at a time, then you're wasting
> memory on the number of backends that are started up and doing
> nothing.  each one consumes some amount of memory on its own, usually
> in the 5 to 10 meg range, just to sit there and do nothing.
>
> Plus you've got issues with thundering herd type situations that can
> show up as you increase connections.
>
> Pooling is the answer here.
>
Thanks for the suggestion.  I fully agree with you, and the client is
already making plans to move from persistent connections to connection
pooling (they will probably use PgBouncer).  I'm just trying to figure
out the exact cause of this memory issue so that we can make sure it
doesn't happen again, even after they switch to connection pooling.
According to my rough calculations, if the server were to max out at
2,000 connections there should still be around 2GB of memory free -
unless all of them were running active queries which is doubtful since I
did not see unusual changes in the load patterns.  And from what I could
tell, the server did not tap into swap when PostgreSQL ran out of memory.

Thanks,

Alex

On Fri, Mar 28, 2008 at 01:38:57PM -0500, Alex Adriaanse wrote:
> First some background information:
>
> Software (at the time of the memory errors): CentOS 4.5 (x86_64) running
> its 2.6.9-55.ELsmp Linux kernel, PostgreSQL 8.1.9 (from RPMs provided on
> the PostgreSQL web site: postgresql-8.1.9-1PGDG.x86_64).
>
> Hardware: 4 dual-core Opterons.  16GB physical RAM, 2GB swap.

Since you've clearly disabled overcommit, you should realise that under
the default settings you will never use more than about 50-60% of your
memory for the database. Your swap will essentially always be unused.
The rest will be simply buffers/cache (which may be what you want). You
may want to play with the VM settings and/or increase the swap.

As for the precise cause of the crash: I don't see anything in the log
that would indicate anything unusual, though evidently it wanted about
256MB all of a sudden, which looks suspicously like your maintainence
workmem.

My guess is that the total allocated VM is fairly close to the limit of
your configuration and that a slightly higher than normal load and a
background autovacuum took it over the edge. My guess is that if you up
the swap to 4GB or perhaps 8GB, you'll get a lot more room to manouver.

Does Zenoss track to *allocated* VM in addition to total memory used?

Hope this helps,
--
Martijn van Oosterhout   <kleptog@svana.org>   http://svana.org/kleptog/
> Please line up in a tree and maintain the heap invariant while
> boarding. Thank you for flying nlogn airlines.

Martijn van Oosterhout <kleptog@svana.org> writes:
> My guess is that the total allocated VM is fairly close to the limit of
> your configuration and that a slightly higher than normal load and a
> background autovacuum took it over the edge. My guess is that if you up
> the swap to 4GB or perhaps 8GB, you'll get a lot more room to manouver.

The bits about

> 2008-03-10 18:43:33 EDT LOG:  could not fork new process for connection:
> Cannot allocate memory

certainly suggest that the problem was a global out-of-memory condition
and not just within any one process.  I concur with raising swap, but
also with the upthread suggestions to cut down the number of concurrent
connections.

The segfaults (sig11s) are a bit disturbing too --- what that probably
indicates is someplace using malloc() and failing to test for failure,
neither of which is a good thing.  Did you by any chance get core dumps
from those?  A stack trace would be mighty useful.

            regards, tom lane

Thanks everyone for the suggestions so far.

Tom Lane wrote:
> The segfaults (sig11s) are a bit disturbing too --- what that probably
> indicates is someplace using malloc() and failing to test for failure,
> neither of which is a good thing.  Did you by any chance get core dumps
> from those?  A stack trace would be mighty useful.
>
Unfortunately, we do not have any core dumps from those.  Is there
anything else I can provide to make tracing this easier?  Could we use
the addresses mentioned in the segfault messages for anything useful?

Alex

Alex Adriaanse <alex@innovacomputing.com> writes:
> Unfortunately, we do not have any core dumps from those.  Is there
> anything else I can provide to make tracing this easier?  Could we use
> the addresses mentioned in the segfault messages for anything useful?

Hmm, you could try attaching to a running Postgres process with gdb
and doing "x/i 0xHEXADDRESS" --- that should at least come up with a
routine name, unless your kernel is into address randomization ...

            regards, tom lane

Tom Lane wrote:
> Alex Adriaanse <alex@innovacomputing.com> writes:
>
>> Unfortunately, we do not have any core dumps from those.  Is there
>> anything else I can provide to make tracing this easier?  Could we use
>> the addresses mentioned in the segfault messages for anything useful?
>>
>
> Hmm, you could try attaching to a running Postgres process with gdb
> and doing "x/i 0xHEXADDRESS" --- that should at least come up with a
> routine name, unless your kernel is into address randomization ...
>
We weren't able to do this on the production server where PostgreSQL
crashed, but we did try to recreate as close a setup as possible on
another similar server with the same version of PostgreSQL 8.1.9.  It is
possible that some of the libraries are different or that we're using
different binaries of the same version of PostgreSQL.  Thus, it might be
possible that these particular addresses have shifted due to the
different environment and now point to irrelevant instructions.  But in
case they haven't, here's the output I got:

(gdb) x/i 0x000000000049ea35
0x49ea35 <transformExpr+53>:    callq  0x562c00 <check_stack_depth>

(gdb) x/i 0x000000000049ea00
0x49ea00 <transformExpr>:       mov    %rbx,0xffffffffffffffd0(%rsp)

(gdb) x/i 0x00000000005e7b13
0x5e7b13 <pfree+3>:     mov    0xfffffffffffffff0(%rdi),%rdi

I hope this helps.

Alex

Alex Adriaanse <alex@innovacomputing.com> writes:
> ... possible that these particular addresses have shifted due to the
> different environment and now point to irrelevant instructions.  But in
> case they haven't, here's the output I got:

> (gdb) x/i 0x000000000049ea35
> 0x49ea35 <transformExpr+53>:    callq  0x562c00 <check_stack_depth>

> (gdb) x/i 0x000000000049ea00
> 0x49ea00 <transformExpr>:       mov    %rbx,0xffffffffffffffd0(%rsp)

> (gdb) x/i 0x00000000005e7b13
> 0x5e7b13 <pfree+3>:     mov    0xfffffffffffffff0(%rdi),%rdi

Hmm, not exactly what I was expecting to see.  The last one looks like
someone passed garbage (maybe a NULL) to pfree; which would be a bug but
it's not clear how memory pressure would result in that, and without
knowing where pfree was called from we're not going to be able to get
far investigating.

The first two both seem like they could only be explained by running out
of execution stack space.  8.1 takes the max_stack_depth setting you
tell it as gospel, so a core dump right there is possible if you set
max_stack_depth too large, but you didn't mention having changed it.
In any case it's not clear why you'd get a transient spate of problems
like that, unless the system was handlng especially (and unreasonably)
complicated queries for awhile.  Did you query the client about whether
their workload could have been unusual during this episode?

Of course this is all just speculation since we can't trust the
addresses completely.

            regards, tom lane