Hi,

I have a coda-server (Linux 2.0.34, coda 4.6.6), two clients cc1, cc2 (Linux
2.1.128, coda 4.6.6, kernel-module built from linux-coda-4.7.0.tgz) and a
problem with mv(1).

I did the following as admin-user (with tokens):

[admin_at_cc1 /coda/var]$ctokens

Token held by the Cache Manager:

Local uid: 500
Coda user id: 500
Expiration time: Sat Nov 28 12:06:30 1998   

[admin_at_cc2 /coda/var]$ctokens

Token held by the Cache Manager:

Local uid: 500
Coda user id: 500
Expiration time: Sat Nov 28 10:06:47 1998  


create file on cc1:

[admin_at_cc1 /coda/var]$touch test1/dummy  

move file to directory test2 (on cc2):

[admin_at_cc2 /coda/var]$time mv test1/dummy test2/
0.00user 0.01system 0:00.03elapsed 29%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (76major+8minor)pagefaults 0swaps  

move file to directory test1 (on cc1):

[admin_at_cc1 /coda/var]$mv test2/dummy test1/

stop venus on cc1:

[root_at_cc1 /]# /etc/rc.d/init.d/venus.init stop 


another move on cc2:

[admin_at_cc2 /coda/var]$time mv test1/dummy test2/
0.01user 0.00system 1:00.43elapsed 0%CPU (0avgtext+0avgdata 0maxresident)k
                    ^^^^^^^^^^^^^^
0inputs+0outputs (76major+8minor)pagefaults 0swaps


That's quite slow .... :-(   

Some lines from venus.log (vutil d 1):

[ W(15) : 0000 : 12:09:12 ] vproc::getattr: fid = (7f000003.5.10b)
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Getattr): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] fsobj::GetAttr: failed validation
[ W(15) : 0000 : 12:09:12 ] 	remote = [33 0 0 0 0 0 0 0] [4c36eb7 365e87cb] [0]
[ W(15) : 0000 : 12:09:12 ] 	local = [32 0 0 0 0 0 0 0] [4c368b7 365e8575] [0]
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Getattr): code = 157
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Getattr): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] fsobj::GetAttr: failed validation
[ W(15) : 0000 : 12:09:12 ] 	remote = [33 0 0 0 0 0 0 0] [4c36eb7 365e87cb] [0]
[ W(15) : 0000 : 12:09:12 ] 	local = [32 0 0 0 0 0 0 0] [4c368b7 365e8575] [0]
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Getattr): code = 0
[ W(15) : 0000 : 12:09:12 ] Getattr : returns SUCCESS, elapsed = 4.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::lookup: fid = (7f000003.1.1), name = test1, nc = 0
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Lookup): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 1.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Lookup): code = 0
[ W(15) : 0000 : 12:09:12 ] Lookup : returns SUCCESS, elapsed = 5.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::getattr: fid = (7f000003.3.10a)
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Getattr): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Getattr): code = 0
[ W(15) : 0000 : 12:09:12 ] Getattr : returns SUCCESS, elapsed = 0.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::access: fid = (7f000003.3.10a), mode = 01
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Access): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Access): code = 0
[ W(15) : 0000 : 12:09:12 ] Access : returns SUCCESS, elapsed = 0.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::lookup: fid = (7f000003.3.10a), name = dummy, nc = 0
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Lookup): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 1.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Lookup): code = 0
[ W(15) : 0000 : 12:09:12 ] Lookup : returns SUCCESS, elapsed = 12.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::getattr: fid = (7f000003.44.12a)
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Getattr): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Getattr): code = 0
[ W(15) : 0000 : 12:09:12 ] Getattr : returns SUCCESS, elapsed = 0.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::lookup: fid = (7f000003.5.10b), name = dummy, nc = 0
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Lookup): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Lookup): code = 2
[ W(15) : 0000 : 12:09:12 ] Lookup : returns No such file or directory, elapsed = 7.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::access: fid = (7f000003.3.10a), mode = 03
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Access): vid = 7f000003, u.u_vol = 0, mode = -1
[ W(15) : 0000 : 12:09:12 ] vproc::End_VFS(Access): code = 0
[ W(15) : 0000 : 12:09:12 ] Access : returns SUCCESS, elapsed = 0.0 msec
[ W(15) : 0000 : 12:09:12 ] vproc::rename: fid = (7f000003.3.10a), td_fid = (7f000003.5.10b), name = dummy, toname = dummy
[ W(15) : 0000 : 12:09:12 ] vproc::Begin_VFS(Rename): vid = 7f000003, u.u_vol = 0, mode = -1

[ D(02) : 0119 : 12:09:17 ] NotifyUserOfServerBandwidthEvent

[ F(06) : 0120 : 12:09:27 ] Transaction: elapsed = 0.0, delta_vm = 0

[ F(06) : 0123 : 12:09:42 ] Transaction: elapsed = 3.0, delta_vm = 0

[ T(01) : 0124 : 12:09:42 ] RecovFlush: count = 1, size = 24320, elapsed = 20.0, delta_vm = 0

[ F(06) : 0128 : 12:10:12 ] Transaction: elapsed = 0.0, delta_vm = 0

[ W(15) : 0000 : 12:10:12 ] *** Long Running (Multi)VRename: code = -2001, elapsed = 60105.0 ***
[ W(15) : 0000 : 12:10:12 ] Transaction: elapsed = 0.0, delta_vm = 0
[ W(15) : 0000 : 12:10:12 ] Transaction: elapsed = 1.0, delta_vm = 0
[ W(15) : 0000 : 12:10:12 ] Rename : returns SUCCESS, elapsed = -1631886080.0 msec
[ W(15) : 0000 : 12:10:12 ] vproc::End_VFS(Rename): code = 0
[ W(15) : 0000 : 12:10:12 ] [Return Done] Rename : returns SUCCESS, elapsed = 60109.0



What went wrong? What have I done wrong?



-MIC

p.s: I found "[ H(07) : 0003 : 12:15:38 ] Tally for vuid=-1:" somewhere
else in the log-file. What does this mean? Is is related to the problem?