Date: Thu, 10 Nov 2005 15:25:35 +0100
From: "Steinar H. Gunderson" <sgunderson@bigfoot.com>
To: pgsql-performance@postgresql.org
Subject: Re: WAL sync behaviour
Message-ID: <20051110142535.GA4530@uio.no>
Mail-Followup-To: pgsql-performance@postgresql.org
References: <20051110133241.GA4031@uio.no> <437355C6.4030604@archonet.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
In-Reply-To: <437355C6.4030604@archonet.com>
User-Agent: Mutt/1.5.11

On Thu, Nov 10, 2005 at 02:14:30PM +0000, Richard Huxton wrote:
> You're beyond my area of expertise, but I do know that someone's going 
> to ask what filesystem this is (ext2/xfs/etc).

Ah, yes, I forgot -- it's ext3. We're considering simply moving the WAL onto
a separate partition (with data=writeback and noatime) if that can help us
any.

> And probably to see the strace too.

The strace with wal_sync_method = fdatasync goes like this (I attach just
before I do the commit):

cirkus:~> sudo strace -T -p 15718               
Process 15718 attached - interrupt to quit
read(8, "\27\3\1\0 ", 5)                = 5 <2.635856>
read(8, "\336\333\24KB\325Ga\324\264[\307v\254h\254\350\20\220a"..., 32) = 32 <0.000031>
read(8, "\27\3\1\0000", 5)              = 5 <0.000027>
read(8, "$E\217<z\350bI\2217\317\3662\301\273\233\17\177\256\225"..., 48) = 48 <0.000026>
send(7, "\3\0\0\0\30\0\0\0\20\0\0\0f=\0\0commit;\0", 24, 0) = 24 <0.000071>
gettimeofday({1131632603, 187599}, NULL) = 0 <0.000026>
time(NULL)                              = 1131632603 <0.000027>
open("pg_xlog/0000000100000000000000A2", O_RDWR|O_LARGEFILE) = 14 <0.000039>
_llseek(14, 12500992, [12500992], SEEK_SET) = 0 <0.000026>
write(14, "]\320\1\0\1\0\0\0\0\0\0\0\0\300\276\242\362\0\0\0\31\0"..., 8192) = 8192 <0.000057>
fdatasync(14)                           = 0 <0.260194>
gettimeofday({1131632603, 448459}, NULL) = 0 <0.000034>
time(NULL)                              = 1131632603 <0.000027>
time([1131632603])                      = 1131632603 <0.000025>
getpid()                                = 15718 <0.000025>
rt_sigaction(SIGPIPE, {0x558a27e0, [], 0}, {SIG_IGN}, 8) = 0 <0.000029>
send(3, "<134>Nov 10 15:23:23 postgres[15"..., 121, 0) = 121 <0.000032>
rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0 <0.000029>
send(7, "\4\0\0\0\330\3\0\0\20\0\0\0f=\0\0\247@\0\0\16\0\0\0\1\0"..., 984, 0) = 984 <0.000076>
send(7, "\4\0\0\0\330\3\0\0\20\0\0\0f=\0\0\247@\0\0\16\0\0\0\0\0"..., 984, 0) = 984 <0.000051>
send(7, "\4\0\0\0\330\3\0\0\20\0\0\0f=\0\0\247@\0\0\16\0\0\0\0\0"..., 984, 0) = 984 <0.000050>
send(7, "\4\0\0\0\250\0\0\0\20\0\0\0f=\0\0\247@\0\0\2\0\0\0\0\0"..., 168, 0) = 168 <0.000050>
send(7, "\4\0\0\0\250\0\0\0\20\0\0\0f=\0\0\0\0\0\0\2\0\0\0\0\0\0"..., 168, 0) = 168 <0.000049>
send(7, "\3\0\0\0\27\0\0\0\20\0\0\0f=\0\0<IDLE>\0", 23, 0) = 23 <0.000047>
write(8, "\27\3\1\0 B\260\253rq)\232\265o\225\272\235\v\375\31\323"..., 90) = 90 <0.000229>
read(8,  <unfinished ...>
Process 15718 detached

> Do vmstat/iostat show any unusual activity?

No, there's not much activity. In fact, it's close to idle.

> Are your system logs on these disks too?

Yes, they are, but nothing much is logged, really -- and sync is off for most
of the logs in syslogd.
 
> Could it be the journalling on the fs clashing with the WAL?

Unsure -- that's what I was hoping to get some information on :-)

/* Steinar */
-- 
Homepage: http://www.sesse.net/