Skip site navigation (1) Skip section navigation (2)

8.3rc1 Out of memory when performing update

From: "Stephen Denne" <Stephen(dot)Denne(at)datamail(dot)co(dot)nz>
To: <pgsql-performance(at)postgresql(dot)org>
Subject: 8.3rc1 Out of memory when performing update
Date: 2008-01-24 23:46:20
Message-ID: F0238EBA67824444BC1CB4700960CB480482B525@dmpeints002.isotach.com (view raw or flat)
Thread:
Lists: pgsql-performance
A simple update query, over roughly 17 million rows, populating a newly added column in a table, resulted in an out of memory error when the process memory usage reached 2GB. Could this be due to a poor choice of some configuration parameter, or is there a limit on how many rows I can update in a single statement?

Log:
...
2008-01-25 09:42:08.119 NZDT [3432]: [1-1] LOG:  checkpoint starting: time
2008-01-25 09:42:08.697 NZDT [3432]: [2-1] LOG:  checkpoint complete: wrote 2 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.218 s, sync=0.047 s, total=0.578 s
...
2008-01-25 10:44:49.011 NZDT [3824]: [1-1] LOG:  connection received: host=(removed) port=3207
2008-01-25 10:44:49.042 NZDT [3824]: [2-1] LOG:  connection authorized: user=postgres database=(removed)
2008-01-25 10:52:08.204 NZDT [3432]: [3-1] LOG:  checkpoint starting: time
2008-01-25 10:52:39.673 NZDT [3432]: [4-1] LOG:  checkpoint complete: wrote 275 buffers (6.7%); 1 transaction log file(s) added, 0 removed, 0 recycled; write=27.078 s, sync=1.485 s, total=31.407 s
2008-01-25 11:02:08.055 NZDT [3432]: [5-1] LOG:  checkpoint starting: time
2008-01-25 11:02:32.759 NZDT [3432]: [6-1] LOG:  checkpoint complete: wrote 222 buffers (5.4%); 0 transaction log file(s) added, 0 removed, 69 recycled; write=22.766 s, sync=0.968 s, total=24.704 s
2008-01-25 11:12:08.344 NZDT [3432]: [7-1] LOG:  checkpoint starting: time
2008-01-25 11:12:38.423 NZDT [3432]: [8-1] LOG:  checkpoint complete: wrote 268 buffers (6.5%); 0 transaction log file(s) added, 0 removed, 77 recycled; write=27.875 s, sync=1.312 s, total=30.094 s
2008-01-25 11:22:08.088 NZDT [3432]: [9-1] LOG:  checkpoint starting: time
2008-01-25 11:22:29.526 NZDT [3432]: [10-1] LOG:  checkpoint complete: wrote 188 buffers (4.6%); 0 transaction log file(s) added, 0 removed, 48 recycled; write=18.155 s, sync=1.391 s, total=21.312 s
2008-01-25 11:32:08.362 NZDT [3432]: [11-1] LOG:  checkpoint starting: time
2008-01-25 11:33:21.706 NZDT [3432]: [12-1] LOG:  checkpoint complete: wrote 672 buffers (16.4%); 0 transaction log file(s) added, 0 removed, 59 recycled; write=70.423 s, sync=1.562 s, total=73.375 s
2008-01-25 11:42:08.244 NZDT [3432]: [13-1] LOG:  checkpoint starting: time
2008-01-25 11:42:27.010 NZDT [3432]: [14-1] LOG:  checkpoint complete: wrote 175 buffers (4.3%); 0 transaction log file(s) added, 0 removed, 51 recycled; write=17.077 s, sync=1.204 s, total=18.813 s
2008-01-25 11:52:08.299 NZDT [3432]: [15-1] LOG:  checkpoint starting: time
2008-01-25 11:52:33.627 NZDT [3432]: [16-1] LOG:  checkpoint complete: wrote 233 buffers (5.7%); 0 transaction log file(s) added, 0 removed, 64 recycled; write=23.328 s, sync=1.468 s, total=25.391 s
TopMemoryContext: 49816 total in 6 blocks; 5656 free (6 chunks); 44160 used
  RI compare cache: 8192 total in 1 blocks; 1800 free (0 chunks); 6392 used
  RI query cache: 8192 total in 1 blocks; 5968 free (0 chunks); 2224 used
  TopTransactionContext: 8192 total in 1 blocks; 7792 free (0 chunks); 400 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: 40960 total in 3 blocks; 19960 free (5 chunks); 21000 used
  smgr relation table: 8192 total in 1 blocks; 2808 free (0 chunks); 5384 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: 1024 total in 1 blocks; 760 free (0 chunks); 264 used
      ExecutorState: 2044715008 total in 270 blocks; 21056 free (262 chunks); 2044693952 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
  Relcache by OID: 8192 total in 1 blocks; 3376 free (0 chunks); 4816 used
  CacheMemoryContext: 667472 total in 20 blocks; 182800 free (1 chunks); 484672 used
  location_ix: 1024 total in 1 blocks; 304 free (0 chunks); 720 used
...    [Cut 58 indexes with very similar lines to the above, to save space]
  MdSmgr: 8192 total in 1 blocks; 7240 free (0 chunks); 952 used
  LOCALLOCK hash: 8192 total in 1 blocks; 3912 free (0 chunks); 4280 used
  Timezones: 49432 total in 2 blocks; 5968 free (0 chunks); 43464 used
  ErrorContext: 8192 total in 1 blocks; 8176 free (3 chunks); 16 used
2008-01-25 11:53:10.315 NZDT [3824]: [3-1] ERROR:  out of memory
2008-01-25 11:53:10.362 NZDT [3824]: [4-1] DETAIL:  Failed on request of size 28.
2008-01-25 11:53:10.362 NZDT [3824]: [5-1] STATEMENT:  UPDATE document_file SET document_type_id = (SELECT document_type_id FROM document d where d.id = document_id);
2008-01-25 12:00:53.571 NZDT [3604]: [1-1] LOG:  connection received: host=(removed) port=3399
2008-01-25 12:00:54.274 NZDT [3604]: [2-1] LOG:  connection authorized: user=postgres database=(removed)
2008-01-25 12:00:55.727 NZDT [3604]: [3-1] LOG:  duration: 1264.999 ms  statement: SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS encoding, datlastsysoid
	  FROM pg_database WHERE oid = 16466
2008-01-25 12:02:08.322 NZDT [3432]: [17-1] LOG:  checkpoint starting: time
2008-01-25 12:07:03.591 NZDT [3432]: [18-1] LOG:  checkpoint complete: wrote 2784 buffers (68.0%); 0 transaction log file(s) added, 0 removed, 92 recycled; write=292.488 s, sync=1.515 s, total=295.473 s
2008-01-25 12:10:07.031 NZDT [3604]: [4-1] LOG:  duration: 539646.999 ms  statement: select count(*) from document_file;
2008-01-25 12:12:08.048 NZDT [3432]: [19-1] LOG:  checkpoint starting: time
2008-01-25 12:15:22.176 NZDT [3432]: [20-1] LOG:  checkpoint complete: wrote 949 buffers (23.2%); 0 transaction log file(s) added, 0 removed, 8 recycled; write=193.097 s, sync=0.936 s, total=194.127 s

Environment:
OS: Windows XP
PostgreSQL: 8.3RC1

Non default Resource and WAL configuration settings:
shared_buffers = 32MB
max_fsm_pages = 204800
checkpoint_segments = 300
checkpoint_timeout = 10min

The previous query (not logged due to log_min_duration_statement = 500) had been:
ALTER TABLE document_file ADD document_type_id integer;

The query plan:
Seq Scan on document_file  (cost=0.00..280337907.00 rows=27619541 width=617)
  SubPlan
    ->  Index Scan using pk_document_id on document d  (cost=0.00..10.12 rows=1 width=4)
          Index Cond: (id = $0)

Stephen Denne

Disclaimer:
At the Datamail Group we value team commitment, respect, achievement, customer focus, and courage. This email with any attachments is confidential and may be subject to legal privilege.  If it is not intended for you please advise by reply immediately, destroy it and do not copy, disclose or use it in any way.

__________________________________________________________________
  This email has been scanned by the DMZGlobal Business Quality 
              Electronic Messaging Suite.
Please see http://www.dmzglobal.com/services/bqem.htm for details.
__________________________________________________________________

Responses

pgsql-performance by date

Next:From: Fernando IkeDate: 2008-01-25 01:14:33
Subject: Re: 8.3rc1 Out of memory when performing update
Previous:From: Greg SmithDate: 2008-01-24 18:52:49
Subject: Re: Configuration settings (shared_buffers, etc) in Linux: puzzled

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group