Bug 445560 - GFS2: fstest using fsync() after each write much slower than open O_SYNC or using fdatasync()
GFS2: fstest using fsync() after each write much slower than open O_SYNC or u...
Status: CLOSED NOTABUG
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: kernel (Show other bugs)
5.3
All Linux
medium Severity medium
: rc
: ---
Assigned To: Steve Whitehouse
GFS Bugs
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-05-07 12:08 EDT by Scott Crenshaw
Modified: 2009-05-27 23:35 EDT (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-07-09 09:51:58 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
fstest - test program to simulate sync writes for messaging loads (7.12 KB, text/x-csrc)
2008-05-07 12:08 EDT, Rob Kenna
no flags Details
Updated version where -t 1 doesn't spin a thread so tracing is easier (7.32 KB, text/x-csrc)
2008-05-07 14:31 EDT, Rob Kenna
no flags Details

  None (edit)
Description Rob Kenna 2008-05-07 12:08:38 EDT
For some reason a call to fsync() after a write is appreciably slower than
either opening a file O_SYNC or using the fdatasync() call.  ext3 and gfs1 do
not exhibit this behavior.  GFS2 is actually slower than GFS1 in this case.

Use the following to reproduce
// "-S 1" means sync on every write.
// "-A" means buffered (i.e. not open O_SYNC)
fstest -b 1k -t 1 -s 30m -A -S 1 

Compare to 
fstest -b 1k -t 1 -s 30m -A -d // fdatasync()  or
fstest -b 1k -t 1 -s 30m       // open O_SYNC

fstest.c program attached.
Comment 1 Rob Kenna 2008-05-07 12:08:38 EDT
Created attachment 304777 [details]
fstest - test program to simulate sync writes for messaging loads
Comment 2 Rob Kenna 2008-05-07 14:29:18 EDT
Here's a trace of the program.  It has the expected pattern of calls

open("test.MRMmBj", O_WRONLY)           = 3
lseek(3, 0, SEEK_SET)                   = 0
time(NULL)                              = 1210184262
gettimeofday({1210184262, 558839}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fsync(3)                                = 0
gettimeofday({1210184262, 559377}, NULL) = 0
gettimeofday({1210184262, 559442}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fsync(3)                                = 0
gettimeofday({1210184262, 559984}, NULL) = 0
gettimeofday({1210184262, 560049}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fsync(3)                                = 0
gettimeofday({1210184262, 560987}, NULL) = 0
gettimeofday({1210184262, 561054}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fsync(3)                                = 0
gettimeofday({1210184262, 561822}, NULL) = 0
close(3)                                = 0


VERSUS using "-d" in the test program and getting fdatasync() calls.
open("test.fcYQV1", O_WRONLY)           = 3
lseek(3, 0, SEEK_SET)                   = 0
time(NULL)                              = 1210184897
gettimeofday({1210184897, 828763}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fdatasync(3)                            = 0
gettimeofday({1210184897, 829359}, NULL) = 0
gettimeofday({1210184897, 829426}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fdatasync(3)                            = 0
gettimeofday({1210184897, 829977}, NULL) = 0
gettimeofday({1210184897, 830057}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fdatasync(3)                            = 0
gettimeofday({1210184897, 830678}, NULL) = 0
gettimeofday({1210184897, 830743}, NULL) = 0
write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
1024) = 1024
fdatasync(3)                            = 0
gettimeofday({1210184897, 831429}, NULL) = 0
fsync(3)                                = 0
close(3)                                = 0
Comment 3 Rob Kenna 2008-05-07 14:31:51 EDT
Created attachment 304795 [details]
Updated version where -t 1 doesn't spin a thread so tracing is easier

This version won't spin a thread when "-t 1" is supplied.  This makes tracing
easier (using strace.)
Comment 4 Rob Kenna 2008-05-07 14:37:54 EDT
doing fsync() versus open O_SYNC is about 3-4 times slower (600-700 KBs vs. 2 MBs)
Comment 6 Steve Whitehouse 2008-07-02 11:19:01 EDT
Its not a great surprise that fsync() is slower than fdatasync() for GFS2. Also
I believe that O_SYNC is basically the same as fdatasync().

GFS1 is very similar to ext3. They both use the sync_inode method, now frowned
upon by upstream. The main difference between this and GFS2 is that in GFS2 we
sync the metadata even for I_DIRTY_SYNC, which I guess we could change, but
really I'm not sure its that much of a big deal. If someone has called fsync,
then I think we can reasonably assume that they want all data stable on disk,
even the minor inode changes. If they didn't, then they'd have called
fdatasync() instead.

So GFS2 does what the man page for fsync says, whereas GFS and ext3 ignore minor
changes (i.e. I_DIRTY_SYNC changes) which probably explains the difference in
performance.

So I don't think there is anything really to change at this stage, and I'm
intending to close this as NOTABUG shortly.

Note You need to log in before you can comment on or make changes to this bug.