From owner-freebsd-hackers Tue Sep 24 4: 1:48 2002 Delivered-To: freebsd-hackers@freebsd.org Received: from mx1.FreeBSD.org (mx1.FreeBSD.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 19F4537B404 for ; Tue, 24 Sep 2002 04:01:42 -0700 (PDT) Received: from sofia.digsys.bg (sofia.digsys.bg [193.68.3.250]) by mx1.FreeBSD.org (Postfix) with ESMTP id 6C6F043E77 for ; Tue, 24 Sep 2002 04:01:25 -0700 (PDT) (envelope-from alalev@uni-svishtov.bg) Received: from ns.uni-svishtov.bg (ns.uni-svishtov.bg [193.68.172.1]) by sofia.digsys.bg (8.9.0/8.9.0) with ESMTP id OAA16536 for ; Tue, 24 Sep 2002 14:01:18 +0300 (EEST) Received: from mail.uni-svishtov.bg (grinch.uni-svishtov.bg [193.68.172.9]) by ns.uni-svishtov.bg (8.12.3/8.12.3) with ESMTP id g8OB1H0j008521 for ; Tue, 24 Sep 2002 14:01:17 +0300 (EEST) (envelope-from alalev@uni-svishtov.bg) Received: from uni-svishtov.bg (lalev.uni-svishtov.bg [193.68.173.61]) by mail.uni-svishtov.bg (8.12.6/8.12.6) with ESMTP id g8OB1GjD070959 for ; Tue, 24 Sep 2002 14:01:17 +0300 (EEST) (envelope-from alalev@uni-svishtov.bg) Message-ID: <3D9045E1.7040302@uni-svishtov.bg> Date: Tue, 24 Sep 2002 14:00:49 +0300 From: Angelin Lazarov Lalev User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.0.0) Gecko/20020530 X-Accept-Language: en-us, en MIME-Version: 1.0 To: freebsd-hackers@freebsd.org Subject: What does this log mean (SCSI problem ?) Content-Type: text/plain; charset=us-ascii; format=flowed Content-Transfer-Encoding: 7bit Sender: owner-freebsd-hackers@FreeBSD.ORG Precedence: bulk List-ID: List-Archive: (Web Archive) List-Help: (List Instructions) List-Subscribe: List-Unsubscribe: X-Loop: FreeBSD.ORG I think I have a problem. From time to tme, apparently when the disk activity of my IBM SCSI disk becomes higher, all disk operations are suspended for about 30 seconds. After that all continues ok, but the following log messages are written to the syslog. Is that normal? Sep 18 16:39:53 ns1 /kernel: (da0:ahc0:0:6:0): SCB 0x15 - timed out Sep 18 16:40:11 ns1 /kernel: ahc0: Dumping Card State in Data-out phase, at SEQADDR 0x8c Sep 18 16:40:11 ns1 /kernel: ACCUM = 0x0, SINDEX = 0x22, DINDEX = 0xe4, ARG_2 = 0x5 Sep 18 16:40:11 ns1 /kernel: HCNT = 0x0 SCBPTR = 0x12 Sep 18 16:40:11 ns1 /kernel: SCSISEQ = 0x12, SBLKCTL = 0xa Sep 18 16:40:11 ns1 /kernel: DFCNTRL = 0x2c, DFSTATUS = 0x82 Sep 18 16:40:11 ns1 /kernel: LASTPHASE = 0x0, SCSISIGI = 0x4, SXFRCTL0 = 0x80 Sep 18 16:40:11 ns1 /kernel: SSTAT0 = 0x0, SSTAT1 = 0x2 Sep 18 16:40:11 ns1 /kernel: STACK == 0x8a, 0x64, 0x165, 0x0 Sep 18 16:40:11 ns1 /kernel: SCB count = 30 Sep 18 16:40:11 ns1 /kernel: Kernel NEXTQSCB = 17 Sep 18 16:40:11 ns1 /kernel: Card NEXTQSCB = 29 Sep 18 16:40:11 ns1 /kernel: QINFIFO entries: 29 0 4 8 7 23 28 5 24 18 9 25 15 1 2 11 10 3 16 22 19 27 Sep 18 16:40:11 ns1 /kernel: Waiting Queue entries: Sep 18 16:40:11 ns1 /kernel: Disconnected Queue entries: Sep 18 16:40:11 ns1 /kernel: QOUTFIFO entries: Sep 18 16:40:11 ns1 /kernel: Sequencer Free SCB List: 11 25 9 26 19 23 28 12 20 22 21 2 5 0 10 8 14 16 3 15 1 4 6 7 17 24 27 13 29 30 31 Sep 18 16:40:11 ns1 /kernel: Sequencer SCB Info: 0(c 0x60, s 0x67, l 0, t 0xff) 1(c 0x60, s 0x67, l 0, t 0xff) 2(c 0x60, s 0x67, l 0, t 0xff) 3(c 0x60, s 0x67, l 0, t 0x ff) 4(c 0x60, s 0x67, l 0, t 0xff) 5(c 0x60, s 0x67, l 0, t 0xff) 6(c 0x60, s 0x67, l 0, t 0xff) 7(c 0x60, s 0x67, l 0, t 0xff) 8(c 0x60, s 0x67, l 0, t 0xff) 9(c 0x60, s 0x67, l 0, t 0xff) 10(c 0x60, s 0x67, l 0, t 0xff) 11(c 0x62, s 0x67, l 0, t 0xff) 12(c 0x60, s 0x67, l 0, t 0xff) 13(c 0x60, s 0x67, l 0, t 0xff) 14(c 0x60, s 0x67, l 0, t 0xff) 15(c 0x60, s 0x67, l 0, t 0xff) 16(c 0x60, s 0x67, l 0, t 0xff) 17(c 0x60, s 0x67, l 0, t 0xff) 18(c 0x60, s 0x67, l 0, t 0x15) 19(c 0x60, s 0x67, l 0, t 0xf f) 20(c 0x60, s 0x67, l 0, t 0xff) 21(c 0x60, s 0x67, l 0, t 0xff) 22(c 0x60, s 0x67, l 0, t 0xff) 23(c 0x60, s 0x67, l 0, t 0xff) 24(c 0x60, s 0x67, l 0, t 0xff) 25(c 0 x60, s 0x67, l 0, t 0xff) 26(c 0x60, s 0x67, l 0, t 0xff) 27(c 0x60, s 0x67, l 0, t 0xff) 28(c 0x60, s 0x67, l 0, t 0xff) 29(c 0x0, s 0x67, l 0, t 0xff) 30(c 0x0, s 0x67 , l 0, t 0xff) 31(c 0x0, s 0x6 Sep 18 16:40:11 ns1 /kernel: t 0xff) Sep 18 16:40:11 ns1 /kernel: Pending list: 27(c 0x60, s 0x67, l 0), 19(c 0x62, s 0x67, l 0), 22(c 0x60, s 0x67, l 0), 16(c 0x60, s 0x67, l 0), 3(c 0x60, s 0x67, l 0), 10 (c 0x60, s 0x67, l 0), 11(c 0x60, s 0x67, l 0), 2(c 0x60, s 0x67, l 0), 1(c 0x60, s 0x67, l 0), 15(c 0x60, s 0x67, l 0), 25(c 0x60, s 0x67, l 0), 9(c 0x60, s 0x67, l 0), 18(c 0x60, s 0x67, l 0), 24(c 0x60, s 0x67, l 0), 5(c 0x60, s 0x67, l 0), 28(c 0x60, s 0x67, l 0), 23(c 0x60, s 0x67, l 0), 7(c 0x60, s 0x67, l 0), 8(c 0x60, s 0x67, l 0), 4(c 0x60, s 0x67, l 0), 0(c 0x60, s 0x67, l 0), 29(c 0x60, s 0x67, l 0), 21(c 0x60, s 0x67, l 0) Sep 18 16:40:11 ns1 /kernel: Kernel Free SCB list: 12 6 26 20 14 13 Sep 18 16:40:11 ns1 /kernel: sg[0] - Addr 0x60f5000 : Length 4096 Sep 18 16:40:11 ns1 /kernel: sg[1] - Addr 0x6a16000 : Length 4096 Sep 18 16:40:12 ns1 /kernel: sg[2] - Addr 0x6077000 : Length 4096 Sep 18 16:40:12 ns1 /kernel: sg[3] - Addr 0x6778000 : Length 4096 Sep 18 16:40:12 ns1 /kernel: (da0:ahc0:0:6:0): BDR message in message buffer Sep 18 16:40:12 ns1 /kernel: (da0:ahc0:0:6:0): SCB 0x15 - timed out Sep 18 16:40:12 ns1 /kernel: ahc0: Dumping Card State in Data-out phase, at SEQADDR 0x8b Sep 18 16:40:12 ns1 /kernel: ACCUM = 0x0, SINDEX = 0x22, DINDEX = 0xe4, ARG_2 = 0x5 Sep 18 16:40:12 ns1 /kernel: HCNT = 0x0 SCBPTR = 0x12 Sep 18 16:40:12 ns1 /kernel: SCSISEQ = 0x12, SBLKCTL = 0xa Sep 18 16:40:12 ns1 /kernel: DFCNTRL = 0x2c, DFSTATUS = 0x82 Sep 18 16:40:12 ns1 /kernel: LASTPHASE = 0x0, SCSISIGI = 0x14, SXFRCTL0 = 0x80 Sep 18 16:40:12 ns1 /kernel: SSTAT0 = 0x0, SSTAT1 = 0x2 Sep 18 16:40:12 ns1 /kernel: STACK == 0x8a, 0x64, 0x165, 0x0 Sep 18 16:40:12 ns1 /kernel: SCB count = 30 Sep 18 16:40:12 ns1 /kernel: Kernel NEXTQSCB = 17 Sep 18 16:40:12 ns1 /kernel: Card NEXTQSCB = 29 Sep 18 16:40:12 ns1 /kernel: QINFIFO entries: 29 0 4 8 7 23 28 5 24 18 9 25 15 1 2 11 10 3 16 22 19 27 Sep 18 16:40:12 ns1 /kernel: Waiting Queue entries: Sep 18 16:40:12 ns1 /kernel: Disconnected Queue entries: Sep 18 16:40:12 ns1 /kernel: QOUTFIFO entries: Sep 18 16:40:12 ns1 /kernel: Sequencer Free SCB List: 11 25 9 26 19 23 28 12 20 22 21 2 5 0 10 8 14 16 3 15 1 4 6 7 17 24 27 13 29 30 31 Sep 18 16:40:12 ns1 /kernel: Sequencer SCB Info: 0(c 0x60, s 0x67, l 0, t 0xff) 1(c 0x60, s 0x67, l 0, t 0xff) 2(c 0x60, s 0x67, l 0, t 0xff) 3(c 0x60, s 0x67, l 0, t 0x ff) 4(c 0x60, s 0x67, l 0, t 0xff) 5(c 0x60, s 0x67, l 0, t 0xff) 6(c 0x60, s 0x67, l 0, t 0xff) 7(c 0x60, s 0x67, l 0, t 0xff) 8(c 0x60, s 0x67, l 0, t 0xff) 9(c 0x60, s 0x67, l 0, t 0xff) 10(c 0x60, s 0x67, l 0, t 0xff) 11(c 0x62, s 0x67, l 0, t 0xff) 12(c 0x60, s 0x67, l 0, t 0xff) 13(c 0x60, s 0x67, l 0, t 0xff) 14(c 0x60, s 0x67, l 0, t 0xff) 15(c 0x60, s 0x67, l 0, t 0xff) 16(c 0x60, s 0x67, l 0, t 0xff) 17(c 0x60, s 0x67, l 0, t 0xff) 18(c 0x60, s 0x67, l 0, t 0x15) 19(c 0x60, s 0x67, l 0, t 0xf f) 20(c 0x60, s 0x67, l 0, t 0xff) 21(c 0x60, s 0x67, l 0, t 0xff) 22(c 0x60, s 0x67, l 0, t 0xff) 23(c 0x60, s 0x67, l 0, t 0xff) 24(c 0x60, s 0x67, l 0, t 0xff) 25(c 0 x60, s 0x67, l 0, t 0xff) 26(c 0x60, s 0x67, l 0, t 0xff) 27(c 0x60, s 0x67, l 0, t 0xff) 28(c 0x60, s 0x67, l 0, t 0xff) 29(c 0x0, s 0x67, l 0, t 0xff) 30(c 0x0, s 0x67 , l 0, t 0xff) 31(c 0x0, s 0x6 Sep 18 16:40:12 ns1 /kernel: t 0xff) Sep 18 16:40:12 ns1 /kernel: Pending list: 27(c 0x60, s 0x67, l 0), 19(c 0x62, s 0x67, l 0), 22(c 0x60, s 0x67, l 0), 16(c 0x60, s 0x67, l 0), 3(c 0x60, s 0x67, l 0), 10 (c 0x60, s 0x67, l 0), 11(c 0x60, s 0x67, l 0), 2(c 0x60, s 0x67, l 0), 1(c 0x60, s 0x67, l 0), 15(c 0x60, s 0x67, l 0), 25(c 0x60, s 0x67, l 0), 9(c 0x60, s 0x67, l 0), 18(c 0x60, s 0x67, l 0), 24(c 0x60, s 0x67, l 0), 5(c 0x60, s 0x67, l 0), 28(c 0x60, s 0x67, l 0), 23(c 0x60, s 0x67, l 0), 7(c 0x60, s 0x67, l 0), 8(c 0x60, s 0x67, l 0), 4(c 0x60, s 0x67, l 0), 0(c 0x60, s 0x67, l 0), 29(c 0x60, s 0x67, l 0), 21(c 0x60, s 0x67, l 0) Sep 18 16:40:13 ns1 /kernel: Kernel Free SCB list: 12 6 26 20 14 13 Sep 18 16:40:13 ns1 /kernel: sg[0] - Addr 0x60f5000 : Length 4096 Sep 18 16:40:13 ns1 /kernel: sg[1] - Addr 0x6a16000 : Length 4096 Sep 18 16:40:13 ns1 /kernel: sg[2] - Addr 0x6077000 : Length 4096 Sep 18 16:40:13 ns1 /kernel: sg[3] - Addr 0x6778000 : Length 4096 Sep 18 16:40:13 ns1 /kernel: (da0:ahc0:0:6:0): no longer in timeout, status = 34b Sep 18 16:40:13 ns1 /kernel: ahc0: Issued Channel A Bus Reset. 23 SCBs aborted And this is what my kernel prints when I'm booting. Aug 21 10:07:39 ns1 /kernel: Copyright (c) 1992-2002 The FreeBSD Project. Aug 21 10:07:39 ns1 /kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 Aug 21 10:07:39 ns1 /kernel: The Regents of the University of California. All rights reserved. Aug 21 10:07:39 ns1 /kernel: FreeBSD 4.6.1-RELEASE-p7 #1: Fri Aug 2 16:04:44 EEST 2002 Aug 21 10:07:39 ns1 /kernel: root@lalev.uni-svishtov.bg:/usr/opt/obj/usr/opt/src/sys/GENERIC Aug 21 10:07:39 ns1 /kernel: Timecounter "i8254" frequency 1193182 Hz Aug 21 10:07:39 ns1 /kernel: CPU: Pentium III/Pentium III Xeon/Celeron (451.02-MHz 686-class CPU) Aug 21 10:07:39 ns1 /kernel: Origin = "GenuineIntel" Id = 0x673 Stepping = 3 Aug 21 10:07:39 ns1 /kernel: Features=0x383f9ff Aug 21 10:07:39 ns1 /kernel: real memory = 268423168 (262132K bytes) Aug 21 10:07:39 ns1 /kernel: avail memory = 256253952 (250248K bytes) Aug 21 10:07:39 ns1 /kernel: Preloaded elf kernel "kernel" at 0xc04d4000. Aug 21 10:07:39 ns1 /kernel: Preloaded elf module "splash_bmp.ko" at 0xc04d409c. Aug 21 10:07:39 ns1 /kernel: Pentium Pro MTRR support enabled Aug 21 10:07:39 ns1 /kernel: md0: Malloc disk Aug 21 10:07:39 ns1 /kernel: module_register_init: MOD_LOAD (splash_bmp, c04cf790, 0) error 2 Aug 21 10:07:39 ns1 /kernel: Using $PIR table, 7 entries at 0xc00f0d10 Aug 21 10:07:39 ns1 /kernel: npx0: on motherboard Aug 21 10:07:39 ns1 /kernel: npx0: INT 16 interface Aug 21 10:07:39 ns1 /kernel: pcib0: on motherboard Aug 21 10:07:39 ns1 /kernel: pci0: on pcib0 Aug 21 10:07:39 ns1 /kernel: pcib1: at device 1.0 on pci0 Aug 21 10:07:39 ns1 /kernel: pci1: on pcib1 Aug 21 10:07:39 ns1 /kernel: isab0: at device 4.0 on pci0 Aug 21 10:07:39 ns1 /kernel: isa0: on isab0 Aug 21 10:07:39 ns1 /kernel: atapci0: port 0xd800-0xd80f at device 4.1 on pci0 Aug 21 10:07:39 ns1 /kernel: ata0: at 0x1f0 irq 14 on atapci0 Aug 21 10:07:39 ns1 /kernel: ata1: at 0x170 irq 15 on atapci0 Aug 21 10:07:39 ns1 /kernel: uhci0: port 0xd400-0xd41f irq 10 at device 4.2 on pci0 Aug 21 10:07:39 ns1 /kernel: usb0: on uhci0 Aug 21 10:07:39 ns1 /kernel: usb0: USB revision 1.0 Aug 21 10:07:39 ns1 /kernel: uhub0: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 Aug 21 10:07:39 ns1 /kernel: uhub0: 2 ports with 2 removable, self powered Aug 21 10:07:39 ns1 /kernel: chip1: port 0xe800-0xe80f at device 4.3 on pci0 Aug 21 10:07:39 ns1 /kernel: ahc0: port 0xd000-0xd0ff mem 0xcd000000-0xcd000fff irq 10 at device 6.0 on pci0 Aug 21 10:07:39 ns1 /kernel: aic7890/91: Ultra2 Wide Channel A, SCSI Id=7, 32/253 SCBs Aug 21 10:07:39 ns1 /kernel: pci0: at 9.0 irq 10 Aug 21 10:07:39 ns1 /kernel: tl0: port 0xb800-0xb80f mem 0xcb800000-0xcb80000f irq 11 at device 11.0 on pci0 Aug 21 10:07:39 ns1 /kernel: tl0: Ethernet address: 00:08:c7:28:9d:96 Aug 21 10:07:40 ns1 /kernel: miibus0: on tl0 Aug 21 10:07:40 ns1 /kernel: nsphy0: on miibus0 Aug 21 10:07:40 ns1 /kernel: nsphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto Aug 21 10:07:40 ns1 /kernel: tlphy0: on miibus0 Aug 21 10:07:40 ns1 /kernel: tlphy0: 10base2/BNC, 10base5/AUI Aug 21 10:07:40 ns1 /kernel: orm0: