Re: query log corrupted-looking entries

Hoping to resurrect this thread. I am seeing more and more of this as
the database gets more usage and it really messes up query log analysis.


A quick summary: When I posted this was getting corrupted query log
entries. I still am. They look like this (the problem line + one line
before and after):

2007-05-15 14:24:52 PDT [3859]: [968-1] LOG:  duration: 0.071 ms
2007-05-15 14:24:52 PDT [3859]: [969-1] LOG:  statement2007-05-15
14:24:52 PDT [3885]: [208-1] LOG:  duration: 11.800 ms
: PREPARE <unnamed> AS SELECT P.IS_DISPLAY, P.IS_ACTIVE,
P.CITY_POSTAL_CODE_ID,P.property_name,P.address_1,P.address_2,

This seems to happen with statements of all lengths (some are long, but
many are not).

This used to happen on 8.1.3. I am now on: PostgreSQL 8.1.8 on
x86_64-redhat-linux-gnu, compiled by GCC gcc (GCC) 3.4.6 20060404 (Red
Hat 3.4.6-3)

I think what Tom suggested last (see below) is that I try something on
my machine, but it was not entirely to me what exactly and I failed to
follow up. I'd be happy to do any tests to help diagnose this better,
although I don't have a reliable way to reproduce it ("put a lot of
stress on the DB" is all I can do and hope it happens).

Thanks,

George



> -----Original Message-----
> From: George Pavlov
> Sent: Wednesday, October 18, 2006 1:23 PM
> To: Tom Lane
> Cc: pgsql-hackers@postgreSQL.org
> Subject: RE: [GENERAL] query log corrupted-looking entries
>
> > the behavior.  It'd be interesting to verify whether it's
> the same on
> > George's machine though.
>
> Let me know how to test this. (Please do a "for dummies"
> version -- I am not sure I can figure it out from the thread
> even though someone else might be able to.)
>
>

> -----Original Message-----
> From: Tom Lane [mailto:tgl@sss.pgh.pa.us]
> Sent: Wednesday, October 18, 2006 1:17 PM
> To: George Pavlov
> Cc: pgsql-hackers@postgreSQL.org
> Subject: Re: [GENERAL] query log corrupted-looking entries
>
> I wrote:
> > I checked around with some kernel/glibc gurus in Red Hat, and the
> > consensus seemed to be that we'd be better off to bypass
> fprintf() and
> > just send message strings to stderr using write() --- ie, instead of
> > elog.c doing
> >             fprintf(stderr, "%s", buf.data);
> > do
> >             write(fileno(stderr), buf.data, strlen(buf.data));
>
> I did some strace'ing of the backend, and observed that even for very
> long messages (upwards of 100K) the fprintf results in a
> single write()
> call.  This was true on both Fedora Core 5 and a pretty old
> HPUX version.
> So it'd seem that most versions of libc already know about optimizing
> fprintf-%s into a direct write(), and changing our code
> wouldn't change
> the behavior.  It'd be interesting to verify whether it's the same on
> George's machine though.
>
>             regards, tom lane
>