Thread: syslog slowing the database?

syslog slowing the database?

From
Greg Spiegelberg
Date:
I've been waiting all day for a pg_restore to finish on a test system
identically configured as our production in hardware and software
with the exception prod is 7.3.5 and test is 7.4.1.

The file it's restoring from is about 8GB uncompressed from a
"pg_dump -b -F t" and after 2 hours the directory the database is in
contains only 1GB.  iostat reported ~2000 blocks written every 2
seconds to the DB file system.

I turned syslog off to see if it was blocking anything and in the
past couple minutes 1GB has been restored and iostat reports ~35,000
blocks written every 2 seconds to the DB file system.

The system is completely idle except for this restore process.  Could
syslog the culprit?

I turned syslog back on and the restore slowed down again.  Turned
it off and it sped right back up.

Can anyone confirm this for me?

Greg

--
Greg Spiegelberg
  Sr. Product Development Engineer
  Cranel, Incorporated.
  Phone: 614.318.4314
  Fax:   614.431.8388
  Email: gspiegelberg@Cranel.com
Cranel. Technology. Integrity. Focus.



Re: syslog slowing the database?

From
Tom Lane
Date:
Greg Spiegelberg <gspiegelberg@cranel.com> writes:
> I turned syslog back on and the restore slowed down again.  Turned
> it off and it sped right back up.

We have heard reports before of syslog being quite slow.  What platform
are you on exactly?  Does Richard's suggestion of turning off syslog's
fsync help?

            regards, tom lane

Re: [PERFORM] syslog slowing the database?

From
Richard Huxton
Date:
On Tuesday 09 March 2004 20:29, Greg Spiegelberg wrote:

> iostat reported ~2000 blocks written every 2
> seconds to the DB file system.
>
> I turned syslog off to see if it was blocking anything and in the
> past couple minutes 1GB has been restored and iostat reports ~35,000
> blocks written every 2 seconds to the DB file system.

> Can anyone confirm this for me?

If syslog is set to sync after every line and you're logging too much then it
could slow things down as the disk heads shift back and fore between two
areas of disk. How many disks do you have and in what configuration?

Also - was PG logging a lot of info, or is some other application the culprit?

Tip: put a minus "-" in front of the file-path in your syslog.conf and it
won't sync to disk after every entry.

--
  Richard Huxton
  Archonet Ltd

Re: [PERFORM] syslog slowing the database?

From
"Gavin M. Roy"
Date:
Might want to look at metalog, it does delayed writes, though ultimately
your issue is io bound and there's not much you can do to reduce io if
you want to keep syslog logging your pgsql queries and such.

Tom Lane wrote:

>Greg Spiegelberg <gspiegelberg@cranel.com> writes:
>
>
>>I turned syslog back on and the restore slowed down again.  Turned
>>it off and it sped right back up.
>>
>>
>
>We have heard reports before of syslog being quite slow.  What platform
>are you on exactly?  Does Richard's suggestion of turning off syslog's
>fsync help?
>
>            regards, tom lane
>
>---------------------------(end of broadcast)---------------------------
>TIP 3: if posting/reading through Usenet, please send an appropriate
>      subscribe-nomail command to majordomo@postgresql.org so that your
>      message can get through to the mailing list cleanly
>
>


Re: [PERFORM] syslog slowing the database?

From
"Magnus Naeslund(t)"
Date:
Tom Lane wrote:
> Greg Spiegelberg <gspiegelberg@cranel.com> writes:
>
>>I turned syslog back on and the restore slowed down again.  Turned
>>it off and it sped right back up.
>
>
> We have heard reports before of syslog being quite slow.  What platform
> are you on exactly?  Does Richard's suggestion of turning off syslog's
> fsync help?
>

Another tip is to use a better (well atleast more optimized) syslog
implementation, like metalog. It optimizes log writes to a blocksize
that is better for disk throughput.
You can also use "per line" mode with those if you want, i think.

I use another logger that is called multilog (see at http://cr.yp.to),
that's a pipe logger thing, like one per postmaster.
It also gives very exact timestamps to every line, has built in log
rotation and works nice with all programs i use it for.

One thing is for sure, if you log much, standard syslog (atleast on
linux) sucks big time.
I gained back approx 30% CPU on a mailserver over here by changing to
another logger.

Cheers
Magnus




Re: [PERFORM] syslog slowing the database?

From
Stephen Robert Norris
Date:
On Wed, 2004-03-10 at 12:09, Gavin M. Roy wrote:
> Might want to look at metalog, it does delayed writes, though ultimately
> your issue is io bound and there's not much you can do to reduce io if
> you want to keep syslog logging your pgsql queries and such.

Yeah, but syslog with fsync() after each line is much, much worse than
syslog without it, assuming anything else is on the same disk (array).
It just guarantees to screw up your drive head movements...

--
Stephen Norris      srn@fn.com.au
Farrow Norris Pty Ltd    +61 417 243 239


Re: syslog slowing the database?

From
Greg Spiegelberg
Date:
Tom Lane wrote:
> Greg Spiegelberg <gspiegelberg@cranel.com> writes:
>
>>I turned syslog back on and the restore slowed down again.  Turned
>>it off and it sped right back up.
>
> We have heard reports before of syslog being quite slow.  What platform
> are you on exactly?  Does Richard's suggestion of turning off syslog's
> fsync help?

RedHat 7.3 w/ 2.4.24 kernel on a dual Intel PIII 1.3Ghz, 2GB memory,
U160 internal on integrated controller, 1Gbps SAN for database.
Database file being restored and the actual database are on different
disk and controllers than syslog files.

With the ``-'' in front of the syslog file postgres logs too gives
me roughly 75% of the I/O the performance as reported by iostat.  So,
it helps though turning syslog off gives the optimum performance.

If the log and database were on the same disk I'd be okay with the
current workaround.  If the ``-'' gave me near the same performance as
turning syslog off I'd be okay with that too.  However, neither of these
are the case so there has to be something else blocking between the two
processes.

<2 hours and multiple test later>

I've found that hardware interrupts are the culprit.  Given my system
config both SCSI and fibre controllers were throttling the system with
the interrupts required to write the data (syslog & database) and read
the data from the restore.  I'm okay with that.

In the order of worst to best.

* There were, on average about 450 interrupts/sec with the default
   config of syslog on one disk, database on the SAN and syslog using
   fsync.

* Turning fsync off in syslog puts interrupts around 105/sec and.

* Having syslog fsync turned off in syslog AND moving the syslog file
   to a filesystem serviced by the same fibre controller put interrupts
   at around 92/sec.  I decided to do this after watching the I/O on
   the SAN with syslog turned off and found that it had bandwidth to
   spare.  FYI, the system when idle generated about 50 interrupts/sec.


I'm going with the later for now on the test system and after running
it through it's paces with all our processes I'll make the change in
production.  I'll post if I run into anything else.

Greg


BTW, I like what metalog has to offer but I prefer using as many of the
default tools as possible and replacing them only when absolutely
necessary.  What I've learned with syslog here is that it is still
viable but likely requires a minor tweak.  If this tweak fails in
testing I'll look at metalog then.


--
Greg Spiegelberg
  Sr. Product Development Engineer
  Cranel, Incorporated.
  Phone: 614.318.4314
  Fax:   614.431.8388
  Email: gspiegelberg@Cranel.com
Cranel. Technology. Integrity. Focus.



Re: syslog slowing the database?

From
Tom Lane
Date:
Greg Spiegelberg <gspiegelberg@cranel.com> writes:
> If the log and database were on the same disk I'd be okay with the
> current workaround.  If the ``-'' gave me near the same performance as
> turning syslog off I'd be okay with that too.  However, neither of these
> are the case so there has to be something else blocking between the two
> processes.

You could also consider not using syslog at all: let the postmaster
output to its stderr, and pipe that into a log-rotation program.
I believe some people use Apache's log rotator for this with good
results.

            regards, tom lane

Re: syslog slowing the database?

From
Mark Harrison
Date:
Tom Lane wrote:
> Greg Spiegelberg <gspiegelberg@cranel.com> writes:
>
>>If the log and database were on the same disk I'd be okay with the
>>current workaround.  If the ``-'' gave me near the same performance as
>>turning syslog off I'd be okay with that too.  However, neither of these
>>are the case so there has to be something else blocking between the two
>>processes.
>
>
> You could also consider not using syslog at all: let the postmaster
> output to its stderr, and pipe that into a log-rotation program.
> I believe some people use Apache's log rotator for this with good
> results.

I do this... here's the relevant lines from my startup script:

ROTATE="/inst/apache/bin/rotatelogs $PGLOGS/postgresql 86400"
$PGBIN/pg_ctl start -s -D $PGDATA | $ROTATE &

Following is a patch to rotatelogs that does two things:

- makes a symbolic link 'foo.current' that points to the
   current output file.

- gzips the rotated logfile

If you have gnu tools installed, you can
     tail --retry --follow=name foo.current
and it will automatically track the most recent
log file.

HTH,
Mark

--
Mark Harrison
Pixar Animation Studios


*** rotatelogs.c-orig    2004-03-10 10:24:02.000000000 -0800
--- rotatelogs.c    2004-03-10 11:01:55.000000000 -0800
***************
*** 25,30 ****
--- 25,32 ----
   int main (int argc, char **argv)
   {
       char buf[BUFSIZE], buf2[MAX_PATH], errbuf[ERRMSGSZ];
+     char linkbuf[MAX_PATH];
+     char oldbuf2[MAX_PATH];
       time_t tLogEnd = 0, tRotation;
       int nLogFD = -1, nLogFDprev = -1, nMessCount = 0, nRead, nWrite;
       int utc_offset = 0;
***************
*** 75,80 ****
--- 77,84 ----
       setmode(0, O_BINARY);
   #endif

+     sprintf(linkbuf, "%s.current", szLogRoot);
+     sprintf(oldbuf2, "");
       use_strftime = (strstr(szLogRoot, "%") != NULL);
       for (;;) {
           nRead = read(0, buf, sizeof buf);
***************
*** 99,104 ****
--- 103,111 ----
                   sprintf(buf2, "%s.%010d", szLogRoot, (int) tLogStart);
               }
               tLogEnd = tLogStart + tRotation;
+ printf("oldbuf2=%s\n",oldbuf2);
+ printf("buf2=%s\n",buf2);
+ printf("linkbuf=%s\n",linkbuf);
               nLogFD = open(buf2, O_WRONLY | O_CREAT | O_APPEND, 0666);
               if (nLogFD < 0) {
                   /* Uh-oh. Failed to open the new log file. Try to clear
***************
*** 125,130 ****
--- 132,146 ----
               }
               else {
                   close(nLogFDprev);
+                 /* use: tail --follow=name foo.current */
+                 unlink(linkbuf);
+                 symlink(buf2,linkbuf);
+                 if (strlen(oldbuf2) > 0) {
+                     char cmd[MAX_PATH+100];
+                     sprintf(cmd, "gzip %s &", oldbuf2);
+                     system(cmd);
+                 }
+                 strcpy(oldbuf2, buf2);
               }
               nMessCount = 0;
           }


Re: [PERFORM] syslog slowing the database?

From
Bruno Wolff III
Date:
On Thu, Mar 11, 2004 at 09:34:54 +0800,
  Christopher Kings-Lynne <chriskl@familyhealth.com.au> wrote:
> >You could also consider not using syslog at all: let the postmaster
> >output to its stderr, and pipe that into a log-rotation program.
> >I believe some people use Apache's log rotator for this with good
> >results.
>
> Not an option I'm afraid.  PostgreSQL just jams and stops logging after
> the first rotation...
>
> I've read in the docs that syslog logging is the only "production"
> solution...

I use multilog to log postgres' output and it works fine.

Re: [PERFORM] syslog slowing the database?

From
Tom Lane
Date:
Christopher Kings-Lynne <chriskl@familyhealth.com.au> writes:
>> You could also consider not using syslog at all: let the postmaster
>> output to its stderr, and pipe that into a log-rotation program.
>> I believe some people use Apache's log rotator for this with good
>> results.

> Not an option I'm afraid.  PostgreSQL just jams and stops logging after
> the first rotation...

I know some people use this in production.  Dunno what went wrong in
your test, but it can be made to work.

            regards, tom lane

Re: [PERFORM] syslog slowing the database?

From
Christopher Kings-Lynne
Date:
> You could also consider not using syslog at all: let the postmaster
> output to its stderr, and pipe that into a log-rotation program.
> I believe some people use Apache's log rotator for this with good
> results.

Not an option I'm afraid.  PostgreSQL just jams and stops logging after
the first rotation...

I've read in the docs that syslog logging is the only "production"
solution...

Chris


Re: [PERFORM] syslog slowing the database?

From
"Joshua D. Drake"
Date:
>>Not an option I'm afraid.  PostgreSQL just jams and stops logging after
>>the first rotation...

Are you using a copy truncate method to rotate the logs? In RedHat add
the keyword COPYTRUCATE to your /etc/logrotate.d/syslog file.

Sincerely,

Joshua D. Drake



>
>
> I know some people use this in production.  Dunno what went wrong in
> your test, but it can be made to work.
>
>             regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: you can get off all lists at once with the unregister command
>     (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)


Attachment

Re: [PERFORM] syslog slowing the database?

From
"Chris Smith"
Date:
It might depend on how you're rotating it.

Try the copy/truncate method instead of moving the log file. If you move
the log file to another filename you usually have to restart the app
doing the logging before it starts logging again.

Chris.

-----Original Message-----
From: pgsql-performance-owner@postgresql.org
[mailto:pgsql-performance-owner@postgresql.org] On Behalf Of Christopher
Kings-Lynne
Sent: Thursday, March 11, 2004 12:35 PM
To: Tom Lane
Cc: Greg Spiegelberg; PgSQL Performance ML; Postgres Admin List
Subject: Re: [PERFORM] [ADMIN] syslog slowing the database?


> You could also consider not using syslog at all: let the postmaster
> output to its stderr, and pipe that into a log-rotation program. I
> believe some people use Apache's log rotator for this with good
> results.

Not an option I'm afraid.  PostgreSQL just jams and stops logging after
the first rotation...

I've read in the docs that syslog logging is the only "production"
solution...

Chris


---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command
    (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)



Re: [PERFORM] syslog slowing the database?

From
"scott.marlowe"
Date:
On Thu, 11 Mar 2004, Christopher Kings-Lynne wrote:

> > You could also consider not using syslog at all: let the postmaster
> > output to its stderr, and pipe that into a log-rotation program.
> > I believe some people use Apache's log rotator for this with good
> > results.
>
> Not an option I'm afraid.  PostgreSQL just jams and stops logging after
> the first rotation...
>
> I've read in the docs that syslog logging is the only "production"
> solution...

Can you use the apache log rotator?  It's known to work in my environment
(redhat 7.2, postgresql 7.2 and 7.4) with this command to start it in my
rc.local file:

su - postgres -c 'pg_ctl start | rotatelogs $PGDATA/pglog 86400 2>1&'


Re: [PERFORM] syslog slowing the database?

From
Bruce Momjian
Date:
scott.marlowe wrote:
> On Thu, 11 Mar 2004, Christopher Kings-Lynne wrote:
>
> > > You could also consider not using syslog at all: let the postmaster
> > > output to its stderr, and pipe that into a log-rotation program.
> > > I believe some people use Apache's log rotator for this with good
> > > results.
> >
> > Not an option I'm afraid.  PostgreSQL just jams and stops logging after
> > the first rotation...
> >
> > I've read in the docs that syslog logging is the only "production"
> > solution...
>
> Can you use the apache log rotator?  It's known to work in my environment
> (redhat 7.2, postgresql 7.2 and 7.4) with this command to start it in my
> rc.local file:
>
> su - postgres -c 'pg_ctl start | rotatelogs $PGDATA/pglog 86400 2>1&'

Sure, our documentation specifically mentions using rotatelogs.

--
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

Re: [PERFORM] syslog slowing the database?

From
"scott.marlowe"
Date:
On Mon, 15 Mar 2004, Bruce Momjian wrote:

> scott.marlowe wrote:
> > On Thu, 11 Mar 2004, Christopher Kings-Lynne wrote:
> >
> > > > You could also consider not using syslog at all: let the postmaster
> > > > output to its stderr, and pipe that into a log-rotation program.
> > > > I believe some people use Apache's log rotator for this with good
> > > > results.
> > >
> > > Not an option I'm afraid.  PostgreSQL just jams and stops logging after
> > > the first rotation...
> > >
> > > I've read in the docs that syslog logging is the only "production"
> > > solution...
> >
> > Can you use the apache log rotator?  It's known to work in my environment
> > (redhat 7.2, postgresql 7.2 and 7.4) with this command to start it in my
> > rc.local file:
> >
> > su - postgres -c 'pg_ctl start | rotatelogs $PGDATA/pglog 86400 2>1&'
>
> Sure, our documentation specifically mentions using rotatelogs.


hehe.  What I meant was can Christopher use it, or does he have a
limitation in his environment where he can't get ahold of the apache log
rotater... :-)