SEO

While going through some log files, we noticed that some of the log entries
are "garbled". For example:

2007-03-27 01:19:44.139 UTC [1761474] oxrsa aepp xx.xx.xx.xx LOG:
duratio2007-03-n: 3751.27 01:19801 ms :44.139 statemenUTC [421940]
oxrt: EXECUsor
g aTE <unnaepp 10.4med> [P0.136.10REPARE: 8 LOG: select
durationname fro: 3866.1m epp_do88 ms smain_dz_tatementnames wh:
EXECUTere nameE <unnam = $1]
2007-03-27 01:19:49.213 UTC [528480] oxrsa aepp xx.xx.xx.xx LOG:
duration: 4510.129 ms statement: EXECUTE <unnam2007-03-ed> [PR27
01:19EPARE: :49
.213 select nUTC [294ame from930] oxr b_domsa aain_dz_nb
10.4ames whe0.136.10re name 7 LOG: = $1]

Here are the logging sections in the postgresql.conf file:

log_destination = 'stderr'
redirect_stderr = on
log_directory = '/opt/rg/logs/pgsql81'
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'
log_truncate_on_rotation = off
log_rotation_age = 1440
log_rotation_size = 10240
log_line_prefix = '%m [%p] %d %u %h ' # Special values:

We're seeing this in postgresql 8.1.8 on AIX 5.3. Also, even though we're
using the same binaries for a bunch of clusters, we've only seen this issue
on one of them.

Any ideas of what could cause this?

--
Tim Goodaire 416-673-4126 tgoodair@ca.afilias.info
Database Team Lead, Afilias Canada Corp.

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQBGEmkFRI056rlRJ/YRAjaFAJ0ayHeUt1JXRTud8dL7InNz9Z5wwwCffxOK
1tB8RLzdk5JpJ0xbO1hcjPc=
=9Brx
-----END PGP SIGNATURE-----

Tim Goodaire <tgoodair@ca.afilias.info> writes:
> While going through some log files, we noticed that some of the log entries
> are "garbled". For example:

> 2007-03-27 01:19:44.139 UTC [1761474] oxrsa aepp xx.xx.xx.xx LOG:
> duratio2007-03-n: 3751.27 01:19801 ms :44.139 statemenUTC [421940]
> oxrt: EXECUsor
> g aTE <unnaepp 10.4med> [P0.136.10REPARE: 8 LOG: select
> durationname fro: 3866.1m epp_do88 ms smain_dz_tatementnames wh:
> EXECUTere nameE <unnam = $1]
> 2007-03-27 01:19:49.213 UTC [528480] oxrsa aepp xx.xx.xx.xx LOG:
> duration: 4510.129 ms statement: EXECUTE <unnam2007-03-ed> [PR27
> 01:19EPARE: :49
> .213 select nUTC [294ame from930] oxr b_domsa aain_dz_nb
> 10.4ames whe0.136.10re name 7 LOG: = $1]

> We're seeing this in postgresql 8.1.8 on AIX 5.3. Also, even though we're
> using the same binaries for a bunch of clusters, we've only seen this issue
> on one of them.

It looks like you've got messages from different backends being
interleaved, which is surely not impossible but normally it only happens
line-by-line at worst. This must have something to do with the
buffering behavior on stderr. Perhaps the difference is caused
by a difference in where the postmaster's stderr originally pointed
--- was this postmaster started in a different fashion than the others?

Note to hackers: would it make sense to use write() instead of
fprintf() in send_message_to_server_log to avoid any possibility
of stdio deciding to fragment the message? Possibly there'd be
some marginal efficiency gain too.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Tom Lane wrote:
> Note to hackers: would it make sense to use write() instead of
> fprintf() in send_message_to_server_log to avoid any possibility
> of stdio deciding to fragment the message? Possibly there'd be
> some marginal efficiency gain too.
>

What about in write_syslogger_file_binary()? Since redirect_stderr is
set true in the case reported, wont that be what does the writing?

cheers

andrew


---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

On Tue, 2007-04-03 at 15:02 -0400, Tom Lane wrote:
> Tim Goodaire <tgoodair@ca.afilias.info> writes:
> > While going through some log files, we noticed that some of the log entries
> > are "garbled". For example:
>
> > 2007-03-27 01:19:44.139 UTC [1761474] oxrsa aepp xx.xx.xx.xx LOG:
> > duratio2007-03-n: 3751.27 01:19801 ms :44.139 statemenUTC [421940]
> > oxrt: EXECUsor
> > g aTE <unnaepp 10.4med> [P0.136.10REPARE: 8 LOG: select
> > durationname fro: 3866.1m epp_do88 ms smain_dz_tatementnames wh:
> > EXECUTere nameE <unnam = $1]
> > 2007-03-27 01:19:49.213 UTC [528480] oxrsa aepp xx.xx.xx.xx LOG:
> > duration: 4510.129 ms statement: EXECUTE <unnam2007-03-ed> [PR27
> > 01:19EPARE: :49
> > .213 select nUTC [294ame from930] oxr b_domsa aain_dz_nb
> > 10.4ames whe0.136.10re name 7 LOG: = $1]
>
> > We're seeing this in postgresql 8.1.8 on AIX 5.3. Also, even though we're
> > using the same binaries for a bunch of clusters, we've only seen this issue
> > on one of them.
>
> It looks like you've got messages from different backends being
> interleaved, which is surely not impossible but normally it only happens
> line-by-line at worst. This must have something to do with the
> buffering behavior on stderr. Perhaps the difference is caused
> by a difference in where the postmaster's stderr originally pointed
> --- was this postmaster started in a different fashion than the others?

No. Standard init script was used to start all clusters.

--
Brad Nicholson 416-673-4106
Database Administrator, Afilias Canada Corp.


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> Note to hackers: would it make sense to use write() instead of
>> fprintf() in send_message_to_server_log to avoid any possibility
>> of stdio deciding to fragment the message? Possibly there'd be
>> some marginal efficiency gain too.

> What about in write_syslogger_file_binary()? Since redirect_stderr is
> set true in the case reported, wont that be what does the writing?

No, syslogger is single-threaded so it can't be at fault. The
interleaving must be happening when the data is inserted into the pipe
that leads to syslogger. We've got multiple backends concurrently
writing that pipe, remember.

BTW, although I'm blaming stdio here, it's conceivable that it is
issuing messages in a single write() and the kernel is failing to keep
the writes atomic, as I think is required by spec if the write is for
less than PIPEBUF bytes. So Tim might want to compare exact kernel
versions as well as exact libc versions between the misbehaving machine
and the others.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

On Tue, Apr 03, 2007 at 04:51:33PM -0400, Tom Lane wrote:
> No, syslogger is single-threaded so it can't be at fault. The
> interleaving must be happening when the data is inserted into the pipe
> that leads to syslogger. We've got multiple backends concurrently
> writing that pipe, remember.
>
> BTW, although I'm blaming stdio here, it's conceivable that it is
> issuing messages in a single write() and the kernel is failing to keep
> the writes atomic, as I think is required by spec if the write is for
> less than PIPEBUF bytes. So Tim might want to compare exact kernel
> versions as well as exact libc versions between the misbehaving machine
> and the others.

I've compared the libc and kernel versions between a misbehaving machine and a
machine that is logging properly and they're the same:

bos.rte.libc 5.3.0.52 C F libc Library
bos.mp64:bos.mp64:5.3.0.52: : :A:F:Base Operating System 64-bit
Multiprocessor Runtime

--
Tim Goodaire 416-673-4126 tgoodair@ca.afilias.info
Database Team Lead, Afilias Canada Corp.

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

tgoodair@ca.afilias.info (Tim Goodaire) writes:
> I've compared the libc and kernel versions between a misbehaving machine and a
> machine that is logging properly and they're the same:

[ scratches head... ] So what's different?

Anyway, if you are interested in trying to cut libc out of the equation,
the patch I had in mind goes like this (against 8.1)

regards, tom lane


*** src/backend/utils/error/elog.c.orig Thu Feb 22 03:11:50 2007
--- src/backend/utils/error/elog.c Thu Apr 5 12:03:57 2007
***************
*** 1710,1716 ****
write_eventlog(edata->elevel, buf.data);
else
#endif
! fprintf(stderr, "%s", buf.data);
}

/* If in the syslogger process, try to write messages direct to file */
--- 1710,1716 ----
write_eventlog(edata->elevel, buf.data);
else
#endif
! write(fileno(stderr), buf.data, buf.len);
}

/* If in the syslogger process, try to write messages direct to file */
***************
*** 2043,2048 ****
--- 2043,2049 ----
#ifndef WIN32
/* On Unix, we just fprintf to stderr */
vfprintf(stderr, fmt, ap);
+ fflush(stderr);
#else

/*
***************
*** 2058,2065 ****
--- 2059,2069 ----
write_eventlog(EVENTLOG_ERROR_TYPE, errbuf);
}
else
+ {
/* Not running as service, write to stderr */
vfprintf(stderr, fmt, ap);
+ fflush(stderr);
+ }
#endif
va_end(ap);
}


---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings