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