Thread: syslog slowing the database?
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.
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
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
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 > >
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
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
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.
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
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;
}
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.
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
> 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
>>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
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)
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&'
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
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... :-)