Re: WAL sync behaviour

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(at)\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(at)\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(at)\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(at)\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/