Subject: Re: kern/28472: NFS client gets atime wrong
To: YAMAMOTO Takashi <yamt@mwd.biglobe.ne.jp>
From: Brian Marcotte <marcotte@panix.com>
List: netbsd-bugs
Date: 12/08/2004 22:09:05
> > Example where atime is updated when it shouldn't be.
> > This is similar to when mail is delivered to a mailbox.
>
> i guess it's due to (superfluous?) cache invalidation due to IO_APPEND.
It's worse than I thought. We were having a problem where procmail log
files would sometimes contain a string of nulls between the entries.
When trying to debug this, I found that NetBSD 2.0 is reading the ENTIRE
file and then writing the last bit of data. In fact, it is not just
writing the data which is to be appended to the file, it is writing the
entire final block (4k blocks).
My test program does this:
Spawns 20 children
Each child does this 20 times:
open "logfile" for append
write a message of about 200 characters
close the file
Here is a summary of the packet trace:
WRITE Call Offset:0 Len:212
READ Call Offset:0 Len:212
WRITE Call Offset:0 Len:425
READ Call Offset:0 Len:425
WRITE Call Offset:0 Len:637
READ Call Offset:0 Len:637
WRITE Call Offset:0 Len:850
READ Call Offset:0 Len:850
WRITE Call Offset:0 Len:1063
READ Call Offset:0 Len:1063
WRITE Call Offset:0 Len:1276
READ Call Offset:0 Len:1276
WRITE Call Offset:0 Len:1489
.
.
.
WRITE Call Offset:0 Len:4252
READ Call Offset:0 Len:4252
WRITE Call Offset:4096 Len:368
READ Call Offset:0 Len:4464
WRITE Call Offset:4096 Len:581
READ Call Offset:0 Len:4677
WRITE Call Offset:4096 Len:793
READ Call Offset:0 Len:4889
WRITE Call Offset:4096 Len:1006
READ Call Offset:0 Len:5102
WRITE Call Offset:4096 Len:1219
READ Call Offset:0 Len:5315
WRITE Call Offset:4096 Len:1432
.
.
.
WRITE Call Offset:12288 Len:1531
READ Call Offset:0 Len:13819
WRITE Call Offset:12288 Len:1744
READ Call Offset:0 Len:14032
WRITE Call Offset:12288 Len:1957
READ Call Offset:0 Len:14245
WRITE Call Offset:12288 Len:2170
READ Call Offset:0 Len:14458
WRITE Call Offset:12288 Len:2382
READ Call Offset:0 Len:14670
WRITE Call Offset:12288 Len:2595
READ Call Offset:0 Len:14883
WRITE Call Offset:12288 Len:2807
READ Call Offset:0 Len:15095
WRITE Call Offset:12288 Len:3020
As you can see, the write call is always from the last 4k boundary to
the end of file, and before the next write does a read of the entire file.
This is (obviously) bad because:
1. It updates the atime when it shouldn't
2. It's causing strings of nulls in log files (multiple clients only)
3. It makes for really bad performance.
The complete packet dump can be retrieved here:
http://www.panix.com/~marcotte/append.pcap
The test program is here:
http://www.panix.com/~marcotte/appendtest.pl
Under NetBSD 1.5, there are just WRITE calls with no READ calls. 1.5 also
only writes the data which is to be appended, not the entire last block.
--
- Brian