Thread: BUG #5196: Excessive memory consumption when using csvlog

The following bug has been logged online:

Bug reference:      5196
Logged by:          Poindessous Thomas
Email address:      thomas@poindessous.com
PostgreSQL version: 8.3.8
Operating system:   Linux redhat 5.3 x86_64
Description:        Excessive memory consumption when using csvlog
Details:

Hi

we have a weird bug. When using csvlog instead of stderr, the postgres
logger process uses a lot of memory. We even had an OOM error with kernel.

For example, after 30 minutes of high use of the DB (apache benchmark),
logger process uses more than 1 Go of RAM :

begin of postgres :
ps fauxw :
pg83     14397 15.0  0.5 1148168 29472 ?       Ss   22:08   0:00
/usr/bin/postgres
pg83     14439  0.0  0.0  61076   800 ?        Ss   22:08   0:00  \_
postgres: logger process
pg83     14443  0.0  0.0 1148632 1096 ?        Ss   22:08   0:00  \_
postgres: writer process
pg83     14444  0.0  0.0 1148632  936 ?        Ss   22:08   0:00  \_
postgres: wal writer process
pg83     14445  0.0  0.0 1148820 1216 ?        Ss   22:08   0:00  \_
postgres: autovacuum launcher process
pg83     14446  0.0  0.0  61360   980 ?        Ss   22:08   0:00  \_
postgres: stats collector process


end of bench :
pg83     14397  2.8  0.5 1148168 29488 ?       Ss   22:08   0:33
/usr/bin/postgres
pg83     14439  2.6 21.6 1200360 1132696 ?     Ss   22:08   0:31  \_
postgres: logger process
pg83     14443  0.0  2.6 1148632 141380 ?      Ss   22:08   0:00  \_
postgres: writer process
pg83     14444  0.0  0.0 1148632 1044 ?        Ss   22:08   0:00  \_
postgres: wal writer process
pg83     14445  0.0  0.0 1148820 1256 ?        Ss   22:08   0:00  \_
postgres: autovacuum launcher process
pg83     14446  0.2  0.0  61360   980 ?        Ss   22:08   0:02  \_
postgres: stats collector process


If we change log_destination to stderr and we relaunch postgres and the
benchmark :

begin of postgres :
pg83     29567  1.3  0.5 1148168 29476 ?       Ss   22:37   0:00
/usr/bin/postgres
pg83     29572  0.0  0.0  61072   736 ?        Ss   22:37   0:00  \_
postgres: logger process
pg83     29574  0.0  0.0 1148632 3312 ?        Ss   22:37   0:00  \_
postgres: writer process
pg83     29575  0.0  0.0 1148632  936 ?        Ss   22:37   0:00  \_
postgres: wal writer process
pg83     29576  0.0  0.0 1148820 1244 ?        Ss   22:37   0:00  \_
postgres: autovacuum launcher process
pg83     29577  0.0  0.0  61360   980 ?        Ss   22:37   0:00  \_
postgres: stats collector process


end of bench :
pg83     29567  2.8  0.5 1148168 29484 ?       Ss   22:37   0:30
/usr/bin/postgres
pg83     29572  2.3  0.0  61072   804 ?        Ss   22:37   0:25  \_
postgres: logger process
pg83     29574  0.0  2.4 1148632 129872 ?      Ss   22:37   0:00  \_
postgres: writer process
pg83     29575  0.0  0.0 1148632 1052 ?        Ss   22:37   0:00  \_
postgres: wal writer process
pg83     29576  0.0  0.0 1148820 1244 ?        Ss   22:37   0:00  \_
postgres: autovacuum launcher process
pg83     29577  0.1  0.0  61360   980 ?        Ss   22:37   0:02  \_
postgres: stats collector process


Here are our param :
datestyle = 'iso, mdy'
default_text_search_config = 'pg_catalog.english'
effective_cache_size = 1536MB
lc_messages = 'C'
lc_monetary = 'C'
lc_numeric = 'C'
lc_time = 'C'
listen_addresses = '*'
log_checkpoints = on
log_connections = on
log_destination = 'stderr'
log_directory = 'pg_log'
log_disconnections = on
log_filename = 'postgresql-%Y-%m-%d.log'
log_hostname = on
log_line_prefix = '%m %u:%d : '
log_lock_waits = on
log_min_duration_statement = 0
logging_collector = on
maintenance_work_mem = 256MB
max_connections = 500
max_fsm_pages = 204800
shared_buffers = 1024MB
silent_mode = on
work_mem = 8MB

and we have 5 Go of physical RAM.

Thanks.

"Poindessous Thomas" <thomas@poindessous.com> writes:
> we have a weird bug. When using csvlog instead of stderr, the postgres
> logger process uses a lot of memory. We even had an OOM error with kernel.

I poked at this a bit and noted that if only one of the two possible
output files is rotated, logfile_rotate() leaks a copy of the other
file's name.  At the default settings this would only amount to one
filename string for every 10MB of output ... how much log output
does your test scenario generate?

            regards, tom lane

Hi,

for csv output, we have a 750 Mo logfile. But on another site, we have
an logfile of 1,6 Go and logger process was using more than 3 Go of
RAM.

Even with our configuration (log collector, silent mode and
csv/stderr), we launched potsgresql daemon like this :
pg_ctl -l ${HOME}/pgsql/logs/postgres.log start

so we have three logfiles :

postgresql.log (always empty)
postgresql-YYYY-MM-DD.csv (big file if set to csvlog)
postgresql-YYYY-MM-DD.log (always empty if set to csvlog)

Thanks.

2009/11/19 Tom Lane <tgl@sss.pgh.pa.us>:
> "Poindessous Thomas" <thomas@poindessous.com> writes:
>> we have a weird bug. When using csvlog instead of stderr, the postgres
>> logger process uses a lot of memory. We even had an OOM error with kerne=
l.
>
> I poked at this a bit and noted that if only one of the two possible
> output files is rotated, logfile_rotate() leaks a copy of the other
> file's name. =A0At the default settings this would only amount to one
> filename string for every 10MB of output ... how much log output
> does your test scenario generate?
>
> =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0regards, tom lane
>