From owner-freebsd-questions@FreeBSD.ORG Wed Feb 18 08:08:53 2004 Return-Path: Delivered-To: freebsd-questions@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 57AE316A4CE for ; Wed, 18 Feb 2004 08:08:53 -0800 (PST) Received: from mail019.syd.optusnet.com.au (mail019.syd.optusnet.com.au [211.29.132.73]) by mx1.FreeBSD.org (Postfix) with ESMTP id 461DF43D1D for ; Wed, 18 Feb 2004 08:08:52 -0800 (PST) (envelope-from tfrank@optushome.com.au) Received: from marvin.home.local (c211-28-241-189.eburwd5.vic.optusnet.com.au [211.28.241.189])i1IG8mB13550 for ; Thu, 19 Feb 2004 03:08:49 +1100 Received: by marvin.home.local (Postfix, from userid 1001) id 477A0156; Thu, 19 Feb 2004 03:08:46 +1100 (EST) Date: Thu, 19 Feb 2004 03:08:45 +1100 From: Tony Frank To: freebsd-questions@freebsd.org Message-ID: <20040218160845.GA6332@marvin.home.local> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.4.2i Subject: 4.9-stable system lockup with vinum raid5 activity X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 18 Feb 2004 16:08:53 -0000 Hi all, I'm running 4.9-STABLE built 17th Feb based on cvsup on same day. Custom kernel in use with device polling enabled on fxp0. Kernel config is attached in case anyone can spot anything obvious there. It's an 'older' system, Pentium2-200, 132mb ram, basic Asus slot1 m/b (Via chipset) with 2 ide/ata disks (ad0, ad2) Also has a adaptec 2940UW SCSI (ahc0) with 4x4g scsi drives (da0-da3) kernel + vinum loaded via loader.conf with vinum root environment built around ad0 & ad2. See some other messages in questions regarding exact build of this box due to previous problems with vinum & raid5 volume. First I noticed fsck had errors right after I newfs'd my raid5 volume. I let fsck fix the errors and mounted the volume. I then copied some test data across and while this appeared to work, the md5 checksum of the files copied across no longer matches my original md5 records taken from both a separate system (transferred via ftp) and from another volume (a vinum mirror) on the same system. My test data is an iso CD image + a tar archive containing /usr/obj from my build system. Around 1gig all up and lots of files/dirs in the tar file. I then tried extracting the tar archive and after about 20 mins the system appeared to freeze. At this time vty switching was still working and I noticed the following on the console: (hand copy) devstat_end_transaction: HELP!! busy_count for da2 is < 0 (-1)! devstat_end_transaction: HELP!! busy_count for da2 is < 0 (-1)! devstat_end_transaction: HELP!! busy_count for da3 is < 0 (-1)! devstat_end_transaction: HELP!! busy_count for da3 is < 0 (-1)! devstat_end_transaction: HELP!! busy_count for da3 is < 0 (-2)! ahc0: Timedout SCB already complete. Interrupts may not be functioning. ahc0: Timedout SCB already complete. Interrupts may not be functioning. ahc0: Timedout SCB already complete. Interrupts may not be functioning. ahc0: Timedout SCB already complete. Interrupts may not be functioning. ahc0: Timedout SCB already complete. Interrupts may not be functioning. ahc0: Timedout SCB already complete. Interrupts may not be functioning. I tried a few commands but while the first few went through any new command I ran through the console appeared to pause for ~5 mins before running, eg "vmstat -i" Pressing ctrl-t on the console for vmstat shows: load: 0.00 cmd: vmstat 455 [flswai] 0.00u 0.01s 0% 472k I eventually pressed 'ctl-alt-del' (no debugger in this kernel) and after ~20 mins the box has now rebooted but did no restart. As it is a test system I am now going to further investigate in the morning. Full history of what I was doing: raider# umount /data raider# newfs -v /dev/vinum/data Warning: Block size and bytes per inode restrict cylinders per group to 22. Warning: 1856 sector(s) in last cylinder unallocated /dev/vinum/data: 35211456 sectors in 8597 cylinders of 1 tracks, 4096 sectors 17193.1MB in 391 cyl groups (22 c/g, 44.00MB/g, 10944 i/g) super-block backups (for fsck -b #) at: 32, 90144, 180256, 270368, 360480, 450592, 540704, 630816, 720928, 811040, 901152, 991264, 1081376, 1171488, 1261600, 1351712, 1441824, 1531936, 1622048, 1712160, 1802272, 1892384, 1982496, 2072608, 2162720, 2252832, 2342944, 2433056, 2523168, 2613280, 2703392, 2793504, 2883616, 2973728, 3063840, 3153952, 3244064, 3334176, 3424288, 3514400, 3604512, 3694624, 3784736, 3874848, 3964960, 4055072, 4145184, 4235296, 4325408, 4415520, 4505632, 4595744, 4685856, 4775968, 4866080, 4956192, 5046304, 5136416, 5226528, 5316640, 5406752, 5496864, 5586976, 5677088, 5767200, 5857312, 5947424, 6037536, 6127648, 6217760, 6307872, 6397984, 6488096, 6578208, 6668320, 6758432, 6848544, 6938656, 7028768, 7118880, 7208992, 7299104, 7389216, 7479328, 7569440, 7659552, 7749664, 7839776, 7929888, 8020000, 8110112, 8200224, 8290336, 8380448, 8470560, 8560672, 8650784, 8740896, 8831008, 8921120, 9011232, 9101344, 9191456, 9281568, 9371680, 9461792, 9551904, 9642016, 9732128, 9822240, 9912352, 10002464, 10092576, 10182688, 10272800, 10362912, 10453024, 10543136, 10633248, 10723360, 10813472, 10903584, 10993696, 11083808, 11173920, 11264032, 11354144, 11444256, 11534368, 11624480, 11714592, 11804704, 11894816, 11984928, 12075040, 12165152, 12255264, 12345376, 12435488, 12525600, 12615712, 12705824, 12795936, 12886048, 12976160, 13066272, 13156384, 13246496, 13336608, 13426720, 13516832, 13606944, 13697056, 13787168, 13877280, 13967392, 14057504, 14147616, 14237728, 14327840, 14417952, 14508064, 14598176, 14688288, 14778400, 14868512, 14958624, 15048736, 15138848, 15228960, 15319072, 15409184, 15499296, 15589408, 15679520, 15769632, 15859744, 15949856, 16039968, 16130080, 16220192, 16310304, 16400416, 16490528, 16580640, 16670752, 16760864, 16850976, 16941088, 17031200, 17121312, 17211424, 17301536, 17391648, 17481760, 17571872, 17661984, 17752096, 17842208, 17932320, 18022432, 18112544, 18202656, 18292768, 18382880, 18472992, 18563104, 18653216, 18743328, 18833440, 18923552, 19013664, 19103776, 19193888, 19284000, 19374112, 19464224, 19554336, 19644448, 19734560, 19824672, 19914784, 20004896, 20095008, 20185120, 20275232, 20365344, 20455456, 20545568, 20635680, 20725792, 20815904, 20906016, 20996128, 21086240, 21176352, 21266464, 21356576, 21446688, 21536800, 21626912, 21717024, 21807136, 21897248, 21987360, 22077472, 22167584, 22257696, 22347808, 22437920, 22528032, 22618144, 22708256, 22798368, 22888480, 22978592, 23068704, 23158816, 23248928, 23339040, 23429152, 23519264, 23609376, 23699488, 23789600, 23879712, 23969824, 24059936, 24150048, 24240160, 24330272, 24420384, 24510496, 24600608, 24690720, 24780832, 24870944, 24961056, 25051168, 25141280, 25231392, 25321504, 25411616, 25501728, 25591840, 25681952, 25772064, 25862176, 25952288, 26042400, 26132512, 26222624, 26312736, 26402848, 26492960, 26583072, 26673184, 26763296, 26853408, 26943520, 27033632, 27123744, 27213856, 27303968, 27394080, 27484192, 27574304, 27664416, 27754528, 27844640, 27934752, 28024864, 28114976, 28205088, 28295200, 28385312, 28475424, 28565536, 28655648, 28745760, 28835872, 28925984, 29016096, 29106208, 29196320, 29286432, 29376544, 29466656, 29556768, 29646880, 29736992, 29827104, 29917216, 30007328, 30097440, 30187552, 30277664, 30367776, 30457888, 30548000, 30638112, 30728224, 30818336, 30908448, 30998560, 31088672, 31178784, 31268896, 31359008, 31449120, 31539232, 31629344, 31719456, 31809568, 31899680, 31989792, 32079904, 32170016, 32260128, 32350240, 32440352, 32530464, 32620576, 32710688, 32800800, 32890912, 32981024, 33071136, 33161248, 33251360, 33341472, 33431584, 33521696, 33611808, 33701920, 33792032, 33882144, 33972256, 34062368, 34152480, 34242592, 34332704, 34422816, 34512928, 34603040, 34693152, 34783264, 34873376, 34963488, 35053600, 35143712 raider# tunefs -n enable /dev/vinum/data tunefs: soft updates set raider# fsck /dev/vinum/data ** /dev/vinum/data ** Last Mounted on ** Phase 1 - Check Blocks and Sizes PARTIALLY ALLOCATED INODE I=52408 UNEXPECTED SOFT UPDATE INCONSISTENCY CLEAR? [yn] y UNKNOWN FILE TYPE I=52409 UNEXPECTED SOFT UPDATE INCONSISTENCY CLEAR? [yn] y PARTIALLY ALLOCATED INODE I=970704 UNEXPECTED SOFT UPDATE INCONSISTENCY CLEAR? [yn] ^C ***** FILE SYSTEM MARKED DIRTY ***** raider# fsck -y /dev/vinum/data ** /dev/vinum/data ** Last Mounted on ** Phase 1 - Check Blocks and Sizes PARTIALLY ALLOCATED INODE I=970704 UNEXPECTED SOFT UPDATE INCONSISTENCY CLEAR? yes UNKNOWN FILE TYPE I=970705 UNEXPECTED SOFT UPDATE INCONSISTENCY CLEAR? yes PARTIALLY ALLOCATED INODE I=2916201 UNEXPECTED SOFT UPDATE INCONSISTENCY CLEAR? yes ** Phase 2 - Check Pathnames ** Phase 3 - Check Connectivity ** Phase 4 - Check Reference Counts ** Phase 5 - Check Cyl groups 1 files, 1 used, 17064560 free (8 frags, 2133069 blocks, 0.0% fragmentation) ***** FILE SYSTEM MARKED CLEAN ***** ***** FILE SYSTEM WAS MODIFIED ***** raider# fsck -y /dev/vinum/data ** /dev/vinum/data ** Last Mounted on ** Phase 1 - Check Blocks and Sizes ** Phase 2 - Check Pathnames ** Phase 3 - Check Connectivity ** Phase 4 - Check Reference Counts ** Phase 5 - Check Cyl groups 1 files, 1 used, 17064560 free (8 frags, 2133069 blocks, 0.0% fragmentation) raider# mount /data raider# tar cf - -C /usr/tmp . | tar xpf - -C /data raider# tar cf - -C /usr/tmp . | tar xpf - -C /data raider# pwd /usr/tmp raider# cd /data raider# ll total 1046006 -rw-r--r-- 1 root wheel 510709760 Feb 7 15:12 objtest.tar -rw-r--r-- 1 root wheel 53 Feb 19 01:20 objtest.tar.d.md5 -rw-r--r-- 1 root wheel 53 Feb 19 01:00 objtest.tar.md5 -rw-r--r-- 1 root wheel 53 Feb 19 01:04 objtest.tar.r.md5 -rw-r--r-- 1 root wheel 559839232 Apr 13 2003 otest.iso -rw-r--r-- 1 root wheel 54 Feb 19 01:21 otest.iso.d.md5 -rw-r--r-- 1 root wheel 54 Feb 19 01:00 otest.iso.md5 -rw-r--r-- 1 root wheel 54 Feb 19 01:07 otest.iso.r.md5 raider# md5 otest.iso > /usr/tmp/otest.iso.d.md5 & [1] 398 raider# md5 objtest.tar > /usr/tmp/objtest.tar.d.md5 & [2] 399 raider# fg md5 otest.iso > /usr/tmp/otest.iso.d.md5 raider# [2] Done md5 objtest.tar > /usr/tmp/objtest.tar.d.md5 raider# cd /usr/tmp raider# ll total 1046006 -rw-r--r-- 1 root wheel 510709760 Feb 7 15:12 objtest.tar -rw-r--r-- 1 root wheel 53 Feb 19 01:51 objtest.tar.d.md5 -rw-r--r-- 1 root wheel 53 Feb 19 01:00 objtest.tar.md5 -rw-r--r-- 1 root wheel 53 Feb 19 01:04 objtest.tar.r.md5 -rw-r--r-- 1 root wheel 559839232 Apr 13 2003 otest.iso -rw-r--r-- 1 root wheel 54 Feb 19 01:51 otest.iso.d.md5 -rw-r--r-- 1 root wheel 54 Feb 19 01:00 otest.iso.md5 -rw-r--r-- 1 root wheel 54 Feb 19 01:07 otest.iso.r.md5 raider# diff otest.iso.d.md5 otest.iso.r.md5 1c1 < MD5 (otest.iso) = f3b9f26df24416227d6f9734c858ee49 --- > MD5 (otest.iso) = 41ab9f997013558fdc9bf656ce570c64 raider# diff objtest.tar.d.md5 objtest.tar.r.md5 1c1 < MD5 (objtest.tar) = af81d3a24a9eec107a8bf14b3a8cc4bf --- > MD5 (objtest.tar) = e09df10d7a58ab2db661803750c8764d raider# pwd /usr/tmp raider# cd / raider# umount /data raider# fsck -y /data ** /dev/vinum/data ** Last Mounted on /data ** Phase 1 - Check Blocks and Sizes ** Phase 2 - Check Pathnames ** Phase 3 - Check Connectivity ** Phase 4 - Check Reference Counts ** Phase 5 - Check Cyl groups 9 files, 1046007 used, 16018554 free (2 frags, 2002319 blocks, 0.0% fragmentation) raider# mount /data raider# cd /data raider# ls objtest.tar objtest.tar.md5 otest.iso otest.iso.md5 objtest.tar.d.md5 objtest.tar.r.md5 otest.iso.d.md5 otest.iso.r.md5 raider# ls -al total 1046008 drwxr-xr-x 2 root wheel 512 Feb 19 01:46 . drwxr-xr-x 19 root wheel 512 Feb 18 15:30 .. -rw-r--r-- 1 root wheel 510709760 Feb 7 15:12 objtest.tar -rw-r--r-- 1 root wheel 53 Feb 19 01:20 objtest.tar.d.md5 -rw-r--r-- 1 root wheel 53 Feb 19 01:00 objtest.tar.md5 -rw-r--r-- 1 root wheel 53 Feb 19 01:04 objtest.tar.r.md5 -rw-r--r-- 1 root wheel 559839232 Apr 13 2003 otest.iso -rw-r--r-- 1 root wheel 54 Feb 19 01:21 otest.iso.d.md5 -rw-r--r-- 1 root wheel 54 Feb 19 01:00 otest.iso.md5 -rw-r--r-- 1 root wheel 54 Feb 19 01:07 otest.iso.r.md5 raider# tar xf objtest.tar vinum setup: 6 drives: D vinumdrive0 State: up Device /dev/ad0s1h Avail: 0/8055 MB (0%) D vinumdrive5 State: up Device /dev/ad2s1h Avail: 0/3093 MB (0%) D vinumdrive1 State: up Device /dev/da0s1h Avail: 0/4298 MB (0%) D vinumdrive2 State: up Device /dev/da1s1h Avail: 0/4298 MB (0%) D vinumdrive3 State: up Device /dev/da2s1h Avail: 0/4298 MB (0%) D vinumdrive4 State: up Device /dev/da3s1h Avail: 0/4298 MB (0%) 7 volumes: V root State: up Plexes: 2 Size: 256 MB V swap State: up Plexes: 2 Size: 256 MB V var State: up Plexes: 2 Size: 256 MB V tmp State: up Plexes: 2 Size: 256 MB V usr State: up Plexes: 2 Size: 2069 MB V data State: up Plexes: 1 Size: 16 GB V junk State: up Plexes: 1 Size: 664 MB 12 plexes: P root.p0 C State: up Subdisks: 1 Size: 256 MB P swap.p0 C State: up Subdisks: 1 Size: 256 MB P var.p0 C State: up Subdisks: 1 Size: 256 MB P tmp.p0 C State: up Subdisks: 1 Size: 256 MB P usr.p0 C State: up Subdisks: 1 Size: 2069 MB P root.p1 C State: up Subdisks: 1 Size: 256 MB P swap.p1 C State: up Subdisks: 1 Size: 256 MB P var.p1 C State: up Subdisks: 1 Size: 256 MB P tmp.p1 C State: up Subdisks: 1 Size: 256 MB P usr.p1 C State: up Subdisks: 1 Size: 2069 MB P data.p0 R5 State: up Subdisks: 5 Size: 16 GB P junk.p0 C State: up Subdisks: 1 Size: 664 MB 16 subdisks: S root.p0.s0 State: up PO: 0 B Size: 256 MB S swap.p0.s0 State: up PO: 0 B Size: 256 MB S var.p0.s0 State: up PO: 0 B Size: 256 MB S tmp.p0.s0 State: up PO: 0 B Size: 256 MB S usr.p0.s0 State: up PO: 0 B Size: 2069 MB S root.p1.s0 State: up PO: 0 B Size: 256 MB S swap.p1.s0 State: up PO: 0 B Size: 256 MB S var.p1.s0 State: up PO: 0 B Size: 256 MB S tmp.p1.s0 State: up PO: 0 B Size: 256 MB S usr.p1.s0 State: up PO: 0 B Size: 2069 MB S data.p0.s0 State: up PO: 0 B Size: 4298 MB S data.p0.s1 State: up PO: 492 kB Size: 4298 MB S data.p0.s2 State: up PO: 984 kB Size: 4298 MB S data.p0.s3 State: up PO: 1476 kB Size: 4298 MB S data.p0.s4 State: up PO: 1968 kB Size: 4298 MB S junk.p0.s0 State: up PO: 0 B Size: 664 MB My kernel config file RAIDER: machine i386 cpu I686_CPU ident RAIDER maxusers 0 options NO_F00F_HACK #makeoptions DEBUG=-g #Build kernel with gdb(1) debug symbols options INCLUDE_CONFIG_FILE options DEVICE_POLLING options HZ=1000 options DUMMYNET options IPSTEALTH options IPDIVERT options IPFIREWALL_FORWARD options IPFIREWALL_VERBOSE options IPFIREWALL options IPFW2 options RANDOM_IP_ID options IPSEC_ESP options IPSEC options INET #InterNETworking options FFS #Berkeley Fast Filesystem options FFS_ROOT #FFS usable as root device [keep this!] options SOFTUPDATES #Enable FFS soft updates support options UFS_DIRHASH #Improve performance on big directories options MFS options MD_ROOT options NFS #Network Filesystem options NFS_ROOT #NFS usable as root device, NFS required options PROCFS #Process filesystem options COMPAT_43 #Compatible with BSD 4.3 [KEEP THIS!] options SCSI_DELAY=9000 #Delay (in ms) before probing SCSI options UCONSOLE #Allow users to grab the console options USERCONFIG #boot -c editor options KTRACE #ktrace(1) support options SYSVSHM #SYSV-style shared memory options SYSVMSG #SYSV-style message queues options SYSVSEM #SYSV-style semaphores options P1003_1B #Posix P1003_1B real-time extensions options _KPOSIX_PRIORITY_SCHEDULING options ICMP_BANDLIM #Rate limit bad replies options KBD_INSTALL_CDEV # install a CDEV entry in /dev options AHC_REG_PRETTY_PRINT # Print register bitfields in debug # output. Adds ~128k to driver. device isa device pci options PCI_ENABLE_IO_MODES # Floppy drives device fdc0 at isa? port IO_FD1 irq 6 drq 2 device fd0 at fdc0 drive 0 # ATA and ATAPI devices device ata device atadisk # ATA disk drives device atapicd # ATAPI CDROM drives device atapicam options ATA_STATIC_ID #Static device numbering # SCSI Controllers device ahc # AHA2940 and onboard AIC7xxx devices options AHC_ALLOW_MEMIO # SCSI peripherals device scbus # SCSI bus (required) device da # Direct Access (disks) device cd # CD device pass # Passthrough device (direct SCSI access) # atkbdc0 controls both the keyboard and the PS/2 mouse device atkbdc0 at isa? port IO_KBD device atkbd0 at atkbdc? irq 1 flags 0x1 device psm0 at atkbdc? irq 12 device vga0 at isa? # splash screen/screen saver pseudo-device splash options VESA # syscons is the default console driver, resembling an SCO console device sc0 at isa? flags 0x100 options SC_HISTORY_SIZE=1024 device agp # support several AGP chipsets # Floating point support - do not disable. device npx0 at nexus? port IO_NPX irq 13 # Power management support (see LINT for more options) device apm0 at nexus? # Advanced Power Management # Serial (COM) ports device sio0 at isa? port IO_COM1 flags 0x10 irq 4 device sio1 at isa? port IO_COM2 irq 3 # Parallel port device ppc0 at isa? irq 7 device ppbus # Parallel port bus (required) device lpt # Printer device ppi # Parallel port interface device # PCI Ethernet NICs that use the common MII bus controller code. # NOTE: Be sure to keep the 'device miibus' line in order to use these NICs! device miibus # MII bus support device fxp # Intel EtherExpress PRO/100B (82557, 82558) # Pseudo devices - the number indicates how many units to allocate. pseudo-device loop # Network loopback pseudo-device ether # Ethernet support pseudo-device tun # Packet tunnel. pseudo-device pty # Pseudo-ttys (telnet etc) pseudo-device md # Memory "disks" pseudo-device gif # IPv6 and IPv4 tunneling pseudo-device faith 1 # IPv6-to-IPv4 relaying (translation) pseudo-device vn # The `bpf' pseudo-device enables the Berkeley Packet Filter. # Be aware of the administrative consequences of enabling this! pseudo-device bpf #Berkeley packet filter Thanks, Tony