[OpenAFS] Re: HPUX client hanging

Wed, 11 Aug 2004 09:30:14 -0400

Derrick J Brashear wrote:

> fstrace setset cm -active
> (wait some time)
> fstrace dump cm

OK, here's what I did:

set -x
fstrace setset cm -active
sleep 5
/usr/local/bin/vim & # this is the hanging executable
echo $! # to identify the process
sleep 30
fstrace dump cm >/home/project-releases/tmp/temp.trace 2>&1
fstrace setset cm -inactive

The background process is ksh (it never becomes vim).  Using "tusc" to
trace the ksh system calls, it looks like it is execve() that is hanging.

Curiously, I can read the file in question without problems -- it's executing
the file that has a problem.

By the way, the machine has 4 processors, if it matters.

Looking in the log file, here is what I see, starting with the pid
of the background ksh process:

...

time 816.110561, pid 25858: vfs root vp 0xa400000, code 0
time 816.110562, pid 25858: Lookup adp 0xa400270 name hp_ux110 fid (1:536870968.26.10015), code=0
time 816.110563, pid 25858: Mount point is to vp 0xa4003a8 fid (1:536870968.26.10015)
time 816.110564, pid 25858: Lookup adp 0xa4031f8 name vim fid (1:536875088.1084.22610), code=0
time 816.110565, pid 25858: Open 0xa590350 flags 0x0
time 816.110566, pid 25858: Open 0xa590350 flags 0xf423f

# that's all there is for pid 25858...

time 819.180575, pid 25854: Getattr vp 0xa43ded8 len 0x165000
time 820.360580, pid 25760: vfs root vp 0xa400000, code 0
time 820.360581, pid 25760: readlink 0xa51bd10
time 820.360582, pid 25760: Getattr vp 0xa60a150 len 0x603e
time 820.360583, pid 25760: vfs root vp 0xa400000, code 0
time 820.360584, pid 25760: readlink 0xa51bd10
time 820.360585, pid 25760: Getattr vp 0xa60a150 len 0x603e
time 820.360586, pid 25863: vfs root vp 0xa400000, code 0
time 820.360587, pid 25863: readlink 0xa6be888
time 820.360588, pid 25863: vfs root vp 0xa400000, code 0
time 820.360589, pid 25863: readlink 0xa51bd10
time 820.360590, pid 25863: Open 0xa60a150 flags 0x0
time 820.360591, pid 25863: Open 0xa60a150 flags 0xf423f
time 820.360592, pid 25863: Getattr vp 0xa60a150 len 0x603e
time 820.360593, pid 25863: Access vp 0xa60a150 mode 0x40 len 0x603e
time 820.360594, pid 25863: Getattr vp 0xa60a150 len 0x603e
time 820.360595, pid 25863: Read vp 0xa60a150 off 0x0 resid 0x88 file length 0x603e
time 820.360597, pid 25863: Read vp 0xa60a150 off 0x80 resid 0x30 file length 0x603e
time 820.360599, pid 25863: Read vp 0xa60a150 off 0xb0 resid 0xc file length 0x603e
time 820.360601, pid 25863: Close 0xa60a150 flags 0x0
time 820.360602, pid 25863: Getattr vp 0xa60a150 len 0x603e
time 820.360603, pid 25863: Getattr vp 0xa60a150 len 0x603e
time 820.360604, pid 25863: Getattr vp 0xa60a150 len 0x603e
time 820.360605, pid 25863: vfs root vp 0xa400000, code 0
time 820.360606, pid 25863: readlink 0xa6be888
time 820.360607, pid 25863: Lookup adp 0xa6af738 name libc.1 fid (1:536871260.13.1090524935), code=2
time 820.360608, pid 25863: Returning code 2 from 19
time 820.370580, pid 25863: vfs root vp 0xa400000, code 0
time 820.370581, pid 25863: readlink 0xa6be888
time 820.370582, pid 25863: Lookup adp 0xa6af738 name libdld.1 fid (1:536871260.13.1090524935), code=2
time 820.370583, pid 25863: Returning code 2 from 19
time 820.370584, pid 25863: vfs root vp 0xa400000, code 0
time 820.370585, pid 25863: readlink 0xa6be888
time 820.370586, pid 25863: Lookup adp 0xa6af738 name libast.0 fid (1:536871260.13.1090524935), code=2
time 820.370587, pid 25863: Returning code 2 from 19
time 820.370588, pid 25863: vfs root vp 0xa400000, code 0
time 820.370589, pid 25863: readlink 0xa6be888
time 820.370590, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370591, pid 25863: vfs root vp 0xa400000, code 0
time 820.370592, pid 25863: readlink 0xa6be888
time 820.370593, pid 25863: Access vp 0xa53f020 mode 0x100 len 0xb197a
time 820.370594, pid 25863: Open 0xa53f020 flags 0x1
time 820.370595, pid 25863: Open 0xa53f020 flags 0xf423f
time 820.370596, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370597, pid 25863: Read vp 0xa53f020 off 0x0 resid 0x80 file length 0xb197a
time 820.370598, pid 25863: GetdCache vp 0xa53f020 dcache 0xa8929a8 dcache low-version 0x1, vcache low-version 0x1
time 820.370600, pid 25863: Read vp 0xa53f020 off 0x80 resid 0x30 file length 0xb197a
time 820.370602, pid 25863: Read vp 0xa53f020 off 0xb0 resid 0xc file length 0xb197a
time 820.370604, pid 25863: Read vp 0xa53f020 off 0x24000 resid 0x70 file length 0xb197a
time 820.370605, pid 25863: GetdCache vp 0xa53f020 dcache 0xa8947bc dcache low-version 0x1, vcache low-version 0x1
time 820.370607, pid 25863: Access vp 0xa53f020 mode 0x40 len 0xb197a
time 820.370608, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370609, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370610, pid 25863: Close 0xa53f020 flags 0x1
time 820.370611, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370612, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370613, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370614, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370615, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370616, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.370617, pid 25863: Getattr vp 0xa53f020 len 0xb197a
time 820.410581, pid 25865: vfs root vp 0xa400000, code 0
time 820.410582, pid 25865: readlink 0xa51bd10
time 820.410583, pid 25865: Getattr vp 0xa6cd3c0 len 0x5033
time 820.410584, pid 25865: vfs root vp 0xa400000, code 0
time 820.410585, pid 25865: readlink 0xa51bd10
time 820.410586, pid 25865: Open 0xa6cd3c0 flags 0x0
time 820.410587, pid 25865: Open 0xa6cd3c0 flags 0xf423f
time 820.410588, pid 25865: Getattr vp 0xa6cd3c0 len 0x5033
time 820.410589, pid 25865: Access vp 0xa6cd3c0 mode 0x40 len 0x5033
time 820.410590, pid 25865: Getattr vp 0xa6cd3c0 len 0x5033
time 820.410591, pid 25865: Read vp 0xa6cd3c0 off 0x0 resid 0x88 file length 0x5033
time 820.410593, pid 25865: Read vp 0xa6cd3c0 off 0x80 resid 0x30 file length 0x5033
time 820.410595, pid 25865: Read vp 0xa6cd3c0 off 0xb0 resid 0xc file length 0x5033
time 820.420580, pid 25865: Getattr vp 0xa6cd3c0 len 0x5033
time 820.420581, pid 25865: Close 0xa6cd3c0 flags 0x0
time 820.420582, pid 25865: Getattr vp 0xa6cd3c0 len 0x5033
time 820.420583, pid 25865: Getattr vp 0xa6cd3c0 len 0x5033
time 820.420584, pid 25865: vfs root vp 0xa400000, code 0
time 820.420585, pid 25865: readlink 0xa6be888
time 820.420586, pid 25865: Lookup adp 0xa6af738 name libc.1 fid (1:536871260.13.1090524935), code=2
time 820.420587, pid 25865: Returning code 2 from 19
time 820.420588, pid 25865: vfs root vp 0xa400000, code 0
time 820.420589, pid 25865: readlink 0xa6be888
time 820.420590, pid 25865: Lookup adp 0xa6af738 name libdld.1 fid (1:536871260.13.1090524935), code=2
time 820.420591, pid 25865: Returning code 2 from 19
time 820.420592, pid 25865: vfs root vp 0xa400000, code 0
time 820.420593, pid 25865: readlink 0xa6be888
time 820.420594, pid 25865: Lookup adp 0xa6af738 name libast.0 fid (1:536871260.13.1090524935), code=2
time 820.420595, pid 25865: Returning code 2 from 19
time 820.420596, pid 25865: vfs root vp 0xa400000, code 0
time 820.420597, pid 25865: readlink 0xa6be888
time 820.420598, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.420599, pid 25865: vfs root vp 0xa400000, code 0
time 820.420600, pid 25865: readlink 0xa6be888
time 820.420601, pid 25865: Access vp 0xa53f020 mode 0x100 len 0xb197a
time 820.420602, pid 25865: Open 0xa53f020 flags 0x1
time 820.420603, pid 25865: Open 0xa53f020 flags 0xf423f
time 820.420604, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.420605, pid 25865: Read vp 0xa53f020 off 0x0 resid 0x80 file length 0xb197a
time 820.420606, pid 25865: GetdCache vp 0xa53f020 dcache 0xa8929a8 dcache low-version 0x1, vcache low-version 0x1
time 820.420608, pid 25865: Read vp 0xa53f020 off 0x80 resid 0x30 file length 0xb197a
time 820.420610, pid 25865: Read vp 0xa53f020 off 0xb0 resid 0xc file length 0xb197a
time 820.420612, pid 25865: Read vp 0xa53f020 off 0x24000 resid 0x70 file length 0xb197a
time 820.420613, pid 25865: GetdCache vp 0xa53f020 dcache 0xa8947bc dcache low-version 0x1, vcache low-version 0x1
time 820.420615, pid 25865: Access vp 0xa53f020 mode 0x40 len 0xb197a
time 820.420616, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.420617, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.420618, pid 25865: Close 0xa53f020 flags 0x1
time 820.420619, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.420620, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.420621, pid 25865: vfs root vp 0xa400000, code 0
time 820.420622, pid 25865: readlink 0xa6be888
time 820.420623, pid 25865: Lookup adp 0xa6af738 name libcmd.0 fid (1:536871260.13.1090524935), code=2
time 820.420624, pid 25865: Returning code 2 from 19
time 820.420625, pid 25865: vfs root vp 0xa400000, code 0
time 820.420626, pid 25865: readlink 0xa6be888
time 820.420627, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420628, pid 25865: vfs root vp 0xa400000, code 0
time 820.420629, pid 25865: readlink 0xa6be888
time 820.420630, pid 25865: Access vp 0xa677ec0 mode 0x100 len 0x1c0fc
time 820.420631, pid 25865: Open 0xa677ec0 flags 0x1
time 820.420632, pid 25865: Open 0xa677ec0 flags 0xf423f
time 820.420633, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420634, pid 25865: Read vp 0xa677ec0 off 0x0 resid 0x80 file length 0x1c0fc
time 820.420636, pid 25865: Read vp 0xa677ec0 off 0x80 resid 0x30 file length 0x1c0fc
time 820.420638, pid 25865: Read vp 0xa677ec0 off 0xb0 resid 0xc file length 0x1c0fc
time 820.420640, pid 25865: Read vp 0xa677ec0 off 0x7000 resid 0x70 file length 0x1c0fc
time 820.420642, pid 25865: Access vp 0xa677ec0 mode 0x40 len 0x1c0fc
time 820.420643, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420644, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420645, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420646, pid 25865: Close 0xa677ec0 flags 0x1
time 820.420647, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420648, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420649, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.420650, pid 25865: vfs root vp 0xa400000, code 0
time 820.420651, pid 25865: readlink 0xa6be888
time 820.420652, pid 25865: Lookup adp 0xa6af738 name libM.1 fid (1:536871260.13.1090524935), code=2
time 820.420653, pid 25865: Returning code 2 from 19
time 820.420654, pid 25865: vfs root vp 0xa400000, code 0
time 820.420655, pid 25865: readlink 0xa6be888
time 820.420656, pid 25865: Lookup adp 0xa6af738 name libast.0 fid (1:536871260.13.1090524935), code=2
time 820.420657, pid 25865: Returning code 2 from 19
time 820.420658, pid 25865: vfs root vp 0xa400000, code 0
time 820.420659, pid 25865: readlink 0xa6be888
time 820.420660, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.430580, pid 25865: vfs root vp 0xa400000, code 0
time 820.430581, pid 25865: readlink 0xa6be888
time 820.430582, pid 25865: Access vp 0xa53f020 mode 0x100 len 0xb197a
time 820.430583, pid 25865: Open 0xa53f020 flags 0x1
time 820.430584, pid 25865: Open 0xa53f020 flags 0xf423f
time 820.430585, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.430586, pid 25865: Close 0xa53f020 flags 0x1
time 820.430587, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.430588, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.430589, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.430590, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.430591, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.430592, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.430593, pid 25865: Getattr vp 0xa677ec0 len 0x1c0fc
time 820.430594, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.430595, pid 25865: Getattr vp 0xa53f020 len 0xb197a
time 820.650580, pid 25867: vfs root vp 0xa400000, code 0
time 820.650581, pid 25867: readlink 0xa6be888
time 820.650582, pid 25867: Lookup adp 0xa6af738 name libc.2 fid (1:536871260.13.1090524935), code=2
time 820.650583, pid 25867: Returning code 2 from 19
time 820.650584, pid 25867: vfs root vp 0xa400000, code 0
time 820.650585, pid 25867: readlink 0xa6be888
time 820.650586, pid 25867: Lookup adp 0xa6af738 name libdld.2 fid (1:536871260.13.1090524935), code=2
time 820.650587, pid 25867: Returning code 2 from 19
time 820.650588, pid 25867: vfs root vp 0xa400000, code 0
time 820.650589, pid 25867: readlink 0xa6be888
time 820.650590, pid 25867: Lookup adp 0xa6af738 name libc.2 fid (1:536871260.13.1090524935), code=2
time 820.650591, pid 25867: Returning code 2 from 19
time 820.650592, pid 25867: vfs root vp 0xa400000, code 0
time 820.650593, pid 25867: readlink 0xa6be888
time 820.650594, pid 25867: Lookup adp 0xa6af738 name libdld.2 fid (1:536871260.13.1090524935), code=2
time 820.650595, pid 25867: Returning code 2 from 19
time 820.650596, pid 25867: vfs root vp 0xa400000, code 0
time 820.650597, pid 25867: readlink 0xa6be888
time 820.650598, pid 25867: Lookup adp 0xa6af738 name libjvm.0 fid (1:536871260.13.1090524935), code=2
time 820.650599, pid 25867: Returning code 2 from 19
time 820.680580, pid 25867: vfs root vp 0xa400000, code 0
time 820.680581, pid 25867: readlink 0xa6be888
time 820.680582, pid 25867: Lookup adp 0xa6af738 name libCsup.2 fid (1:536871260.13.1090524935), code=2
time 820.680583, pid 25867: Returning code 2 from 19
time 820.680584, pid 25867: vfs root vp 0xa400000, code 0
time 820.680585, pid 25867: readlink 0xa6be888
time 820.680586, pid 25867: Lookup adp 0xa6af738 name libcl.2 fid (1:536871260.13.1090524935), code=2
time 820.680587, pid 25867: Returning code 2 from 19
time 820.680588, pid 25867: vfs root vp 0xa400000, code 0
time 820.680589, pid 25867: readlink 0xa6be888
time 820.680590, pid 25867: Lookup adp 0xa6af738 name libisamstub.1 fid (1:536871260.13.1090524935), code=2
time 820.680591, pid 25867: Returning code 2 from 19
time 820.680592, pid 25867: vfs root vp 0xa400000, code 0
time 820.680593, pid 25867: readlink 0xa6be888
time 820.680594, pid 25867: Lookup adp 0xa6af738 name libdld.2 fid (1:536871260.13.1090524935), code=2
time 820.680595, pid 25867: Returning code 2 from 19
time 820.680596, pid 25867: vfs root vp 0xa400000, code 0
time 820.680597, pid 25867: readlink 0xa6be888
time 820.680598, pid 25867: Lookup adp 0xa6af738 name libm.2 fid (1:536871260.13.1090524935), code=2
time 820.680599, pid 25867: Returning code 2 from 19
time 820.680600, pid 25867: vfs root vp 0xa400000, code 0
time 820.680601, pid 25867: readlink 0xa6be888
time 820.680602, pid 25867: Lookup adp 0xa6af738 name libdld.2 fid (1:536871260.13.1090524935), code=2
time 820.680603, pid 25867: Returning code 2 from 19
time 820.680604, pid 25867: vfs root vp 0xa400000, code 0
time 820.680605, pid 25867: readlink 0xa6be888
time 820.680606, pid 25867: Lookup adp 0xa6af738 name libpthread.1 fid (1:536871260.13.1090524935), code=2
time 820.680607, pid 25867: Returning code 2 from 19
time 820.680608, pid 25867: vfs root vp 0xa400000, code 0
time 820.680609, pid 25867: readlink 0xa6be888
time 820.680610, pid 25867: Lookup adp 0xa6af738 name libpthread.1 fid (1:536871260.13.1090524935), code=2
time 820.680611, pid 25867: Returning code 2 from 19
time 820.750586, pid 25867: vfs root vp 0xa400000, code 0
time 820.750587, pid 25867: readlink 0xa6be888
time 820.750588, pid 25867: Lookup adp 0xa6af738 name libdld.2 fid (1:536871260.13.1090524935), code=2
time 820.750589, pid 25867: Returning code 2 from 19
time 820.750590, pid 25867: vfs root vp 0xa400000, code 0
time 820.750591, pid 25867: readlink 0xa6be888
time 820.750592, pid 25867: Lookup adp 0xa6af738 name libm.2 fid (1:536871260.13.1090524935), code=2
time 820.750593, pid 25867: Returning code 2 from 19
time 820.760586, pid 25867: vfs root vp 0xa400000, code 0
time 820.760587, pid 25867: readlink 0xa6be888
time 820.760588, pid 25867: Lookup adp 0xa6af738 name libdld.2 fid (1:536871260.13.1090524935), code=2
time 820.760589, pid 25867: Returning code 2 from 19
time 820.760590, pid 25867: vfs root vp 0xa400000, code 0
time 820.760591, pid 25867: readlink 0xa6be888
time 820.760592, pid 25867: Lookup adp 0xa6af738 name libjvm.0 fid (1:536871260.13.1090524935), code=2
time 820.760593, pid 25867: Returning code 2 from 19
time 820.760594, pid 25867: vfs root vp 0xa400000, code 0
time 820.760595, pid 25867: readlink 0xa6be888
time 820.760596, pid 25867: Lookup adp 0xa6af738 name libjvm.0 fid (1:536871260.13.1090524935), code=2
time 820.760597, pid 25867: Returning code 2 from 19
time 820.770586, pid 25867: vfs root vp 0xa400000, code 0
time 820.770589, pid 25867: readlink 0xa6be888
time 820.780822, pid 25867: Lookup adp 0xa6af738 name libjvm.0 fid (1:536871260.13.10078272), code=2
time 820.780823, pid 25867: Returning code 2 from 19

...

-- 
Joe Buehler