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
Views: Raw Message | Whole Thread | Download mbox | Resend email
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

Browse pgsql-performance by date

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