Xsan Storage Error

[nksvijayan]

Hi,
We are facing this problem from 3 month, we have 2 storages EDIT & NEWS. In that EDIT storage only some time (4 to 6 time in a month) fail over from mdc1 to mdc2, or mdc2 to mdc1.

Configuration :
Xserve Quad Intel Xeon
Mac os x Server : 10.5.8 Ver
Promise VTrak E610f
Xsan Ver : 2.1

i have copied some logs from mdc1 CV Logs reports..

if any one have solution for this.. help me..




[0909 00:30:24.121019] 0xa01d8720 (Debug) FSM memory SUMMARY resident size 158MB.
[0909 00:30:24.121024] 0xa01d8720 (Debug) FSM I/O SUMMARY writes total/40657.
[0909 00:30:24.121027] 0xa01d8720 (Debug) FSM I/O SUMMARY writes journal/12728 sb/0 buf/24157 abm/663.
[0909 00:30:24.121032] 0xa01d8720 (Debug) FSM I/O SUMMARY writes inode/22077 ganged/28158 (3.99%).
[0909 00:30:24.121035] 0xa01d8720 (Debug) FSM wait SUMMARY inode pool expand waits/0.
[0909 00:30:24.121038] 0xa01d8720 (Debug) FSM wait SUMMARY journal waits/0.
[0909 00:30:24.121042] 0xa01d8720 (Debug) FSM wait SUMMARY journal bytes used avg/668861 max/5392384.
[0909 00:30:24.121045] 0xa01d8720 (Debug) FSM wait SUMMARY free buffer waits/0.
[0909 00:30:24.121047] 0xa01d8720 (Debug) FSM wait SUMMARY free inode waits/0.
[0909 00:30:24.121052] 0xa01d8720 (Debug) FSM wait SUMMARY revokes/39 avg/502 min/290 max/707.
[0909 00:30:24.121056] 0xa01d8720 (Debug) FSM threads SUMMARY max busy hi-prio/28 lo-prio/6.
[0909 00:30:24.121059] 0xa01d8720 (Debug) FSM threads SUMMARY max busy dmig/0 events/0.
[0909 00:30:24.121070] 0xa01d8720 (Debug) FSM msg queue SUMMARY hi-prio now/0 min/0 max/14.
[0909 00:30:24.121074] 0xa01d8720 (Debug) FSM msg queue SUMMARY lo-prio now/0 min/0 max/4.
[0909 00:30:24.121077] 0xa01d8720 (Debug) FSM msg queue SUMMARY dmig now/0 min/0 max/0.
[0909 00:30:24.121080] 0xa01d8720 (Debug) FSM msg queue SUMMARY events now/0 min/0 max/0.
[0909 00:30:24.121084] 0xa01d8720 (Debug) FSM cache SUMMARY inode lookups/550886 misses/8671 hits/98.43%.
[0909 00:30:24.121088] 0xa01d8720 (Debug) FSM cache SUMMARY free incore inodes now/8192 min/7592 max/8192.
[0909 00:30:24.121091] 0xa01d8720 (Debug) FSM cache SUMMARY buffer lookups/227786 misses/5707 hits/97.49%.
[0909 00:30:24.121095] 0xa01d8720 (Debug) FSM cache SUMMARY free buffers now/2048 min/2037 max/2048.
[0909 00:30:24.121098] 0xa01d8720 (Debug) FSM cache SUMMARY attrs now/-5 min/69 max/-5.
[0909 00:30:24.121102] 0xa01d8720 (Debug) FSM extent SUMMARY extent lookups/100099 misses/75 hits/99.93%.
[0909 00:30:24.121106] 0xa01d8720 (Debug) FSM extent SUMMARY hint tries/17702 misses/14933 hits/15.64%.
[0909 00:30:24.121111] 0xa01d8720 (Debug) VOP SUMMARY Setattr cnt/32654 avg/129 min/12 max/98578.
[0909 00:30:24.121116] 0xa01d8720 (Debug) VOP SUMMARY Rmdir cnt/4 avg/4308 min/669 max/14638.
[0909 00:30:24.121121] 0xa01d8720 (Debug) VOP SUMMARY Remove cnt/27 avg/1312 min/632 max/8758.
[0909 00:30:24.121125] 0xa01d8720 (Debug) VOP SUMMARY Rename cnt/23 avg/262 min/166 max/832.
[0909 00:30:24.121130] 0xa01d8720 (Debug) VOP SUMMARY AllocSpace cnt/4 avg/880 min/596 max/1339.
[0909 00:30:24.121134] 0xa01d8720 (Debug) VOP SUMMARY Open cnt/28109 avg/46 min/13 max/26009.
[0909 00:30:24.121139] 0xa01d8720 (Debug) VOP SUMMARY Close cnt/28316 avg/71 min/13 max/38749.
[0909 00:30:24.121144] 0xa01d8720 (Debug) VOP SUMMARY PunchHoleApi cnt/13 avg/840 min/418 max/2596.
[0909 00:30:24.121148] 0xa01d8720 (Debug) VOP SUMMARY GetNTSecurity cnt/96 avg/12105 min/34 max/47145.
[0909 00:30:24.121153] 0xa01d8720 (Debug) VOP SUMMARY SetNTSecurity cnt/2 avg/36931 min/26528 max/47334.
[0909 00:30:24.121157] 0xa01d8720 (Debug) VOP SUMMARY Flush2pc cnt/3832 avg/1554 min/7 max/12663.
[0909 00:30:24.121162] 0xa01d8720 (Debug) VOP SUMMARY Getquota cnt/268 avg/42 min/24 max/213.
[0909 00:30:24.121166] 0xa01d8720 (Debug) VOP SUMMARY CreateV3 cnt/22 avg/438 min/121 max/4343.
[0909 00:30:24.121171] 0xa01d8720 (Debug) VOP SUMMARY OpenRet cnt/39 avg/8 min/7 max/12.
[0909 00:30:24.121175] 0xa01d8720 (Debug) VOP SUMMARY VopGetattrV4 cnt/4 avg/192 min/131 max/258.
[0909 00:30:24.121179] 0xa01d8720 (Debug) VOP SUMMARY VopLookupV4 cnt/42901 avg/337 min/16 max/81781.
[0909 00:30:24.121184] 0xa01d8720 (Debug) VOP SUMMARY VopReaddir2 cnt/5490 avg/1238 min/22 max/32213.
[0909 00:30:24.121189] 0xa01d8720 (Debug) VOP SUMMARY CreateV4 cnt/20 avg/1462 min/188 max/24762.
[0909 00:30:24.121193] 0xa01d8720 (Debug) VOP SUMMARY GetResyncAttr cnt/12 avg/122 min/17 max/842.
[0909 00:30:24.121197] 0xa01d8720 (Debug) VOP SUMMARY NotifyContMod cnt/12 avg/12 min/11 max/16.
[0909 00:30:24.121202] 0xa01d8720 (Debug) VOP SUMMARY GetLinkInfo cnt/122 avg/21 min/14 max/53.
[0909 00:30:24.121206] 0xa01d8720 (Debug) VOP SUMMARY TokenReturn cnt/53 avg/0 min/0 max/9.
[0909 00:30:24.121211] 0xa01d8720 (Debug) TKN SUMMARY TokenRequestV3 cnt/1535 avg/1020 min/12 max/39155.
[0909 00:30:24.121215] 0xa01d8720 (Debug) TKN SUMMARY OpenChange cnt/12236 avg/51 min/5 max/1895.
[0909 00:30:24.121220] 0xa01d8720 (Debug) TKN SUMMARY TokenChangeV4 cnt/33225 avg/72 min/7 max/38863.
[0909 00:30:24.121224] 0xa01d8720 (Debug) TKN SUMMARY TokenReqAlloc cnt/613 avg/2057 min/16 max/17953.
[0909 00:30:24.121233] 0xa01d8720 (Debug) BRL SUMMARY SetLock cnt/27998 avg/15 min/8 max/158.
[0909 00:30:24.121237] 0xa01d8720 (Debug) BRL SUMMARY ClearLock cnt/29875 avg/14 min/9 max/172.
[0909 00:30:24.121242] 0xa01d8720 (Debug) BRL SUMMARY ClearAll cnt/28 avg/16 min/11 max/27.
[0909 00:30:24.121252] 0xa01d8720 (Debug) SG SUMMARY MetadataAndJournal space total/698.48 GB free/695.34 GB (99.55%)
[0909 00:30:24.121259] 0xa01d8720 (Debug) SG SUMMARY MetadataAndJournal space minfree/695.34 GB (99.55%) maxfree/695.34 GB (99.55%)
[0909 00:30:24.121270] 0xa01d8720 (Debug) SG SUMMARY MetadataAndJournal alloc extent cnt/2 avgsize/16.00 KB.
[0909 00:30:24.121285] 0xa01d8720 (Debug) SG SUMMARY 165 btree free space fragments 323 splay tree fragments
[0909 00:30:24.121290] 0xa01d8720 (Debug) SG SUMMARY Data space total/6.82 TB free/2.25 TB (32.94%)
[0909 00:30:24.121296] 0xa01d8720 (Debug) SG SUMMARY Data space minfree/2.25 TB (32.94%) maxfree/2.26 TB (33.07%)
[0909 00:30:24.121301] 0xa01d8720 (Debug) SG SUMMARY Data alloc extent cnt/265 avgsize/37.19 MB.
[0909 00:30:24.121304] 0xa01d8720 (Debug) SG SUMMARY 57899 btree free space fragments 115787 splay tree fragments
[0909 00:30:24.121309] 0xa01d8720 (Debug) SG SUMMARY Data2 space total/16.37 TB free/2.25 TB (13.74%)
[0909 00:30:24.121315] 0xa01d8720 (Debug) SG SUMMARY Data2 space minfree/2.25 TB (13.74%) maxfree/2.25 TB (13.77%)
[0909 00:30:24.121319] 0xa01d8720 (Debug) SG SUMMARY Data2 alloc extent cnt/352 avgsize/17.09 MB.
[0909 00:30:24.121342] 0xa01d8720 (Debug) SG SUMMARY 445837 btree free space fragments 891668 splay tree fragments
[0909 00:30:24.121354] 0xa01d8720 (Debug) PIO HiPriWr SUMMARY VT2_MD_EDIT_R1 cnt/12751 maxq/0.
[0909 00:30:24.121360] 0xa01d8720 (Debug) PIO HiPriWr SUMMARY VT2_MD_EDIT_R1 avg/1080 min/312 max/96073.
[0909 00:30:24.121364] 0xa01d8720 (Debug) PIO HiPriWr SUMMARY VT2_MD_EDIT_R1 sysavg/1077 sysmin/311 sysmax/96071.
[0909 00:30:24.121369] 0xa01d8720 (Debug) PIO HiPriWr SUMMARY VT2_MD_EDIT_R1 avglen/2313 minlen/512 maxlen/32768.
[0909 00:30:24.121373] 0xa01d8720 (Debug) PIO Read SUMMARY VT2_MD_EDIT_R1 cnt/9348 maxq/5.
[0909 00:30:24.121377] 0xa01d8720 (Debug) PIO Read SUMMARY VT2_MD_EDIT_R1 avg/3990 min/102 max/205816.
[0909 00:30:24.121381] 0xa01d8720 (Debug) PIO Read SUMMARY VT2_MD_EDIT_R1 sysavg/3076 sysmin/89 sysmax/205806.
[0909 00:30:24.121385] 0xa01d8720 (Debug) PIO Read SUMMARY VT2_MD_EDIT_R1 avglen/10201 minlen/512 maxlen/16384.
[0909 00:30:24.121389] 0xa01d8720 (Debug) PIO Write SUMMARY VT2_MD_EDIT_R1 cnt/27928 maxq/4.
[0909 00:30:24.121394] 0xa01d8720 (Debug) PIO Write SUMMARY VT2_MD_EDIT_R1 avg/1299 min/311 max/112549.
[0909 00:30:24.121398] 0xa01d8720 (Debug) PIO Write SUMMARY VT2_MD_EDIT_R1 sysavg/1186 sysmin/303 sysmax/76334.
[0909 00:30:24.121402] 0xa01d8720 (Debug) PIO Write SUMMARY VT2_MD_EDIT_R1 avglen/14314 minlen/512 maxlen/16384.
[0909 00:30:24] 0xa01d8720 (Info) Exiting.
Logger_thread: sleeps/710744 signals/1 flushes/8516 writes/8517 switches 1
Logger_thread: logged/51922 clean/51922 toss/0 signalled/1 toss_message/0
Logger_thread: waited/0 awakened/0
[0909 01:18:40] 0xa01d8720 (Info) Server Revision 3.1.0 Build 2 (339.21)
[0909 01:18:40] 0xa01d8720 (Info) Built for Darwin 9.0 i386
[0909 01:18:40] 0xa01d8720 (Info) Created on Sun Jun 1 23:04:13 PDT 2008
[0909 01:18:40] 0xa01d8720 (Info) Built in /SourceCache/XsanFS/XsanFS-339.21
[0909 01:18:40] 0xa01d8720 (Info)
Configuration:
DiskTypes-7
Disks-7
StripeGroups-3
ForceStripeAlignment-1
MaxConnections-139
ThreadPoolSize-256
StripeAlignSize-32
FsBlockSize-16384
BufferCacheSize-32M
InodeCacheSize-8192
RestoreJournal-Disabled
RestoreJournalDir-None
[0909 01:18:40] 0xa01d8720 (Info) Self (mdc1.blrfrwl.aclnet.acl.com) IP address is 192.168.8.205.
[0909 01:18:40.043482] 0xa01d8720 (Debug) No fsports file - port range enforcement disabled.
[0909 01:18:40] 0xa01d8720 (Info) Listening on TCP socket mdc1.blrfrwl.aclnet.acl.com:49168
[0909 01:18:40] 0xa01d8720 (Info) Node [0] [mdc1.blrfrwl.aclnet.:49168] File System Manager Login.
[0909 01:18:40] 0xa01d8720 (Info) Service standing by on host 'mdc1.blrfrwl.aclnet.acl.com:49168'.
[0909 01:18:45.402456] 0xa01d8720 (Debug) FOUsurpCheck: read ARB info (pass 1): host (192.168.8.205:49167) conns 0 age 1347130825.00 secs his delta 0.00 secs my delta 5.00 secs.
[0909 01:18:45.402468] 0xa01d8720 (Debug) FOUsurpCheck: ARB is already mine.
[0909 01:18:45] 0xa01d8720 (Info) Branding Arbitration Block (attempt 1) votes 0.
[0909 01:18:47.403903] 0xa01d8720 (Debug) Cannot find fail over script [/Library/Filesystems/Xsan/bin/cvfail.mdc1.blrfrwl.aclnet.acl.com] - looking for generic script.
[0909 01:18:47] 0xa01d8720 (Info) Launching fail over script ["/Library/Filesystems/Xsan/bin/cvfail" mdc1.blrfrwl.aclnet.acl.com 49168 edit]
[0909 01:18:47.410522] 0xa01d8720 (Debug) Starting journal log recovery.
[0909 01:18:47.782469] 0xa01d8720 (Debug) Completed journal log recovery.


if suppose any one have solution for this.. help me..

Thanks
Viajyan S

[singlemalt]

Which part of the logs is giving you concern? As far as I can tell these all look
like normal log entries. From what I can tell the volume is somewhat fragmented and
I've not seen 165 btree free space fragments 323 splay tree fragments before but it
is an entry the hourly summary so that may not matter.
Is your concern that the volume occassionaly fails over?
Do you have system logs from when the volume failed over? We'll want part of the system log
on the mdc that was hosting the when the fail over occurred. So if the volume was being
hosted on mdc1.blrfrwl.aclnet and the volume failed over at 13:00 on Sept 17 then post
mdc1.blrfrwl.aclnet system log starting at about 12:55 through to 13:02 or so.

[cinesys-jdub]

As singlemalt said, this log shows only a clean failover. The nssdbg will talk about which client initiated the failover vote. Then you could look at the raslog to find out a possible reason. Also, if you are concerned about FS issues, you might want to shut the Volume down and run a cvfsck against it to verify if there are any inode issues or anything else that could potentially be causing the failovers.