Обсуждение: out of memory error

H,
 after a few days, i'm seeing the following logs in a database (postgresql 8.3.15 on Windows)
running with rubyrep 1.2.0 for syncing a few table small that have frequent update / insert/ delete.

I don't understand it and I'd like to know what happens and why. How to get rid of it.
I've seen in the same time from Windows Task Manager that the memory of a postregres.exe process goes constantly up (I've seen it up to 1.4 GB) then I suppose the process must crash since I can't see it anymore.

log :
---------------------
TopMemoryContext: 197681816 total in 24131 blocks; 394104 free (24179 chunks); 197287712 used
  TopTransactionContext: 8192 total in 1 blocks; 7792 free (0 chunks); 400 used
  PL/PgSQL function context: 8192 total in 1 blocks; 2912 free (3 chunks); 5280 used
  PL/PgSQL function context: 8192 total in 1 blocks; 2912 free (3 chunks); 5280 used
  PL/PgSQL function context: 8192 total in 1 blocks; 3168 free (4 chunks); 5024 used
  PL/PgSQL function context: 8192 total in 1 blocks; 3168 free (4 chunks); 5024 used
  PL/PgSQL function context: 8192 total in 1 blocks; 3184 free (4 chunks); 5008 used
  PL/PgSQL function context: 8192 total in 1 blocks; 3184 free (4 chunks); 5008 used
  RI compare cache: 8192 total in 1 blocks; 1800 free (0 chunks); 6392 used
  RI query cache: 24576 total in 2 blocks; 14136 free (5 chunks); 10440 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
  Record information cache: 8192 total in 1 blocks; 1800 free (0 chunks); 6392 used
  Prepared Queries: 8192 total in 1 blocks; 1800 free (0 chunks); 6392 used
  Operator class cache: 8192 total in 1 blocks; 3848 free (0 chunks); 4344 used
  Operator lookup cache: 24576 total in 2 blocks; 14072 free (6 chunks); 10504 used
  MessageContext: 8192 total in 1 blocks; 7144 free (1 chunks); 1048 used
  smgr relation table: 8192 total in 1 blocks; 1776 free (0 chunks); 6416 used
  TransactionAbortContext: 32768 total in 1 blocks; 32752 free (0 chunks); 16 used
  Portal hash: 8192 total in 1 blocks; 3912 free (0 chunks); 4280 used
  PortalMemory: 8192 total in 1 blocks; 8040 free (0 chunks); 152 used
    PortalHeapMemory: 4096 total in 1 blocks; 1888 free (0 chunks); 2208 used
      ExecutorState: 122880 total in 4 blocks; 46296 free (5 chunks); 76584 used
        TupleSort: 24600 total in 2 blocks; 7512 free (0 chunks); 17088 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 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
        ExprContext: 0 total in 0 blocks; 0 free (0 chunks); 0 used
        ExprContext: 8192 total in 1 blocks; 8176 free (0 chunks); 16 used
  Relcache by OID: 8192 total in 1 blocks; 2856 free (0 chunks); 5336 used
  CacheMemoryContext: 8531792 total in 24 blocks; 282000 free (617 chunks); 8249792 used
    unnamed prepared statement: 253952 total in 5 blocks; 10664 free (7 chunks); 243288 used
    unnamed prepared statement: 253952 total in 5 blocks; 86232 free (1 chunks); 167720 used
    CachedPlan: 1024 total in 1 blocks; 576 free (0 chunks); 448 used
    CachedPlanSource: 1024 total in 1 blocks; 344 free (0 chunks); 680 used
    SPI Plan: 1024 total in 1 blocks; 912 free (0 chunks); 112 used
    CachedPlan: 1024 total in 1 blocks; 248 free (0 chunks); 776 used
    CachedPlanSource: 1024 total in 1 blocks; 96 free (0 chunks); 928 used
    SPI Plan: 1024 total in 1 blocks; 928 free (0 chunks); 96 used
    CachedPlan: 1024 total in 1 blocks; 576 free (0 chunks); 448 used
    CachedPlanSource: 1024 total in 1 blocks; 344 free (0 chunks); 680 used
    SPI Plan: 1024 total in 1 blocks; 912 free (0 chunks); 112 used
    CachedPlan: 1024 total in 1 blocks; 248 free (0 chunks); 776 used
    CachedPlanSource: 1024 total in 1 blocks; 96 free (0 chunks); 928 used
    SPI Plan: 1024 total in 1 blocks; 928 free (0 chunks); 96 used

.
.
. there it goes for about 80MB of log then it ends
.
.
 SPI Plan: 1024 total in 1 blocks; 912 free (0 chunks); 112 used
    CachedPlan: 1024 total in 1 blocks; 248 free (0 chunks); 776 used
    CachedPlanSource: 1024 total in 1 blocks; 96 free (0 chunks); 928 used
    SPI Plan: 1024 total in 1 blocks; 928 free (0 chunks); 96 used
    CachedPlan: 1024 total in 1 blocks; 576 free (0 chunks); 448 used
    CachedPlanSource: 1024 total in 1 blocks; 344 free (0 chunks); 680 used
    SPI Plan: 1024 total in 1 blocks; 912 free (0 chunks); 112 used
    CachedPlan: 1024 total in 1 blocks; 248 free (0 chunks); 776 used
    CachedPlanSource: 1024 total in 1 blocks; 96 free (0 chunks); 928 used
    SPI Plan: 1024 total in 1 blocks; 928 free (0 chunks); 96 used
    CachedPlan: 1024 total in 1 blocks; 904 free (0 chunks); 120 used
    CachedPlanSource: 1024 total in 1 blocks; 840 free (0 chunks); 184 used
    CachedPlan: 3072 total in 2 blocks; 392 free (0 chunks); 2680 used
    CachedPlanSource: 3072 total in 2 blocks; 1904 free (1 chunks); 1168 used
    CachedPlan: 7168 total in 3 blocks; 4080 free (1 chunks); 3088 used
    CachedPlanSource: 3072 total in 2 blocks; 1384 free (0 chunks); 1688 used
    pg_opclass_oid_index: 1024 total in 1 blocks; 304 free (0 chunks); 720 used
    pg_amop_fam_strat_index: 1024 total in 1 blocks; 88 free (0 chunks); 936 used
    pg_trigger_tgrelid_tgname_index: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
    pg_attribute_relid_attnum_index: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
    pg_class_oid_index: 1024 total in 1 blocks; 304 free (0 chunks); 720 used
    pg_amproc_fam_proc_index: 1024 total in 1 blocks; 88 free (0 chunks); 936 used
    pg_index_indexrelid_index: 1024 total in 1 blocks; 304 free (0 chunks); 720 used
    pg_rewrite_rel_rulename_index: 1024 total in 1 blocks; 240 free (0 chunks); 784 used
    pg_operator_oid_index: 1024 total in 1 blocks; 304 free (0 chunks); 720 used
  MdSmgr: 8192 total in 1 blocks; 7288 free (6 chunks); 904 used
  LOCALLOCK hash: 8192 total in 1 blocks; 1856 free (0 chunks); 6336 used
  Timezones: 49432 total in 2 blocks; 5968 free (0 chunks); 43464 used
  ErrorContext: 8192 total in 1 blocks; 8176 free (0 chunks); 16 used
2012-05-02 08:01:10 WET ERROR:  out of memory
2012-05-02 08:01:10 WET DETAIL:  Failed on request of size 8.
2012-05-02 08:01:10 WET STATEMENT:  SELECT n.nspname,c.relname,a.attname,a.atttypid,a.attnotnull,a.atttypmod,a.attlen,a.attnum,pg_catalog.pg_get_expr(def.adbin, def.adrelid) AS adsrc,dsc.description,t.typbasetype,t.typtype  FROM pg_catalog.pg_namespace n  JOIN pg_catalog.pg_class c ON (c.relnamespace = n.oid)  JOIN pg_catalog.pg_attribute a ON (a.attrelid=c.oid)  JOIN pg_catalog.pg_type t ON (a.atttypid = t.oid)  LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND a.attnum = def.adnum)  LEFT JOIN pg_catalog.pg_description dsc ON (c.oid=dsc.objoid AND a.attnum = dsc.objsubid)  LEFT JOIN pg_catalog.pg_class dc ON (dc.oid=dsc.classoid AND dc.relname='pg_class')  LEFT JOIN pg_catalog.pg_namespace dn ON (dc.relnamespace=dn.oid AND dn.nspname='pg_catalog')  WHERE a.attnum > 0 AND NOT a.attisdropped  AND n.nspname LIKE 'public'  AND c.relname LIKE 'rr_pending_changes'  ORDER BY nspname,c.relname,attnum
2012-05-02 08:01:10 WET LOG:  could not send data to client: No connection could be made because the target machine actively refused it.

   
2012-05-02 08:01:10 WET STATEMENT:  SELECT n.nspname,c.relname,a.attname,a.atttypid,a.attnotnull,a.atttypmod,a.attlen,a.attnum,pg_catalog.pg_get_expr(def.adbin, def.adrelid) AS adsrc,dsc.description,t.typbasetype,t.typtype  FROM pg_catalog.pg_namespace n  JOIN pg_catalog.pg_class c ON (c.relnamespace = n.oid)  JOIN pg_catalog.pg_attribute a ON (a.attrelid=c.oid)  JOIN pg_catalog.pg_type t ON (a.atttypid = t.oid)  LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND a.attnum = def.adnum)  LEFT JOIN pg_catalog.pg_description dsc ON (c.oid=dsc.objoid AND a.attnum = dsc.objsubid)  LEFT JOIN pg_catalog.pg_class dc ON (dc.oid=dsc.classoid AND dc.relname='pg_class')  LEFT JOIN pg_catalog.pg_namespace dn ON (dc.relnamespace=dn.oid AND dn.nspname='pg_catalog')  WHERE a.attnum > 0 AND NOT a.attisdropped  AND n.nspname LIKE 'public'  AND c.relname LIKE 'rr_pending_changes'  ORDER BY nspname,c.relname,attnum
2012-05-02 08:01:10 WET LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.
---------------------  

Thank you for hints about that.
Vincent.

Vincent Dautremont <vincent@searidgetech.com> writes:
>  after a few days, i'm seeing the following logs in a database (postgresql
> 8.3.15 on Windows)
> running with rubyrep 1.2.0 for syncing a few table small that have frequent
> update / insert/ delete.
> I don't understand it and I'd like to know what happens and why. How to get
> rid of it.

Well, this is a bit unusual:

> TopMemoryContext: 197681816 total in 24131 blocks; 394104 free (24179
> chunks); 197287712 used

It's not normal to have so much stuff in TopMemoryContext.  That could
represent a leak, but it's also possible that that's just management
overhead for all of these contexts:

>     SPI Plan: 1024 total in 1 blocks; 912 free (0 chunks); 112 used
>     CachedPlan: 1024 total in 1 blocks; 248 free (0 chunks); 776 used
>     CachedPlanSource: 1024 total in 1 blocks; 96 free (0 chunks); 928 used
>     SPI Plan: 1024 total in 1 blocks; 928 free (0 chunks); 96 used

> .
> .
> . there it goes for about 80MB of log then it ends
> .
> .
>  SPI Plan: 1024 total in 1 blocks; 912 free (0 chunks); 112 used
>     CachedPlan: 1024 total in 1 blocks; 248 free (0 chunks); 776 used
>     CachedPlanSource: 1024 total in 1 blocks; 96 free (0 chunks); 928 used

That's a *heck* of a lot of SPI plans.  You haven't provided any
information that would let anybody diagnose why you have so many,
though.  Tell us about your usage patterns, especially of PL-language
functions.

            regards, tom lane

Well,
I think that i'm using the database for pretty basic stuffs.
It's mostly used with stored procedures to update/ insert / select a row of each table.
On 3 tables (less than 10 rows each), clients does updates/select at 2Hz to have pseudo real-time data up to date.
I've got a total of 6 clients to the DB, they all access DB using stored procedures
I would say that this is a light usage of the DB.

Then I have rubyrep 1.2.0 running to sync a backup of the DB.
it syncs 8 tables : 7 of them doesn't really change often and 1 is one of the pseudo real-time data one.

So everything works fine, but I see postgres process memory usage growing, it can go about 1GB to 1.5GB in about 5to 6 days, then I suppose it crashes.

I don't know a lot about PostgreSQL, what does the TopMemoryContext means. I haven't been able to find much information about it.
Is it like a global memory stack for the DB ?


I've tried using the default postgres.conf file I usually run this modified one with these values.
------------------------
"version";"PostgreSQL 8.3.15, compiled by Visual C++ build 1400"
"autovacuum";"on"
"autovacuum_analyze_threshold";"50"
"autovacuum_max_workers";"3"
"autovacuum_naptime";"1min"
"autovacuum_vacuum_threshold";"50"
"client_encoding";"UNICODE"
"deadlock_timeout";"5s"
"effective_cache_size";"2GB"
"lc_collate";"English_United States.1252"
"lc_ctype";"English_United States.1252"
"listen_addresses";"*"
"log_destination";"stderr"
"log_filename";"postgresql-%Y-%m-%d.log"
"log_line_prefix";"%t "
"log_rotation_age";"1d"
"log_truncate_on_rotation";"on"
"logging_collector";"on"
"max_connections";"100"
"max_fsm_pages";"204800"
"max_stack_depth";"2MB"
"port";"5432"
"server_encoding";"UTF8"
"shared_buffers";"512MB"
"shared_preload_libraries";"$libdir/plugins/plugin_debugger.dll"
"TimeZone";"Africa/Casablanca"
"track_counts";"on"
------------------------
Thanks,
Vincent

Vincent Dautremont <vincent@searidgetech.com> writes:
> I think that i'm using the database for pretty basic stuffs.
> It's mostly used with stored procedures to update/ insert / select a row of
> each table.
> On 3 tables (less than 10 rows each), clients does updates/select at 2Hz to
> have pseudo real-time data up to date.
> I've got a total of 6 clients to the DB, they all access DB using stored
> procedures
> I would say that this is a light usage of the DB.

> Then I have rubyrep 1.2.0 running to sync a backup of the DB.
> it syncs 8 tables : 7 of them doesn't really change often and 1 is one of
> the pseudo real-time data one.

This is not much information.  What I suspect is happening is that
you're using plpgsql functions (or some other PL) in such a way that the
system is leaking cached plans for the functions' queries; but there is
far from enough evidence here to prove or disprove that, let alone debug
the problem if that is a correct guess.  An entirely blue-sky guess as
to what your code might be doing to trigger such a problem is if you
were constantly replacing the same function's definition via CREATE OR
REPLACE FUNCTION.  But that could be totally wrong, too.

Can you put together a self-contained test case that triggers similar
growth in the server process size?

            regards, tom lane

Thanks Tom,
when you say,

 An entirely blue-sky guess as
to what your code might be doing to trigger such a problem is if you
were constantly replacing the same function's definition via CREATE OR
REPLACE FUNCTION.

Vincent Dautremont <vincent@searidgetech.com> writes:
>> An entirely blue-sky guess as
>> to what your code might be doing to trigger such a problem is if you
>> were constantly replacing the same function's definition via CREATE OR
>> REPLACE FUNCTION.

> Do you mean that what would happen is that when we call the plpgsql
> function, it executes each time a create or replace, then execute the
> function ?
> because my functions are all written like that :

> -- Function: spzoneinsert(integer, integer)
>> CREATE OR REPLACE FUNCTION spzoneinsert(i_zoneid integer, i_output_port
>> integer)
>> RETURNS void AS

Well, yeah, that is the common way to define a function.  The question
was about whether you are constantly re-executing this same SQL
thousands of times over the course of a session.  I think it would take
actually using the function in between such redefinitions to provoke a
plan leak, but if you were doing that it might explain the problem.

            regards, tom lane

Thanks,
So I've been able to find what's causing my postgres process memory amount to grow, but I don't know why it happens.

So, my software is updating 6 rows/second on my main database.
Rubyrep is running on my server with thebackup database doing a "replicate"
The huge TopMemoryContext problem and memory size of the postgres process are happening on my backup database.

I've found out that when my software does these updates the memory of the postgres process grows constantly at 24 MB/hour. when I stop my software to update these rows, the memory of the process stops to grow.

also I've noticed that when I stop rubyrep, this postgres process disappear.

I'm running rubyrep 1.2.0 and here is my rubyrep config file :

RR::Initializer::run do |config|
  config.left = {   # main database
    :adapter  => 'xxx',
    :database => 'yyy',
    :username => 'zzz',
    :password => 'ttt',
    :host     => '10.97.14.102'
  }

  config.right = {   # backup database
    :adapter  => 'xxx',
    :database => 'yyy',
    :username => 'zzz',
    :password => 'ttt',
    :host     => '10.97.14.101'
  }

  config.options[:sync_conflict_handling] = :right_wins
  config.options[:replication_conflict_handling] = :right_wins
  config.include_tables 'archiver'
  config.include_tables 'camera'
  config.include_tables 'cda'
  config.include_tables 'component_restart'
  config.include_tables 'operation_mode'
  config.include_tables 'ptz_lock'
  config.include_tables 'standby_table'
  config.include_tables 'video_output'

end

I don't know what other information I could add to that.

Vincent.



 

Vincent Dautremont <vincent@searidgetech.com> writes:
> I've found out that when my software does these updates the memory of the
> postgres process grows constantly at 24 MB/hour. when I stop my software to
> update these rows, the memory of the process stops to grow.
> also I've noticed that when I stop rubyrep, this postgres process disappear.

Hmm.  I wondered whether rubyrep might be triggering this somehow;
I don't know anything about that software.  I went so far as to download
rubyrep and look at the Postgres-specific source code yesterday.  It
doesn't look like it's doing anything strange, but I could easily have
missed something.

One thing you could try doing is to turn on query logging (set
log_statement = all) and look to see if rubyrep, or some other part of
your system, is indeed issuing repeated CREATE OR REPLACE FUNCTION
commands.

            regards, tom lane

Hi,
you were right,
I do see those CREATE OR REPLACE FUNCTION a bit more than 1 per second (approx. 12 times for 10 seconds)

2012-05-23 21:15:45 WET LOG:  execute <unnamed>:           CREATE OR REPLACE FUNCTION "rr_ptz_lock"() RETURNS TRIGGER AS $change_trigger$
                BEGIN
                              PERFORM ACTIVE FROM "public".rr_running_flags;
                IF FOUND THEN
                  RETURN NULL;
                END IF;
   
                  IF (TG_OP = 'DELETE') THEN
                    INSERT INTO "public".rr_pending_changes(change_table, change_key, change_type, change_time)
                      SELECT 'ptz_lock', 'workstation_id|' || OLD."workstation_id" || '|' || 'camera_id|' || OLD."camera_id", 'D', now();
                  ELSIF (TG_OP = 'UPDATE') THEN
                   
                    INSERT INTO  "public".rr_pending_changes(change_table, change_key, change_new_key, change_type, change_time)
                      SELECT 'ptz_lock', 'workstation_id|' || OLD."workstation_id" || '|' || 'camera_id|' || OLD."camera_id", 'workstation_id|' || NEW."workstation_id" || '|' || 'camera_id|' || NEW."camera_id", 'U', now();
                  ELSIF (TG_OP = 'INSERT') THEN
                    INSERT INTO  "public".rr_pending_changes(change_table, change_key, change_type, change_time)
                      SELECT 'ptz_lock', 'workstation_id|' || NEW."workstation_id" || '|' || 'camera_id|' || NEW."camera_id", 'I', now();
                  END IF;
                  RETURN NULL; -- result is ignored since this is an AFTER trigger
                END;
              $change_trigger$ LANGUAGE plpgsql

Vincent Dautremont <vincent@searidgetech.com> writes:
> you were right,
> I do see those CREATE OR REPLACE FUNCTION a bit more than 1 per second
> (approx. 12 times for 10 seconds)

Hah.  Complain to the rubyrep people.  It's most likely just a thinko
about where they should issue that command.  If they actually are
changing the function text from one issuance to the next, they would be
well advised to think of a better way to deal with whatever they're
doing that for; it's going to be quite inefficient even without
considering the effects of this leak.

> I don't know a lot about the internal of rubyrep, but do you think this is
> not a normal behaviour from a postgresql server point of view ?

It's not.  We have plugged that leak, I think, as of 9.1; but the fact
that it took us this long to notice the leak shows that constant
replacement of a function is not a common usage.  All the server's
internal caching related to functions is designed around the assumption
that functions aren't redefined too often.

If you can't get the rubyrep people to fix their code, updating to PG
9.1 is a possible workaround.

            regards, tom lane

Well,
Thank you very much for your help, it's greatly appreciated.
At least I can now pinpoint the problem and search for a solution or another reason to upgrade to 9.1 !

Regards,
Vincent.