[OpenAFS] Slow AFS performance
Jason Edgecombe
jason@rampaginggeek.com
Wed, 28 Nov 2007 11:40:28 -0500
chas williams - CONTRACTOR wrote:
> In message <474D78F2.40808@rampaginggeek.com>,Jason Edgecombe writes:
>
>> array
>>
>> My bonnie++ performance numbers for vicepa are here:
>> http://www.coe.uncc.edu/~jwedgeco/bonnie.html
>>
>>
>> What could AFS be doing that causes the performance to stink?
>>
>
> run strace on fileserver/volserver and see what its doing as far
> as i/o. as i recall, the fileserver doesnt always use the best
> size for getting performance but it could be another issue.
>
>
# truss -c -p 624 shows:
syscall seconds calls errors
read .054 1261
write .069 1258
close .016 1235
time .047 7468
fdsync .048 310
fcntl .009 622
lwp_park .017 1411 127
lwp_unpark .009 1190
mkdir .000 5 4
fchmod .002 311
fchown .004 311
yield .000 62
llseek .011 1555
fstat64 .006 604
open64 .060 1236 1
recvmsg .040 2133
sendmsg .065 2133
-------- ------ ----
sys totals: .465 23105 132
usr time: .157
elapsed: 16.030
A snippet of the long truss:
Base time stamp: 1196267406.3976 [ Wed Nov 28 11:30:06 EST 2007 ]
/5: 0.0520 fcntl(14, F_SETLK, 0xFED7B22C) = 0
/3: 0.0521 lwp_park(0xFEF7BE50, 0) Err#62 ETIME
/5: 0.0522 close(14) = 0
/5: 0.0525 open64("/vicepc/AFSIDat/g/g6==U/7/o2/8Ua++Eeq1",
O_RDWR|O_CREAT|O_TRUN
C|O_EXCL, 0) = 14
/5: 0.0527 fchown(14, 1, 0) = 0
/5: 0.0527 fchmod(14, 0) = 0
/5: 0.0528 close(14) = 0
/5: 0.0528 open64("/vicepc/AFSIDat/g/g6==U/7/o2/8Ua++Eeq1", O_RDWR)
= 14
/5: 0.0529 time() = 1196267406
/3: 0.0530 lwp_park(0xFEF7BE50, 0) = 0
/5: 0.0530 lwp_unpark(3, 1) = 0
/5: 0.0531 time() = 1196267406
/5: 0.0531 time() = 1196267406
/5: 0.0532 sendmsg(4, 0xFED7B258, 0) = 94
/2: 0.0532 recvmsg(4, 0xFF07BEAC, 0) = 94
/5: 0.0533 time() = 1196267406
/2: 0.0534 time() = 1196267406
/5: 0.0534 time() = 1196267406
/2: 0.0535 lwp_unpark(9, 1) = 0
/5: 0.0535 time() = 1196267406
/9: 0.0535 lwp_park(0x00000000, 0) = 0
/5: 0.0536 time() = 1196267406
/9: 0.0536 close(6) = 0
/2: 0.0537 recvmsg(4, 0xFF07BEAC, 0) = 91
/5: 0.0537 sendmsg(4, 0xFED7B258, 0) = 91
/2: 0.0538 time() = 1196267406
/5: 0.0539 time() = 1196267406
/9: 0.0538 open64("/vicepa/AFSIDat/g/g6==U/7/o2/CUa++Meq1", O_RDWR) = 6
/5: 0.0540 write(14, " G I F 8 9 a "01 &01F7\0".., 8192) = 8192
/9: 0.0541 fstat64(6, 0xFE97B8D8) = 0
/5: 0.0542 time() = 1196267406
/9: 0.0542 fstat64(6, 0xFE97B740) = 0
/5: 0.0542 time() = 1196267406
/5: 0.0543 time() = 1196267406
/5: 0.0543 sendmsg(4, 0xFED7B258, 0) = 88
/2: 0.0544 recvmsg(4, 0xFF07BEAC, 0) = 88
/5: 0.0544 time() = 1196267406
...snip...
/5: 0.1116 time() = 1196267406
/5: 0.1117 write(14, " G I F 8 9 aBD01 w01F7\0".., 8192) = 8192
/9: 0.1118 read(6, " G I F 8 9 a X\014\0F7\0".., 1351) = 1351
/5: 0.1118 time() = 1196267406
/9: 0.1119 close(6) = 0
/5: 0.1119 time() = 1196267406
/5: 0.1120 time() = 1196267406
/9: 0.1120 open64("/vicepa/AFSIDat/g/g6==U/7/o2/WUa+++fq1", O_RDWR) = 6
/5: 0.1121 sendmsg(4, 0xFED7B258, 0) = 88
/9: 0.1121 fstat64(6, 0xFE97B8D8) = 0
/2: 0.1121 recvmsg(4, 0xFF07BEAC, 0) = 88
/9: 0.1122 fstat64(6, 0xFE97B740) = 0
/5: 0.1122 time() = 1196267406
/2: 0.1123 time() = 1196267406
/5: 0.1124 time() = 1196267406
/5: 0.1125 time() = 1196267406
/9: 0.1125 read(6, " G I F 8 9 a d\0 <\0F7\0".., 1935) = 1935
/5: 0.1125 time() = 1196267406
/9: 0.1126 close(6) = 0
/2: 0.1127 recvmsg(4, 0xFF07BEAC, 0) = 85
/2: 0.1127 time() = 1196267406
/5: 0.1127 sendmsg(4, 0xFED7B258, 0) = 85
/9: 0.1127 open64("/vicepa/AFSIDat/g/g6==U/7/o2/YUa++2fq1", O_RDWR) = 6
/5: 0.1129 time() = 1196267406
/9: 0.1129 fstat64(6, 0xFE97B8D8) = 0
/9: 0.1129 fstat64(6, 0xFE97B740) = 0
/5: 0.1130 write(14, "06EA1BA8 oA0 >7FFA 4 jD4".., 8192) = 8192
/5: 0.1131 time() = 1196267406
/5: 0.1131 time() = 1196267406
/5: 0.1132 time() = 1196267406
/9: 0.1132 read(6, " G I F 8 9 a ~\0 <\0F7\0".., 2161) = 2161
/2: 0.1133 recvmsg(4, 0xFF07BEAC, 0) = 82
/5: 0.1132 sendmsg(4, 0xFED7B258, 0) = 82
/9: 0.1134 sendmsg(4, 0xFE97B448, 0) = 5688
/2: 0.1134 time() = 1196267406
/2: 0.1135 lwp_unpark(9, 1) = 0
/5: 0.1135 time() = 1196267406
...snip...
Any insights?
Thanks,
Jason