Date: Tue 06/01/2004 07:06:24 New SrvLog started at Tue Jun 1 07:06:24 2004 07:06:24 Resource limit on data size are set to -1 07:06:24 RvmType is Rvm 07:06:24 Main process doing a LWP_Init() 07:06:24 Main thread just did a RVM_SET_THREAD_DATA 07:06:24 Setting Rvm Truncate threshhold to 5. Partition /vicepa: inodes in use: 549, total: 16777216. 07:06:38 Partition /vicepa: 32298296K available (minfree=5%), 29774688K free. 07:06:38 The server (pid 588) can be controlled using volutil commands 07:06:38 "volutil -help" will give you a list of these commands 07:06:38 If desperate, "kill -SIGWINCH 588" will increase debugging level 07:06:38 "kill -SIGUSR2 588" will set debugging level to zero 07:06:38 "kill -9 588" will kill a runaway server 07:06:38 Vice file system salvager, version 3.0. 07:06:38 SanityCheckFreeLists: Checking RVM Vnode Free lists. 07:06:38 DestroyBadVolumes: Checking for destroyed volumes. 07:06:38 Salvaging file system partition /vicepa 07:06:38 Force salvage of all volumes on this partition 07:06:38 Scanning inodes in directory /vicepa... 07:06:38 SFS: There are some volumes without any inodes in them 07:06:38 SalvageIndex: Vnode 0xb2c has no inodeNumber 07:06:38 SalvageIndex: Creating an empty object for it 07:06:38 Entering DCC(0x1000003) 07:06:38 done: 561 files/dirs, 9475 blocks 07:06:38 SalvageFileSys: unclaimed volume header file or no Inodes in volume 1000004 07:06:38 SalvageFileSys: Therefore only resetting inUse flag 07:06:38 SalvageFileSys completed on /vicepa 07:06:38 VAttachVolumeById: vol 1000003 (coda.root.0) attached and online 07:06:38 VAttachVolumeById: vol 1000004 (mta.pending.0) attached and online 07:06:38 Attached 2 volumes; 0 volumes not attached lqman: Creating LockQueue Manager.....LockQueue Manager starting ..... 07:06:38 LockQueue Manager just did a rvmlib_set_thread_data() done 07:06:38 CallBackCheckLWP just did a rvmlib_set_thread_data() 07:06:38 CheckLWP just did a rvmlib_set_thread_data() 07:06:38 ServerLWP 0 just did a rvmlib_set_thread_data() 07:06:38 ServerLWP 1 just did a rvmlib_set_thread_data() 07:06:38 ServerLWP 2 just did a rvmlib_set_thread_data() 07:06:38 ServerLWP 3 just did a rvmlib_set_thread_data() 07:06:38 ServerLWP 4 just did a rvmlib_set_thread_data() 07:06:38 ServerLWP 5 just did a rvmlib_set_thread_data() 07:06:38 ResLWP-0 just did a rvmlib_set_thread_data() 07:06:38 ResLWP-1 just did a rvmlib_set_thread_data() 07:06:38 VolUtilLWP 0 just did a rvmlib_set_thread_data() 07:06:38 VolUtilLWP 1 just did a rvmlib_set_thread_data() 07:06:38 Starting SmonDaemon timer 07:06:38 File Server started Tue Jun 1 07:06:38 2004 07:07:01 client_GetVenusId: got new host 212.85.15.253:32773 07:07:01 Building callback conn. 07:07:04 client_GetVenusId: got new host 212.85.15.251:32769 07:07:04 Building callback conn. 07:07:18 Worker0: Unbinding RPC connection 1643 07:13:02 Worker0: Unbinding RPC connection 6652 07:13:02 Worker1: Unbinding RPC connection 10141 07:14:06 GetAttrPlusSHA: Computing SHA 1000003.2e.120, disk.inode=5 07:14:06 GetAttrPlusSHA: Computing SHA 1000003.4.10b, disk.inode=2 07:14:06 GetAttrPlusSHA: Computing SHA 1000003.2.10a, disk.inode=1 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.12.112, disk.inode=4 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.84a.eea, disk.inode=197 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.da4.fb5, disk.inode=1d5 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.956.fba, disk.inode=170 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.866.1247, disk.inode=15f 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7c8.1362, disk.inode=1da 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7ca.1363, disk.inode=1b2 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7cc.1364, disk.inode=1dc 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.840.ee5, disk.inode=180 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.686.be0, disk.inode=1cd 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.954.c8a, disk.inode=1c2 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7ce.1365, disk.inode=1b3 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7d0.1366, disk.inode=1de 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7d2.1367, disk.inode=1df 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7d4.1368, disk.inode=19b 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7f0.1376, disk.inode=1ec 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7d6.1369, disk.inode=1e1 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7f2.1377, disk.inode=1ed 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7f4.1378, disk.inode=1be 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7f6.1379, disk.inode=1a0 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7f8.137a, disk.inode=1c0 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7d8.136a, disk.inode=1e2 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7da.136b, disk.inode=1b7 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7dc.136c, disk.inode=1e4 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7e0.136e, disk.inode=1fa 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7fa.137b, disk.inode=1f1 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7e4.1370, disk.inode=1b9 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7fc.137c, disk.inode=1a2 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7fe.137d, disk.inode=1c3 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.800.137e, disk.inode=1c4 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.802.137f, disk.inode=1f5 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.b2c.1074, disk.inode=226 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7e6.1371, disk.inode=1e7 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7e8.1372, disk.inode=19e 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7ea.1373, disk.inode=1e9 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7ec.1374, disk.inode=1ea 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.804.1380, disk.inode=1f6 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.7ee.1375, disk.inode=1bc 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.806.1381, disk.inode=1c6 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.88a.1382, disk.inode=1f8 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.2c.11f, disk.inode=7 07:14:07 GetAttrPlusSHA: Computing SHA 1000003.32.122, disk.inode=9 07:15:46 GetAttrPlusSHA: Computing SHA 1000003.b2.2da, disk.inode=227 07:16:32 VAllocFid: volume disk uniquifier being extended 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.672.12be, disk.inode=19d 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.66c.12bb, disk.inode=17b 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.5bc.55f, disk.inode=13d 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.5ba.55e, disk.inode=13c 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.55a.52e, disk.inode=158 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.554.52b, disk.inode=110 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.488.4c5, disk.inode=e5 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.484.4c3, disk.inode=11a 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.3d4.46b, disk.inode=78 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.3d2.46a, disk.inode=b8 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.342.422, disk.inode=d0 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.33c.41f, disk.inode=8c 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.aba.9fb, disk.inode=168 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.ab8.9fa, disk.inode=161 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.1e0.371, disk.inode=68 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.1da.36e, disk.inode=43 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.90e.13c4, disk.inode=21b 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.10c.307, disk.inode=27 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.b4.2db, disk.inode=3 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.7b4.1358, disk.inode=1cf 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.7b2.1357, disk.inode=1aa 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.6ee.12f5, disk.inode=1bf 07:17:03 GetAttrPlusSHA: Computing SHA 1000003.6e8.12f2, disk.inode=1bd 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.3e2.472, disk.inode=c0 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.3e0.471, disk.inode=35 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.366.434, disk.inode=94 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.362.432, disk.inode=60 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.2a4.3d3, disk.inode=46 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.2a0.3d1, disk.inode=a2 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.1c6.364, disk.inode=1c 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.1c2.362, disk.inode=5f 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.906.13c0, disk.inode=219 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.106.304, disk.inode=1a 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.88a.1382, disk.inode=1f8 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.7d2.1367, disk.inode=1df 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.7d0.1366, disk.inode=1de 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.738.131a, disk.inode=1d8 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.732.1317, disk.inode=169 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.968.13ea, disk.inode=239 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.96e.13ed, disk.inode=23b 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.974.13f0, disk.inode=23d 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.97a.13f3, disk.inode=23f 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.97e.13f5, disk.inode=22a 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.984.13f8, disk.inode=242 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.98a.13fb, disk.inode=244 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.98e.13fd, disk.inode=23a 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.994.1400, disk.inode=247 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.99e.146a, disk.inode=23c 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9a2.146c, disk.inode=22d 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9a8.146f, disk.inode=24b 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9ac.1471, disk.inode=231 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9b2.1474, disk.inode=24e 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9e2.148c, disk.inode=265 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9e4.148d, disk.inode=235 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9e6.148e, disk.inode=243 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9e8.148f, disk.inode=227 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9ea.1490, disk.inode=245 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9ec.1491, disk.inode=246 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9ee.1492, disk.inode=22b 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9f0.1493, disk.inode=248 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9f2.1494, disk.inode=249 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9f4.1495, disk.inode=24a 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9f6.1496, disk.inode=23e 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9f8.1497, disk.inode=24c 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9fa.1498, disk.inode=24d 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9fc.1499, disk.inode=240 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.9fe.149a, disk.inode=24f 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a00.149b, disk.inode=241 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a02.149c, disk.inode=250 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a04.149d, disk.inode=251 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a06.149e, disk.inode=252 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a08.149f, disk.inode=253 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a0a.14a0, disk.inode=254 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a0c.14a1, disk.inode=255 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a0e.14a2, disk.inode=256 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a10.14a3, disk.inode=257 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a12.14a4, disk.inode=258 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a14.14a5, disk.inode=259 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a16.14a6, disk.inode=25a 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a18.14a7, disk.inode=25b 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a1a.14a8, disk.inode=25c 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a1c.14a9, disk.inode=25d 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a1e.14aa, disk.inode=25e 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a20.14ab, disk.inode=25f 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a22.14ac, disk.inode=260 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a24.14ad, disk.inode=261 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a26.14ae, disk.inode=262 07:17:12 GetAttrPlusSHA: Computing SHA 1000003.a28.14af, disk.inode=263 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: memory vnode was snatched away 07:18:02 VGetVnode: vnode 1000003.9fe is not allocated 07:18:03 VGetVnode: memory vnode was snatched away 07:18:03 VGetVnode: memory vnode was snatched away 07:18:03 VGetVnode: memory vnode was snatched away 07:18:03 VGetVnode: memory vnode was snatched away 07:18:03 VGetVnode: memory vnode was snatched away 07:18:03 VGetVnode: vnode 1000003.984 is not allocated 07:18:03 VGetVnode: vnode 1000003.98a is not allocated 07:18:03 VGetVnode: vnode 1000003.98e is not allocated 07:18:09 VAllocFid: volume disk uniquifier being extended 07:20:46 VAllocFid: volume disk uniquifier being extended 07:20:58 GetVolObj: Volume (1000003) already write locked 07:20:58 GrabFsObj, GetVolObj error Resource temporarily unavailable 07:21:19 VAllocFid: volume disk uniquifier being extended 07:21:49 VAllocFid: volume disk uniquifier being extended 07:22:11 VAllocFid: volume disk uniquifier being extended 07:22:31 Total operations for File Server = 4096 : time = Tue Jun 1 07:22:31 2004 07:22:31 Vice was last started at Tue Jun 1 07:06:38 2004 07:22:31 NewConnectFS 14 07:22:31 DisconnectFS 3 07:22:31 GetAttr 0 07:22:31 GetAcl 0 07:22:31 Fetch 64 07:22:31 SetAttr 0 07:22:31 SetAcl 0 07:22:31 Store 1245 07:22:31 ValidateAttrs 0 07:22:31 Remove 1220 07:22:31 Create 1245 07:22:31 Rename 0 07:22:31 SymLink 0 07:22:31 Link 0 07:22:31 MakeDir 2 07:22:31 RemoveDir 0 07:22:31 GetRootVolume 1 07:22:31 SetRootVolume 0 07:22:31 GetVolumeStatus 0 07:22:31 SetVolumeStatus 0 07:22:31 GetTime 25 07:22:31 GetStatistics 0 07:22:31 GetVolumeInfo 0 07:22:31 AllocFids 41 07:22:31 COP2 40 07:22:31 Resolve 0 07:22:31 Repair 0 07:22:31 SetVV 0 07:22:31 Reintegrate 5 07:22:31 OpenReintHandle 0 07:22:31 QueryReintHandle 0 07:22:31 SendReintFragment 0 07:22:31 CloseReintHandle 0 07:22:31 GetVolVS 2 07:22:31 ValidateVols 1 07:22:31 GetWBPermit 0 07:22:31 TossWBPermit 0 07:22:31 RejectWBPermit 0 07:22:31 GetAttrPlusSHA 111 07:22:31 ValidateAttrsPlusSHA 77 07:22:31 Total FetchDatas = 64, bytes transfered = 164386, transfer rate = 164386 bps 07:22:31 Fetched files <1k = 0; <8k = 63; <64k = 1; <512k = 0; >512k = 0. 07:22:31 Total StoreDatas = 1245, bytes transfered = 4838976, transfer rate = 1209744 bps 07:22:31 Stored files <1k = 2; <8k = 1243; <64k = 0; <512k = 0; >512k = 0. 07:22:31 Large vnode cache, 500 entries, 4 allocs, 6547 gets (11 reads), 4948 writes 07:22:31 Small vnode cache,500 entries, 1248 allocs, 6212 gets (654 reads), 6228 writes 07:22:31 Volume header cache, 50 entries, 7837 gets, 0 replacements 07:22:31 Partition /vicepa: 32298296K available (minfree=5%), 29780704K free. Dirstats: get 0, put 0, flush 0 07:22:31 RPC Total bytes: sent = 1332250, received = 6698792 07:22:31 bytes sent: rpc = 951384, multirpc = 0, sftp = 380866, sftp multicasted = 0 07:22:31 bytes received: rpc = 1505033, multirpc = 0, sftp = 5193759, sftp multicasted = 0 07:22:31 RPC Total packets: sent = 6937, received = 9932 07:22:31 packets sent: rpc = 4242, multirpc = 0, sftp = 2695, sftp multicasted = 0 07:22:31 packets received: rpc = 4241, multirpc = 0, sftp = 5691, sftp multicasted = 0 07:22:31 RPC Packets retried = 0, Invalid packets received = 35, Busies sent = 4 07:22:31 RPC Requests 4131, Good Requests 4096, Replies 110, Busies 0 07:22:31 RPC Counters: CCount 13; Unbinds 3; FConns 3; AConns 16; GCConns 0 07:22:31 RPC Creation counts: Conn 13; SL 24; PB Small 9, Med 11, Large 6; SS 3 07:22:31 RPC2 In Use: Conn 13; SS 3 07:22:31 RPC2 PB: InUse 5, Hold 0, Freeze 0, SFree 7, MFree 8, LFree 6 07:22:31 RPC2 HW: Freeze 0, Hold 0 07:22:31 SFTP: datas 202, datar 5626, acks 1248, ackr 65, retries 0, duplicates 0 07:22:31 SFTP: timeouts 0, windowfulls 0, bogus 0, didpiggy 5 07:22:31 Total CB entries= 2350, blocks = 3; and total file entries = 1812, blocks = 9 07:22:31 There are currently 11 connections in use 07:22:31 There are 2 workstations and 2 are active (req in < 15 mins) 07:22:31 Ether Total bytes: sent = 0, received = 0 07:22:31 Ether Packets: sent = 0, received = 0, errors = 0 07:22:31 Printing RVM statistics Transaction statistics current cumulative Started: 391 39914 Aborted: 0 0 Committed, flush: 340 35830 Committed, no_flush: 51 4084 Total committed: 391 39914 Committed, but not flushed: 0 Unflushed transactions length: 0 Not committed: 0 Split by log wrap: 0 3 Delayed by truncation: 0 0 Log function statistics current cumulative rvm_flush calls: 0 1 Internal flushes, incl. commit: 340 35583 Total flushes: 340 35584 Average flush time (msec): 2 3 Last flush time (msec): 0 rvm_truncate calls: 2 Automatic truncations: 73 Forced synch. truncations: 0 Recovery truncations: 24 Total truncations: 99 Average truncation time (sec): 0 Last truncation time (sec): 0 Last tree build time (sec): 0 Last tree apply time (sec): 0 Transaction records: 391 39917 Bookeeping records: 1 100 Log wrap-arounds: 0 3 Total records: 392 40020 Log used: 2% 5% Log written (bytes): 741784 118117892 Timing Histograms Current Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 341 0 0 0 0 0 0 0 0 0 Cummulative Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 35200 22 17 0 0 0 0 0 0 0 Truncation Timings for Tree Build (sec): <=1 <=10 <=100 <=500 > 500 102 0 0 0 0 Truncation Timings for Tree Apply (sec): <=1 <=10 <=100 <=500 > 500 101 0 1 0 0 Total Truncation Timings (sec): <=1 <=10 <=100 <=500 > 500 101 0 1 0 0 Transaction Optimization Statistics current cumulative Ranges eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Avg. number eliminated per transaction Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Range length eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Log savings Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Transactions coalesced per flush: 0 0 Tranasction Modification Range Distributions Current Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 424 102 141 12 103 259 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 206 107 207 0 0 Cumulative Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 50014 10850 17573 1761 9558 25652 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 18260 9546 41976 3 2 Current Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 392 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 392 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 784 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Cumulative Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 39242 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 39242 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 78484 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Current Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 392 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 392 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 784 0 0 0 0 0 Cummulative Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 39242 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 39242 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 78484 0 0 0 0 0 Cummulative Number of Transactions Coalesced per flush Cycle <=0 <=5 <=10 <=50 <=100 > 100 39634 0 0 0 0 0 07:22:31 Printing RDS statistics Number of Free bytes: 3fed0020 Alloced bytes: 2fc80 Mallocs: 5686 Frees: 5032 Preallocs: 0 Hits: 3196 Misses: 2485 Large Hits: 0 Large Misses: 5 Coalesces: 4083 Merges 1799 Not Merged: 120213 Times the Large List pointer has changed: 0 07:22:31 done 07:22:37 VAllocFid: volume disk uniquifier being extended 07:23:00 VAllocFid: volume disk uniquifier being extended 07:23:26 VAllocFid: volume disk uniquifier being extended 07:23:48 VAllocFid: volume disk uniquifier being extended 07:25:54 VAllocFid: volume disk uniquifier being extended 07:26:18 VAllocFid: volume disk uniquifier being extended 07:26:54 Total operations for File Server = 8192 : time = Tue Jun 1 07:26:54 2004 07:26:54 Vice was last started at Tue Jun 1 07:06:38 2004 07:26:54 NewConnectFS 15 07:26:54 DisconnectFS 3 07:26:54 GetAttr 0 07:26:54 GetAcl 0 07:26:54 Fetch 72 07:26:54 SetAttr 1 07:26:54 SetAcl 0 07:26:54 Store 2574 07:26:54 ValidateAttrs 0 07:26:54 Remove 2536 07:26:54 Create 2575 07:26:54 Rename 0 07:26:54 SymLink 0 07:26:54 Link 0 07:26:54 MakeDir 5 07:26:54 RemoveDir 3 07:26:54 GetRootVolume 1 07:26:54 SetRootVolume 0 07:26:54 GetVolumeStatus 0 07:26:54 SetVolumeStatus 0 07:26:54 GetTime 32 07:26:54 GetStatistics 0 07:26:54 GetVolumeInfo 0 07:26:54 AllocFids 83 07:26:54 COP2 82 07:26:54 Resolve 0 07:26:54 Repair 0 07:26:54 SetVV 0 07:26:54 Reintegrate 5 07:26:54 OpenReintHandle 0 07:26:54 QueryReintHandle 0 07:26:54 SendReintFragment 0 07:26:54 CloseReintHandle 0 07:26:54 GetVolVS 2 07:26:54 ValidateVols 1 07:26:54 GetWBPermit 0 07:26:54 TossWBPermit 0 07:26:54 RejectWBPermit 0 07:26:54 GetAttrPlusSHA 113 07:26:54 ValidateAttrsPlusSHA 89 07:26:54 Total FetchDatas = 72, bytes transfered = 184866, transfer rate = 184866 bps 07:26:54 Fetched files <1k = 0; <8k = 71; <64k = 1; <512k = 0; >512k = 0. 07:26:54 Total StoreDatas = 2574, bytes transfered = 10000966, transfer rate = 1428709 bps 07:26:54 Stored files <1k = 2; <8k = 2572; <64k = 0; <512k = 0; >512k = 0. 07:26:54 Large vnode cache, 500 entries, 7 allocs, 13208 gets (11 reads), 10261 writes 07:26:54 Small vnode cache,500 entries, 2577 allocs, 11520 gets (654 reads), 12865 writes 07:26:54 Volume header cache, 50 entries, 15866 gets, 0 replacements 07:26:54 Partition /vicepa: 32298296K available (minfree=5%), 29773343K free. Dirstats: get 0, put 0, flush 0 07:26:54 RPC Total bytes: sent = 2533686, received = 13711842 07:26:54 bytes sent: rpc = 1913184, multirpc = 0, sftp = 620502, sftp multicasted = 0 07:26:54 bytes received: rpc = 2996333, multirpc = 0, sftp = 10715509, sftp multicasted = 0 07:26:54 RPC Total packets: sent = 13734, received = 20047 07:26:54 packets sent: rpc = 8361, multirpc = 0, sftp = 5373, sftp multicasted = 0 07:26:54 packets received: rpc = 8360, multirpc = 0, sftp = 11687, sftp multicasted = 0 07:26:54 RPC Packets retried = 0, Invalid packets received = 38, Busies sent = 4 07:26:54 RPC Requests 8230, Good Requests 8192, Replies 130, Busies 0 07:26:54 RPC Counters: CCount 14; Unbinds 3; FConns 3; AConns 17; GCConns 0 07:26:54 RPC Creation counts: Conn 14; SL 24; PB Small 9, Med 12, Large 6; SS 3 07:26:54 RPC2 In Use: Conn 14; SS 3 07:26:54 RPC2 PB: InUse 3, Hold 0, Freeze 0, SFree 8, MFree 10, LFree 6 07:26:54 RPC2 HW: Freeze 0, Hold 0 07:26:54 SFTP: datas 222, datar 11614, acks 2577, ackr 73, retries 0, duplicates 0 07:26:54 SFTP: timeouts 0, windowfulls 0, bogus 0, didpiggy 5 07:26:54 Total CB entries= 3682, blocks = 4; and total file entries = 3144, blocks = 15 07:26:54 There are currently 12 connections in use 07:26:54 There are 2 workstations and 2 are active (req in < 15 mins) 07:26:54 Ether Total bytes: sent = 0, received = 0 07:26:54 Ether Packets: sent = 0, received = 0, errors = 0 07:26:54 Printing RVM statistics Transaction statistics current cumulative Started: 528 50171 Aborted: 0 0 Committed, flush: 459 44767 Committed, no_flush: 69 5404 Total committed: 528 50171 Committed, but not flushed: 0 Unflushed transactions length: 0 Not committed: 0 Split by log wrap: 0 4 Delayed by truncation: 0 0 Log function statistics current cumulative rvm_flush calls: 0 1 Internal flushes, incl. commit: 459 44520 Total flushes: 459 44521 Average flush time (msec): 4 3 Last flush time (msec): 3 rvm_truncate calls: 2 Automatic truncations: 85 Forced synch. truncations: 0 Recovery truncations: 24 Total truncations: 111 Average truncation time (sec): 0 Last truncation time (sec): 0 Last tree build time (sec): 0 Last tree apply time (sec): 0 Transaction records: 528 50175 Bookeeping records: 1 112 Log wrap-arounds: 0 4 Total records: 529 50291 Log used: 2% 5% Log written (bytes): 706952 136957572 Timing Histograms Current Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 460 0 0 0 0 0 0 0 0 0 Cummulative Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 44007 32 18 0 0 0 0 0 0 0 Truncation Timings for Tree Build (sec): <=1 <=10 <=100 <=500 > 500 114 0 0 0 0 Truncation Timings for Tree Apply (sec): <=1 <=10 <=100 <=500 > 500 113 0 1 0 0 Total Truncation Timings (sec): <=1 <=10 <=100 <=500 > 500 113 0 1 0 0 Transaction Optimization Statistics current cumulative Ranges eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Avg. number eliminated per transaction Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Range length eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Log savings Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Transactions coalesced per flush: 0 0 Tranasction Modification Range Distributions Current Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 696 139 139 0 139 346 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 277 144 139 0 0 Cumulative Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 62099 13865 21834 2219 12182 32214 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 23502 12263 47146 3 2 Current Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 530 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 530 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 1060 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Cumulative Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 49361 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 49361 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 98722 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Current Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 530 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 530 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 1060 0 0 0 0 0 Cummulative Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 49361 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 49361 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 98722 0 0 0 0 0 Cummulative Number of Transactions Coalesced per flush Cycle <=0 <=5 <=10 <=50 <=100 > 100 49891 0 0 0 0 0 07:26:54 Printing RDS statistics Number of Free bytes: 3fecfa20 Alloced bytes: 30280 Mallocs: 7026 Frees: 6360 Preallocs: 0 Hits: 4070 Misses: 2951 Large Hits: 0 Large Misses: 5 Coalesces: 5403 Merges 2245 Not Merged: 176704 Times the Large List pointer has changed: 0 07:26:54 done 07:27:07 VAllocFid: volume disk uniquifier being extended 07:27:18 VGetVnode: memory vnode was snatched away 07:27:18 Entering VFlushVnode for vnode 0x9de 07:27:46 VAllocFid: volume disk uniquifier being extended 07:28:34 VAllocFid: volume disk uniquifier being extended 07:30:31 VAllocFid: volume disk uniquifier being extended 07:31:08 VAllocFid: volume disk uniquifier being extended 07:31:55 VAllocFid: volume disk uniquifier being extended 07:32:34 Total operations for File Server = 12288 : time = Tue Jun 1 07:32:34 2004 07:32:34 Vice was last started at Tue Jun 1 07:06:38 2004 07:32:34 NewConnectFS 15 07:32:34 DisconnectFS 3 07:32:34 GetAttr 0 07:32:34 GetAcl 0 07:32:34 Fetch 82 07:32:34 SetAttr 1 07:32:34 SetAcl 0 07:32:34 Store 3895 07:32:34 ValidateAttrs 0 07:32:34 Remove 3856 07:32:34 Create 3895 07:32:34 Rename 0 07:32:34 SymLink 0 07:32:34 Link 0 07:32:34 MakeDir 8 07:32:34 RemoveDir 6 07:32:34 GetRootVolume 1 07:32:34 SetRootVolume 0 07:32:34 GetVolumeStatus 0 07:32:34 SetVolumeStatus 0 07:32:34 GetTime 41 07:32:34 GetStatistics 0 07:32:34 GetVolumeInfo 0 07:32:34 AllocFids 125 07:32:34 COP2 127 07:32:34 Resolve 0 07:32:34 Repair 0 07:32:34 SetVV 0 07:32:34 Reintegrate 7 07:32:34 OpenReintHandle 0 07:32:34 QueryReintHandle 0 07:32:34 SendReintFragment 0 07:32:34 CloseReintHandle 0 07:32:34 GetVolVS 4 07:32:34 ValidateVols 1 07:32:34 GetWBPermit 0 07:32:34 TossWBPermit 0 07:32:34 RejectWBPermit 0 07:32:34 GetAttrPlusSHA 114 07:32:34 ValidateAttrsPlusSHA 107 07:32:34 Total FetchDatas = 82, bytes transfered = 207394, transfer rate = 207394 bps 07:32:34 Fetched files <1k = 0; <8k = 81; <64k = 1; <512k = 0; >512k = 0. 07:32:34 Total StoreDatas = 3894, bytes transfered = 15119265, transfer rate = 1511926 bps 07:32:34 Stored files <1k = 2; <8k = 3892; <64k = 0; <512k = 0; >512k = 0. 07:32:34 Large vnode cache, 500 entries, 10 allocs, 19874 gets (11 reads), 15565 writes 07:32:34 Small vnode cache,500 entries, 3899 allocs, 16814 gets (654 reads), 19480 writes 07:32:34 Volume header cache, 50 entries, 23882 gets, 0 replacements 07:32:34 Partition /vicepa: 32298296K available (minfree=5%), 29769078K free. Dirstats: get 0, put 0, flush 0 07:32:34 RPC Total bytes: sent = 3734886, received = 20676333 07:32:34 bytes sent: rpc = 2873892, multirpc = 0, sftp = 860994, sftp multicasted = 0 07:32:34 bytes received: rpc = 4483669, multirpc = 0, sftp = 16192664, sftp multicasted = 0 07:32:34 RPC Total packets: sent = 20521, received = 30121 07:32:34 packets sent: rpc = 12484, multirpc = 0, sftp = 8037, sftp multicasted = 0 07:32:34 packets received: rpc = 12482, multirpc = 0, sftp = 17639, sftp multicasted = 0 07:32:34 RPC Packets retried = 0, Invalid packets received = 38, Busies sent = 5 07:32:34 RPC Requests 12326, Good Requests 12288, Replies 156, Busies 0 07:32:34 RPC Counters: CCount 14; Unbinds 3; FConns 3; AConns 17; GCConns 0 07:32:34 RPC Creation counts: Conn 14; SL 24; PB Small 9, Med 12, Large 6; SS 3 07:32:34 RPC2 In Use: Conn 14; SS 3 07:32:34 RPC2 PB: InUse 4, Hold 0, Freeze 0, SFree 7, MFree 10, LFree 6 07:32:34 RPC2 HW: Freeze 0, Hold 0 07:32:34 SFTP: datas 244, datar 17556, acks 3898, ackr 83, retries 0, duplicates 0 07:32:34 SFTP: timeouts 0, windowfulls 0, bogus 0, didpiggy 6 07:32:34 Total CB entries= 5009, blocks = 5; and total file entries = 4469, blocks = 21 07:32:34 There are currently 12 connections in use 07:32:34 There are 2 workstations and 2 are active (req in < 15 mins) 07:32:34 Ether Total bytes: sent = 0, received = 0 07:32:34 Ether Packets: sent = 0, received = 0, errors = 0 07:32:34 Printing RVM statistics Transaction statistics current cumulative Started: 221 60389 Aborted: 0 0 Committed, flush: 192 53661 Committed, no_flush: 29 6728 Total committed: 221 60389 Committed, but not flushed: 0 Unflushed transactions length: 0 Not committed: 0 Split by log wrap: 0 4 Delayed by truncation: 0 0 Log function statistics current cumulative rvm_flush calls: 0 1 Internal flushes, incl. commit: 192 53414 Total flushes: 192 53415 Average flush time (msec): 5 3 Last flush time (msec): 4 rvm_truncate calls: 2 Automatic truncations: 95 Forced synch. truncations: 0 Recovery truncations: 24 Total truncations: 121 Average truncation time (sec): 0 Last truncation time (sec): 0 Last tree build time (sec): 0 Last tree apply time (sec): 0 Transaction records: 221 60393 Bookeeping records: 1 122 Log wrap-arounds: 0 4 Total records: 222 60519 Log used: 0% 5% Log written (bytes): 301520 152669596 Timing Histograms Current Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 193 0 0 0 0 0 0 0 0 0 Cummulative Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 53152 47 19 0 0 0 0 0 0 0 Truncation Timings for Tree Build (sec): <=1 <=10 <=100 <=500 > 500 124 0 0 0 0 Truncation Timings for Tree Apply (sec): <=1 <=10 <=100 <=500 > 500 123 0 1 0 0 Total Truncation Timings (sec): <=1 <=10 <=100 <=500 > 500 123 0 1 0 0 Transaction Optimization Statistics current cumulative Ranges eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Avg. number eliminated per transaction Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Range length eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Log savings Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Transactions coalesced per flush: 0 0 Tranasction Modification Range Distributions Current Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 250 58 103 14 59 147 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 118 61 59 0 0 Cumulative Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 74618 16836 26626 2877 14918 39015 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 28965 15097 50662 3 2 Current Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 222 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 222 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 444 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Cumulative Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 59887 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 59887 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 119774 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Current Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 222 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 222 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 444 0 0 0 0 0 Cummulative Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 59887 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 59887 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 119774 0 0 0 0 0 Cummulative Number of Transactions Coalesced per flush Cycle <=0 <=5 <=10 <=50 <=100 > 100 60109 0 0 0 0 0 07:32:34 Printing RDS statistics Number of Free bytes: 3fed00a0 Alloced bytes: 2fc00 Mallocs: 8358 Frees: 7705 Preallocs: 0 Hits: 4752 Misses: 3601 Large Hits: 0 Large Misses: 5 Coalesces: 6727 Merges 2917 Not Merged: 229986 Times the Large List pointer has changed: 0 07:32:34 done 07:32:44 VAllocFid: volume disk uniquifier being extended 07:34:34 ****** WARNING entry at 0x8122320 already has deqing set! 07:34:34 ****** WARNING entry at 0x8122320 already has deqing set! 07:50:01 Shutdown received 07:50:01 Shutdown received 07:50:06 Building callback conn. 07:50:06 ****** WARNING entry at 0x8122320 already has deqing set! 07:50:16 Shutting down the File Server Tue Jun 1 07:50:16 2004 07:50:16 Total operations for File Server = 12875 : time = Tue Jun 1 07:50:16 2004 07:50:16 Vice was last started at Tue Jun 1 07:06:38 2004 07:50:16 NewConnectFS 18 07:50:16 DisconnectFS 3 07:50:16 GetAttr 0 07:50:16 GetAcl 0 07:50:16 Fetch 84 07:50:16 SetAttr 1 07:50:16 SetAcl 0 07:50:16 Store 4073 07:50:16 ValidateAttrs 0 07:50:16 Remove 4031 07:50:16 Create 4073 07:50:16 Rename 0 07:50:16 SymLink 0 07:50:16 Link 0 07:50:16 MakeDir 9 07:50:16 RemoveDir 7 07:50:16 GetRootVolume 1 07:50:16 SetRootVolume 0 07:50:16 GetVolumeStatus 0 07:50:16 SetVolumeStatus 0 07:50:16 GetTime 65 07:50:16 GetStatistics 0 07:50:16 GetVolumeInfo 0 07:50:16 AllocFids 133 07:50:16 COP2 133 07:50:16 Resolve 0 07:50:16 Repair 0 07:50:16 SetVV 0 07:50:16 Reintegrate 8 07:50:16 OpenReintHandle 0 07:50:16 QueryReintHandle 0 07:50:16 SendReintFragment 0 07:50:16 CloseReintHandle 0 07:50:16 GetVolVS 6 07:50:16 ValidateVols 2 07:50:16 GetWBPermit 0 07:50:16 TossWBPermit 0 07:50:16 RejectWBPermit 0 07:50:16 GetAttrPlusSHA 118 07:50:16 ValidateAttrsPlusSHA 110 07:50:16 Total FetchDatas = 84, bytes transfered = 211490, transfer rate = 211490 bps 07:50:16 Fetched files <1k = 0; <8k = 83; <64k = 1; <512k = 0; >512k = 0. 07:50:16 Total StoreDatas = 4072, bytes transfered = 15812824, transfer rate = 1581282 bps 07:50:16 Stored files <1k = 2; <8k = 4070; <64k = 0; <512k = 0; >512k = 0. 07:50:16 Large vnode cache, 500 entries, 11 allocs, 20771 gets (11 reads), 16276 writes 07:50:16 Small vnode cache,500 entries, 4077 allocs, 17524 gets (654 reads), 20366 writes 07:50:16 Volume header cache, 50 entries, 24968 gets, 0 replacements 07:50:16 Partition /vicepa: 32298296K available (minfree=5%), 29764680K free. Dirstats: get 0, put 0, flush 0 07:50:16 RPC Total bytes: sent = 3943110, received = 21801672 07:50:16 bytes sent: rpc = 3048364, multirpc = 0, sftp = 894746, sftp multicasted = 0 07:50:16 bytes received: rpc = 4857413, multirpc = 0, sftp = 16944259, sftp multicasted = 0 07:50:16 RPC Total packets: sent = 22166, received = 32267 07:50:16 packets sent: rpc = 13766, multirpc = 0, sftp = 8400, sftp multicasted = 0 07:50:16 packets received: rpc = 13813, multirpc = 0, sftp = 18454, sftp multicasted = 0 07:50:16 RPC Packets retried = 20, Invalid packets received = 749, Busies sent = 632 07:50:16 RPC Requests 13555, Good Requests 12877, Replies 187, Busies 0 07:50:16 RPC Counters: CCount 19; Unbinds 9; FConns 9; AConns 28; GCConns 0 07:50:16 RPC Creation counts: Conn 20; SL 24; PB Small 9, Med 12, Large 8; SS 3 07:50:16 RPC2 In Use: Conn 19; SS 3 07:50:16 RPC2 PB: InUse 8, Hold 0, Freeze 0, SFree 3, MFree 10, LFree 8 07:50:16 RPC2 HW: Freeze 0, Hold 4 07:50:16 SFTP: datas 248, datar 18369, acks 4078, ackr 85, retries 0, duplicates 0 07:50:16 SFTP: timeouts 0, windowfulls 0, bogus 0, didpiggy 6 07:50:16 Total CB entries= 5189, blocks = 6; and total file entries = 4648, blocks = 22 07:50:16 There are currently 15 connections in use 07:50:16 There are 2 workstations and 2 are active (req in < 15 mins) 07:50:16 Ether Total bytes: sent = 0, received = 0 07:50:16 Ether Packets: sent = 0, received = 0, errors = 0 07:50:16 Printing RVM statistics Transaction statistics current cumulative Started: 409 61742 Aborted: 0 0 Committed, flush: 359 54839 Committed, no_flush: 50 6903 Total committed: 409 61742 Committed, but not flushed: 0 Unflushed transactions length: 0 Not committed: 0 Split by log wrap: 0 4 Delayed by truncation: 0 0 Log function statistics current cumulative rvm_flush calls: 0 1 Internal flushes, incl. commit: 359 54592 Total flushes: 359 54593 Average flush time (msec): 2 3 Last flush time (msec): 3 rvm_truncate calls: 2 Automatic truncations: 96 Forced synch. truncations: 0 Recovery truncations: 24 Total truncations: 122 Average truncation time (sec): 0 Last truncation time (sec): 0 Last tree build time (sec): 0 Last tree apply time (sec): 0 Transaction records: 409 61746 Bookeeping records: 1 123 Log wrap-arounds: 0 4 Total records: 410 61873 Log used: 1% 5% Log written (bytes): 549812 154241500 Timing Histograms Current Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 359 1 0 0 0 0 0 0 0 0 Cummulative Flush Timings (msec): <=25 <=50 <=100 <=250 <=500 <=1000 <=2500 <=5000 <=10000 > 10000 54163 47 19 0 0 0 0 0 0 0 Truncation Timings for Tree Build (sec): <=1 <=10 <=100 <=500 > 500 125 0 0 0 0 Truncation Timings for Tree Apply (sec): <=1 <=10 <=100 <=500 > 500 124 0 1 0 0 Total Truncation Timings (sec): <=1 <=10 <=100 <=500 > 500 124 0 1 0 0 Transaction Optimization Statistics current cumulative Ranges eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Avg. number eliminated per transaction Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Range length eliminated Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Log savings Range coalesce: 0 0 Trans coalesce: 0 0 Totals: 0 0 Transactions coalesced per flush: 0 0 Tranasction Modification Range Distributions Current Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 460 106 202 29 108 268 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 214 111 107 0 0 Cumulative Range Lengths (bytes): <=0 <=4 <=8 <=16 <=32 <=64 <=128 0 75922 17142 27163 2953 15225 39784 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 29580 15415 50969 3 2 Current Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 411 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 411 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 822 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Cumulative Range Lengths Eliminated (bytes): Range coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 61051 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Trans coalesce: <=0 <=4 <=8 <=16 <=32 <=64 <=128 61051 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Totals: <=0 <=4 <=8 <=16 <=32 <=64 <=128 122102 0 0 0 0 0 0 <=256 <=512 <=1024 <=2048 <=4096 > 4096 0 0 0 0 0 0 Current Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 411 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 411 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 822 0 0 0 0 0 Cummulative Number of Eliminated Ranges per Transaction Range coalesce: <=0 <=5 <=10 <=50 <=100 > 100 61051 0 0 0 0 0 Trans coalesce: <=0 <=5 <=10 <=50 <=100 > 100 61051 0 0 0 0 0 Totals: <=0 <=5 <=10 <=50 <=100 > 100 122102 0 0 0 0 0 Cummulative Number of Transactions Coalesced per flush Cycle <=0 <=5 <=10 <=50 <=100 > 100 61462 0 0 0 0 0 07:50:16 Printing RDS statistics Number of Free bytes: 3fecfea0 Alloced bytes: 2fe00 Mallocs: 8539 Frees: 7882 Preallocs: 0 Hits: 4838 Misses: 3696 Large Hits: 0 Large Misses: 5 Coalesces: 6902 Merges 3008 Not Merged: 236460 Times the Large List pointer has changed: 0 07:50:16 done 07:50:16 VShutdown: shutting down on-line volumes... 07:50:16 VShutdown: Taking volume coda.root.0(0x1000003) offline... 07:50:41 Building callback conn. 08:06:38 SmonDaemon timer expired 08:06:38 Entered CheckRVMResStat 08:06:38 Starting SmonDaemon timer 09:06:38 SmonDaemon timer expired 09:06:38 Entered CheckRVMResStat 09:06:38 Starting SmonDaemon timer 10:06:38 SmonDaemon timer expired 10:06:38 Entered CheckRVMResStat 10:06:38 Starting SmonDaemon timer