[OpenAFS-devel] Bug with OpenAFS memory-mapped file I/O under Linux
Nickolai Zeldovich
kolya@MIT.EDU
Mon, 21 Jan 2002 12:16:52 -0500
> any chance you could do a 'fstrace setset -active', run your test code,
> 'fstrace dump' and send the result output? that would be somewhat
> useful.
I've also managed to reproduce the failure on my Linux box, with a
somewhat more compact test case, included below. Here's the fstrace
output from running it. After looking a bit at the Linux afs and vm
code, perhaps we should call filemap_fdatasync() somewhere to get the
data from pages into dcache's?
-- kolya
AFS Trace Dump -
Date: Mon Jan 21 13:08:44 2002
Found 1 logs.
Contents of log cmfx:
time 293.870825, pid 0: Mon Jan 21 13:08:37 2002
time 293.870825, pid 32744: Access vp 0xf89b88b0 mode 0x40 len (0x0, 0x800)
time 293.870825, pid 32744: Access vp 0xf89b88b0 mode 0x40 len (0x0, 0x800)
time 293.870825, pid 32744: GetdCache vp 0xf89b88b0 dcache 0xf89d1e8c dcache low-version 0x27, vcache low-version 0x27
time 293.870825, pid 32744: GetdCache tlen 0x800 flags 0x1 abyte (0x0, 0x0) Position (0x0, 0x0)
time 293.870825, pid 32744: Lookup adp 0xf89b88b0 name testf fid (257:537064976.2148.276115), code=0
time 293.870825, pid 32744: Access vp 0xf89aafb0 mode 0x180 len (0x0, 0x8)
time 293.870825, pid 32744: Setattr vp 0xf89aafb0 len (0x0, 0x8)
time 293.870825, pid 32744: TruncAll vp 0xf89aafb0 old len (0x0, 0x8) new len (0x0, 0x0)
time 293.870825, pid 32744: StoreAll vp 0xf89aafb0 len (0x0, 0x0)
time 293.870825, pid 32744: storemini vp 0xf89aafb0 length 0x0
time 293.870825, pid 32744: StoreData64: fid (537064976:2148.276115.0) offs (0x0, 0x0) len (0x0, 0x0) file length (0x0, 0x0)
time 293.920825, pid 32744: Analyze RPC op 3 conn 0xc887aca0 code 0x0 user 0x0
time 293.920825, pid 32744: StoreAll Done vp 0xf89aafb0 length 0x0 (returns 0x0)
time 293.920825, pid 32744: Vnode Lock vp 0xf89aafb0 wait 0x0 excl 0x2
time 293.920825, pid 32744: Vnode Lock vp 0xf89aafb0 wait 0x0 readers 0 waiters 0
time 293.920825, pid 32744: RXAFS_StoreStatus vp 0xf89aafb0 len (0x0, 0x0)
time 293.930825, pid 32744: Analyze RPC op 5 conn 0xc887aca0 code 0x0 user 0x0
time 293.930825, pid 32744: SimpleVStat vp 0xf89aafb0 old len (0x0, 0x0) new len (0x0, 0x0)
time 293.930825, pid 32744: Open 0xf89aafb0 flags 0x242
time 293.930825, pid 32744: Open 0xf89aafb0 flags 0xf423f
time 293.930825, pid 32744: Iwrite ip 0xf89aafb0 pos (0x0, 0x0) count 0x8 code 1869f
time 293.930825, pid 32744: Iupdatepage ip 0xf89aafb0 pp 0xc11434d8 count 0x2 code 99999
time 293.930825, pid 32744: Write vp 0xf89aafb0 off (0x0, 0x0) resid (0x0, 0x8) file length (0x0, 0x0)
time 293.930825, pid 32744: ../afs/afs_vnop_write.c line 605: m.Length was (0x0, 0x0), now (0x0, 0x8)
time 293.930825, pid 32744: Iupdatepage ip 0xf89aafb0 pp 0xc11434d8 count 0x2 code 8
time 293.930825, pid 32744: Iwrite ip 0xf89aafb0 pos (0x0, 0x8) count 0x8 code 8
time 293.930825, pid 32744: Gn_map vp 0xf89aafb0 addr 0x40018000 len 0x1000 off 0x0
time 293.930825, pid 32744: Ireadpage ip 0xf89aafb0 pp 0xc11434d8 count 0x2 code 1869f
time 293.930825, pid 32744: Read vp 0xf89aafb0 off (0x0, 0x0) resid 0x1000 file length (0x0, 0x8)
time 293.930825, pid 32744: UFSRead: tdc 0xf89d1568, offset (0x0, 0x0) len (0x0 0x8)
time 293.930825, pid 32744: Ireadpage ip 0xf89aafb0 pp 0xc11434d8 count 0x2 code 0
time 293.930825, pid 32744: VMclose ip 0xf89aafb0 mapcnt 1 opens 2 XoW 2
time 293.930825, pid 32744: Close 0xf89aafb0 flags 0x2
time 293.930825, pid 32744: Wapeup: evp 0xc9277ce0, evp->seq 0x8c
time 293.930825, pid 32744: Sleep: evp 0xc9277ee0, count 0 seq 0x9 evp->seq 0x9
time 293.930825, pid 8758: Bkg daemon executing 0x2 request
time 293.930825, pid 8758: StoreAll vp 0xf89aafb0 len (0x0, 0x8)
time 293.930825, pid 8758: StoreData64: fid (537064976:2148.276115.8) offs (0x0, 0x0) len (0x0, 0x8) file length (0x0, 0x8)
time 293.930825, pid 8758: StoreAll 2 vp 0xf89aafb0 chunk 0x0 index 10551 inode 3189433
time 293.930825, pid 8758: StoreProc vp 0xf89aafb0 fid (101:537064976.2148.276115) m.Length (0x0, 0x8) alen 0x8
time 293.930825, pid 8758: StoreProc got 0x8
time 293.930825, pid 8758: StoreProc vp 0xf89aafb0 fid (101:537064976.2148.276115) m.Length (0x0, 0x8) alen 0x0
time 293.930825, pid 8759: Sleep: evp 0xc9277ce0, count 0 seq 0x8c evp->seq 0x8c
time 293.930825, pid 8758: Analyze RPC op 3 conn 0xc887aca0 code 0x0 user 0x0
time 293.930825, pid 8758: StoreAllDCache Done for vp 0xf89aafb0 (returns 0x0)
time 293.930825, pid 8758: StoreAll Done vp 0xf89aafb0 length 0x8 (returns 0x0)
time 293.930825, pid 8758: Vnode Lock vp 0xf89aafb0 wait 0x0 excl 0x2
time 293.930825, pid 8758: Vnode Lock vp 0xf89aafb0 wait 0x0 readers 0 waiters 0
time 293.930825, pid 8758: Wapeup: evp 0xc9277ee0, evp->seq 0xa
time 293.930825, pid 8758: Sleep: evp 0xc9277ce0, count 0 seq 0x8c evp->seq 0x8c
time 293.930825, pid 32744: Close 0xf89aafb0 flags 0x2
time 293.930825, pid 32744: Wapeup: evp 0xc9277ce0, evp->seq 0x8d
time 293.930825, pid 32744: Sleep: evp 0xc9277ee0, count 0 seq 0xa evp->seq 0xa
time 293.930825, pid 8759: Bkg daemon executing 0x2 request
time 293.930825, pid 8759: StoreAll vp 0xf89aafb0 len (0x0, 0x8)
time 293.930825, pid 8759: StoreAll Done vp 0xf89aafb0 length 0x8 (returns 0x0)
time 293.930825, pid 8759: Vnode Lock vp 0xf89aafb0 wait 0x0 excl 0x2
time 293.930825, pid 8759: Vnode Lock vp 0xf89aafb0 wait 0x0 readers 0 waiters 0
time 293.930825, pid 8759: Wapeup: evp 0xc9277ee0, evp->seq 0xb
time 293.930825, pid 8759: Sleep: evp 0xc9277ce0, count 0 seq 0x8d evp->seq 0x8d
time 293.930825, pid 8758: Sleep: evp 0xc9277ce0, count 0 seq 0x8d evp->seq 0x8d
AFS Trace Dump - Completed
Test case:
#include <stdio.h>
#include <stdlib.h>
#include <fcntl.h>
#include <sys/mman.h>
#define SZ 8
int main(int argc, char **argv)
{
void *pa;
int output_fd;
FILE *fp;
char *nm = argv[1];
char *buf = (char*)malloc(SZ);
unsigned long *bp;
memset(buf, 0xaa, SZ);
output_fd = open(nm, O_RDWR | O_CREAT | O_TRUNC, 0666);
if (output_fd < 0) {
perror("open");
exit(-1);
}
if (write(output_fd, buf, SZ) < 0) {
perror("write");
exit(-2);
}
pa = mmap(NULL, SZ, PROT_READ | PROT_WRITE, MAP_SHARED, output_fd, 0);
if ((long)pa == -1L) {
perror("mmap");
exit(-5);
}
bp = (unsigned long*)pa;
*bp++ = 0x55555555;
if (munmap(pa, SZ) == -1) {
perror("munmap");
exit(-6);
}
if (close(output_fd) < 0) {
perror("close");
exit(-1);
}
}