[OpenAFS-devel] 1.4.0-rc4 weirdness
Dale Ghent
daleg@umbc.edu
Wed, 16 Nov 2005 11:27:47 -0500
On Nov 15, 2005, at 6:27 PM, Jim Rees wrote:
> CheckHost in fact already runs with the host held. I was wondering
> whether
> it was really necessary to keep locking and unlocking the hash
> table but
> decided to play it safe for now and leave it as-is.
Doing some research into lock debugging on Solaris, I came across a
new utility on Solaris 10 which uses Dtrace to instrument a running
process.
man plockstat
I'll try using it if (when) things hang here again.
Here's an example of it running against the fileserver process on one
of our AFS servers:
[root@hfs10]~>plockstat -p 15036
^C
Mutex block
Count nsec Lock Caller
------------------------------------------------------------------------
-------
2 1177064 fileserver`vol_glock_mutex fileserver`VGetVolume+0x13
1 883084 fileserver`host_glock_mutex fileserver`BreakCallBack
+0x5e
6 681057 fileserver`host_glock_mutex fileserver`h_Lock_r+0x61
1 626845 fileserver`host_glock_mutex fileserver`AddCallBack1
+0x13
1 578742 0x8b60348 fileserver`ubik_Call+0x26
1 472418 fileserver`host_glock_mutex fileserver`h_FindClient_r
+0x608
4 370074 fileserver`host_glock_mutex fileserver`CallPreamble
+0x2c
6 310114 fileserver`host_glock_mutex fileserver`GetClient+0x17
1 299881 fileserver`rx_stats_mutex fileserver`rxi_SendList
+0x2a8
4 155413 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead_r+0x266
1 154461 fileserver`vol_glock_mutex
fileserver`VAdjustDiskUsage+0x12
2 139791 fileserver`rx_stats_mutex fileserver`rxi_ReadPacket
+0x1bc
1 92994 fileserver`host_glock_mutex
fileserver`MultiBreakCallBack_r+0x2e4
1 90630 libc.so.1`libc_malloc_lock fileserver`rxi_Start+0x31a
2 87102 fileserver`vol_glock_mutex fileserver`VGetVnode+0x13
2 84733 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead+0x13
2 69585 fileserver`host_glock_mutex fileserver`GetRights+0xec
13 68516 fileserver`vol_glock_mutex fileserver`VGetVnode_r
+0x71c
5 59303 fileserver`vol_glock_mutex fileserver`VPutVnode+0x12
3 51464 fileserver`rx_stats_mutex
fileserver`rxi_AllocPacketTSFPQ+0x37
2 49638 fileserver`rx_stats_mutex
fileserver`ReturnToServerPool+0x23
1 41909 fileserver`vol_glock_mutex fileserver`VGetVnode_r
+0x4ca
2 36799 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead+0x13
3 36217 fileserver`rx_stats_mutex fileserver`rxi_SendPacket
+0x24a
1 32362 fileserver`fileproc_glock_mutex
fileserver`common_FetchData64+0x27
1 31798 fileserver`rx_serverPool_lock
fileserver`rxi_AttachServerProc+0x30
1 31062 fileserver`rx_stats_mutex
fileserver`rxi_SendPacketList+0x381
1 22981 0x9e61614 fileserver`rxi_SendList
+0x3a3
6 17154 fileserver`vol_glock_mutex fileserver`VGetVnode_r
+0x71c
2 16334 fileserver`host_glock_mutex fileserver`CallPostamble
+0x14
3 13548 fileserver`rx_stats_mutex
fileserver`rxi_AllocPacketTSFPQ+0x37
8 13114 fileserver`vol_glock_mutex fileserver`VPutVnode+0x12
1 9272 fileserver`rx_stats_mutex fileserver`rxi_ServerProc
+0xf7
3 8949 fileserver`host_glock_mutex fileserver`CallPreamble
+0x2c
4 8796 fileserver`host_glock_mutex fileserver`GetClient+0x17
6 8743 fileserver`host_glock_mutex fileserver`h_Lock_r+0x61
1 8563 fileserver`ih_glock_mutex fileserver`ih_open+0x3c
1 8258 fileserver`vol_glock_mutex fileserver`VAllocVnode_r
+0x472
2 7757 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead_r+0x266
1 7454 fileserver`rx_stats_mutex fileserver`rxi_SendList
+0x5b
1 7425 fileserver`ih_glock_mutex fileserver`ih_release+0x37
1 7045 fileserver`ih_glock_once libc.so.1`pthread_once+0x2c
2 6125 fileserver`host_glock_mutex fileserver`AddCallBack1
+0x13
2 5944 fileserver`ih_glock_mutex fileserver`ih_copy+0x27
1 5415 fileserver`vol_glock_mutex fileserver`VPutVolume+0x12
Mutex spin
Count nsec Lock Caller
------------------------------------------------------------------------
-------
1 17615 fileserver`freeSQEList_lock fileserver`rx_GetCall+0x3a5
1 9766 fileserver`vol_glock_mutex
fileserver`VAdjustDiskUsage+0x12
1 9230 fileserver`host_glock_mutex
fileserver`DeleteFileCallBacks+0x14
1 8195 fileserver`vol_glock_mutex fileserver`VPutVolume+0x12
1 7711 0x932821c
fileserver`rxi_CheckConnReach+0x3e
26 7529 fileserver`vol_glock_mutex fileserver`VGetVnode_r
+0x71c
2 7324 fileserver`ih_glock_mutex fileserver`ih_open+0x3c
9 6985 fileserver`vol_glock_mutex fileserver`VGetVnode+0x13
1 6612 fileserver`fileproc_glock_mutex
fileserver`common_FetchData64+0x27b
1 6588 fileserver`host_glock_mutex fileserver`h_GetHost_r
+0x3af
1 6185 fileserver`fileproc_glock_mutex
fileserver`SRXAFS_FetchStatus+0xb8
84 6084 fileserver`host_glock_mutex fileserver`h_Lock_r+0x61
1 5975 0x99929f0 fileserver`rx_GetSpecific
+0x14
1 5912 fileserver`host_glock_mutex
fileserver`MultiBreakCallBack_r+0x364
39 5639 fileserver`ih_glock_once libc.so.1`pthread_once+0x2c
24 5597 fileserver`vol_glock_mutex fileserver`VPutVnode+0x12
3 5551 fileserver`fileproc_glock_mutex
fileserver`FetchData_RXStyle+0x2d2
1 5531 0x932177c fileserver`rxi_SendList
+0x281
15 5474 fileserver`rx_stats_mutex fileserver`rxi_Start+0x433
3 5468 fileserver`host_glock_mutex fileserver`BreakCallBack
+0x5e
2 5457 fileserver`fileproc_glock_mutex
fileserver`SAFSS_FetchStatus+0x75
1 5420 fileserver`rxevent_lock
fileserver`rxevent_RaiseEvents+0x117
16 5356 fileserver`rx_serverPool_lock fileserver`rx_GetCall+0xa1
2 5316 0x9a018b8
fileserver`rxi_FindConnection+0x36e
2 5099 fileserver`vol_glock_mutex fileserver`VPutVnode_r
+0x367
15 5095 fileserver`vol_glock_mutex fileserver`VGetVnode_r
+0x4ca
14 5062 fileserver`rx_stats_mutex
fileserver`rxi_ReceiveDataPacket+0x16
6 5037 fileserver`ih_glock_mutex fileserver`fd_close+0x37
33 5033 fileserver`host_glock_mutex fileserver`CallPreamble
+0x2c
4 5028 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead_r+0x266
52 4926 fileserver`host_glock_mutex fileserver`CallPostamble
+0x14
38 4889 fileserver`host_glock_mutex fileserver`GetRights+0xec
1 4837 0x9a018b8
fileserver`rxi_ReceiveDataPacket+0x108
3 4815 fileserver`rx_stats_mutex fileserver`rxi_SendAck
+0x585
3 4754 0x932177c fileserver`rxi_ReadPacket
+0x20e
6 4715 fileserver`rx_stats_mutex
fileserver`rxi_SendPacketList+0x381
1 4694 libc.so.1`libc_malloc_lock fileserver`osi_free+0x4f
1 4674 0x99929f0
fileserver`rxi_ReceivePacket+0x74e
3 4671 fileserver`ih_glock_mutex fileserver`ih_release+0x37
20 4671 fileserver`host_glock_mutex fileserver`GetClient+0x17
5 4640 fileserver`fileproc_glock_mutex
fileserver`SetVolumeSync+0x12
3 4603 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead+0x13
25 4593 fileserver`vol_glock_mutex fileserver`VGetVolume+0x13
2 4528 fileserver`rx_stats_mutex
fileserver`rxi_AllocPacketNoLock+0x37
23 4438 fileserver`host_glock_mutex fileserver`AddCallBack1
+0x13
2 4346 libc.so.1`libc_malloc_lock fileserver`rxi_Start+0x4c4
59 4162 fileserver`rx_stats_mutex fileserver`rxi_SendList
+0x2a8
4 4155 fileserver`rx_serverPool_lock
fileserver`rxi_AttachServerProc+0x30
70 4012 fileserver`rx_stats_mutex
fileserver`rxi_AllocPacketTSFPQ+0x37
15 3881 fileserver`rxevent_lock fileserver`_rxevent_Post
+0x16
1 3853 fileserver`ih_glock_mutex fileserver`ih_copy+0x27
51 3824 fileserver`rx_stats_mutex fileserver`rxi_ReadPacket
+0x1bc
19 3663 fileserver`rx_stats_mutex fileserver`QuotaOK+0x26
1 3651 0x9a018b8 fileserver`rx_GetSpecific
+0x14
23 3492 fileserver`rx_stats_mutex fileserver`rxi_SendPacket
+0x24a
4 3466 fileserver`rx_stats_mutex
fileserver`rxi_ComputeRoundTripTime+0x7
29 3458 fileserver`rx_stats_mutex fileserver`rxi_SendList
+0x5b
2 3404 fileserver`ih_glock_mutex fileserver`ih_fdclose+0x1d1
48 3394 fileserver`rx_stats_mutex
fileserver`ReturnToServerPool+0x23
2 3358 libc.so.1`libc_malloc_lock fileserver`rxi_Start+0x31a
20 3342 fileserver`rx_stats_mutex
fileserver`rxi_ReceiveAckPacket+0x29
10 3340 fileserver`rxevent_lock
fileserver`rxevent_Cancel_1+0x5a
4 3339 fileserver`fileproc_glock_mutex
fileserver`SRXAFS_FetchStatus+0x16
3 3303 libc.so.1`libc_malloc_lock fileserver`rxi_Start+0x4c4
26 3301 fileserver`rx_stats_mutex fileserver`rxi_ServerProc
+0xf7
2 3283 fileserver`ih_glock_mutex fileserver`ih_open+0x13a
1 3276 fileserver`afs_bufferLock+0x4 fileserver`DRead+0x353
1 3165 fileserver`freeSQEList_lock fileserver`rx_GetCall+0x17
1 3123 fileserver`host_glock_mutex fileserver`h_FindClient_r
+0x608
2 3041 libc.so.1`libc_malloc_lock fileserver`rxi_Start+0x31a
1 2914 0x8bbb3dc fileserver`h_Lock_r+0x27
4 2908 libc.so.1`libc_malloc_lock fileserver`rxi_Start+0x31a
1 2904 libc.so.1`libc_malloc_lock fileserver`osi_alloc+0x47
1 2899 0x932177c fileserver`rxi_ResetCall
+0x8b
1 2868 0x92d2c54 fileserver`rxi_ReadPacket
+0x20e
2 2832 0x932177c fileserver`rxi_SendList
+0x2d
2 2616 fileserver`ih_glock_mutex fileserver`ih_init+0x4d
1 2527 0x939555c fileserver`rxi_SendList
+0x2d
1 2495 0x932177c fileserver`rxi_SendPacket
+0x27a
1 2369 0x9e61614 fileserver`rxi_SendList
+0x3a3
Mutex unsuccessful spin
Count nsec Lock Caller
------------------------------------------------------------------------
-------
1 16706 fileserver`rx_stats_mutex
fileserver`rxi_SendPacketList+0x381
1 16350 fileserver`rx_serverPool_lock
fileserver`rxi_AttachServerProc+0x30
2 14818 fileserver`host_glock_mutex fileserver`GetRights+0xec
6 14724 fileserver`rx_stats_mutex
fileserver`rxi_AllocPacketTSFPQ+0x37
1 14414 0x9e61614 fileserver`rxi_SendList
+0x3a3
1 14086 fileserver`rx_stats_mutex fileserver`rxi_SendList
+0x5b
4 13965 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead+0x13
19 13818 fileserver`vol_glock_mutex fileserver`VGetVnode_r
+0x71c
1 13653 fileserver`vol_glock_mutex fileserver`VAllocVnode_r
+0x472
1 13529 fileserver`vol_glock_mutex
fileserver`VAdjustDiskUsage+0x12
1 13485 fileserver`vol_glock_mutex fileserver`VGetVnode_r
+0x4ca
2 13400 fileserver`vol_glock_mutex fileserver`VGetVnode+0x13
1 13338 fileserver`ih_glock_mutex fileserver`ih_open+0x3c
13 12966 fileserver`vol_glock_mutex fileserver`VPutVnode+0x12
3 12947 fileserver`rx_stats_mutex fileserver`rxi_SendPacket
+0x24a
1 12883 fileserver`rx_stats_mutex fileserver`rxi_ServerProc
+0xf7
7 12754 fileserver`host_glock_mutex fileserver`CallPreamble
+0x2c
6 12591 fileserver`vol_glock_mutex
fileserver`VVnodeWriteToRead_r+0x266
1 12207 fileserver`ih_glock_once libc.so.1`pthread_once+0x2c
10 12184 fileserver`host_glock_mutex fileserver`GetClient+0x17
12 12130 fileserver`host_glock_mutex fileserver`h_Lock_r+0x61
1 12066 fileserver`host_glock_mutex fileserver`BreakCallBack
+0x5e
1 11744 fileserver`ih_glock_mutex fileserver`ih_release+0x37
1 11574 fileserver`host_glock_mutex fileserver`h_FindClient_r
+0x608
2 11367 fileserver`host_glock_mutex fileserver`CallPostamble
+0x14
1 11257 fileserver`vol_glock_mutex fileserver`VPutVolume+0x12
2 10954 fileserver`ih_glock_mutex fileserver`ih_copy+0x27
1 10881 fileserver`rx_stats_mutex fileserver`rxi_SendList
+0x2a8
3 10770 fileserver`host_glock_mutex fileserver`AddCallBack1
+0x13
1 10744 fileserver`host_glock_mutex
fileserver`MultiBreakCallBack_r+0x2e4
1 10262 0x8b60348 fileserver`ubik_Call+0x26
2 9832 fileserver`rx_stats_mutex
fileserver`ReturnToServerPool+0x23
2 7506 fileserver`rx_stats_mutex fileserver`rxi_ReadPacket
+0x1bc
1 6146 fileserver`fileproc_glock_mutex
fileserver`common_FetchData64+0x27
1 4702 libc.so.1`libc_malloc_lock fileserver`rxi_Start+0x31a
2 4531 fileserver`vol_glock_mutex fileserver`VGetVolume+0x13
--
Dale Ghent
UNIX Systems Specialist
UMBC - Office of Information Technology
ECS 201 - x51705