From owner-freebsd-firewire@FreeBSD.ORG Sun Dec 21 02:49:22 2008 Return-Path: Delivered-To: freebsd-firewire@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id DA1C21065670; Sun, 21 Dec 2008 02:49:22 +0000 (UTC) (envelope-from sbruno@miralink.com) Received: from plato.miralink.com (mail.miralink.com [70.103.185.20]) by mx1.freebsd.org (Postfix) with ESMTP id A86988FC08; Sun, 21 Dec 2008 02:49:22 +0000 (UTC) (envelope-from sbruno@miralink.com) Received: from localhost (localhost.localdomain [127.0.0.1]) by plato.miralink.com (Postfix) with ESMTP id 0DD4B1A9121; Sat, 20 Dec 2008 19:49:21 -0800 (PST) X-Virus-Scanned: amavisd-new at X-Spam-Flag: NO X-Spam-Score: -4.399 X-Spam-Level: X-Spam-Status: No, score=-4.399 tagged_above=-10 required=6.6 tests=[ALL_TRUSTED=-1.8, BAYES_00=-2.599] Received: from plato.miralink.com ([127.0.0.1]) by localhost (plato.miralink.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id rWf4rQ+2bc3L; Sat, 20 Dec 2008 19:49:20 -0800 (PST) Received: from [10.47.1.6] (vpn.office.miralink.com [10.0.0.5]) by plato.miralink.com (Postfix) with ESMTP id 671CF1A911A; Sat, 20 Dec 2008 19:49:20 -0800 (PST) Message-ID: <494DAEB1.1070909@miralink.com> Date: Sat, 20 Dec 2008 18:49:21 -0800 From: Sean Bruno User-Agent: Thunderbird 2.0.0.18 (X11/20081119) MIME-Version: 1.0 To: Dieter References: <200812191902.TAA01939@sopwith.solgatos.com> In-Reply-To: <200812191902.TAA01939@sopwith.solgatos.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: freebsd-firewire@freebsd.org, bug-followup@freebsd.org Subject: Re: kern/118093: firewire bus reset hogs CPU, causing data to be lost X-BeenThere: freebsd-firewire@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Firewire support in FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 21 Dec 2008 02:49:22 -0000 Dieter wrote: > Here are the results of two more experiments: > > I tried to verify what spl the firewire code is at when calling > printf(9) by adding the following block into fwohci.c just > before one of the printfs. > > { > #include > #include > intrmask_t debug_spl; /* __uint32_t */ > intrmask_t debug_spl_high; > intrmask_t debug_spl_tty; > intrmask_t debug_spl_fw; > intrmask_t debug_spl_0; > intrmask_t debug_spl_net; > > debug_spl = splhigh(); > debug_spl_high = spltty(); > debug_spl_tty = splfw(); > debug_spl_fw = splnet(); > debug_spl_net = splhigh(); > spl0(); /* void */ > debug_spl_0 = splhigh(); > splx(debug_spl); > > printf("fwohci_intr_core(): spl = 0x%x\n splhigh=0x%x spltty=0x%x splfw=0x%x splnet=0x%x spl0=0x%x\n", > debug_spl, debug_spl_high, debug_spl_tty, debug_spl_fw, debug_spl_net, debug_spl_0); > } > > But my results appear bogus: > > fwohci_intr_core(): spl = 0x0 > splhigh=0x0 spltty=0x0 splfw=0x0 splnet=0x0 spl0=0x0 > > I have examined my code and the spl(9) man page several times > but I can't find what is wrong. Any clues? > > -------------------------------------------------------- > > To isolate the effects of printf(9) from the firewire bus reset, > I picked a trivial system call (chown(2)) and added some printf(9) > calls. > > Calling chown several times and monitoring with systat -vmstat gives: > 1098 interrupts on the console IRQ > 93.1%Sys 6.7%Intr 0.2%User 0.0%Nice 0.0%Idle > > This did NOT interfere with Ethernet. > > So printf(9) interferes with Ethernet when called from the > firewire driver, but not when called from a vanilla system call. > > I setup my system to execute a bus reset every 1 second, simultaneously, I started copying a large file onto the system see if anything would happen. I saw no change to copy speed reported by SCP during the entire transaction. I also see no change to the system load while this is occurring. This seems indicative of "something else" going on. > -------------------------------------------------------- > > sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 > sio0: type 16550A, console > sio0: [FILTER] > > What does [FILTER] mean? I don't see an explanation on the sio man page. > Did you mean to ask a different list? Because I have no idea. :) From owner-freebsd-firewire@FreeBSD.ORG Sun Dec 21 05:27:02 2008 Return-Path: Delivered-To: freebsd-firewire@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id D396A1065674; Sun, 21 Dec 2008 05:27:02 +0000 (UTC) (envelope-from freebsd@sopwith.solgatos.com) Received: from sopwith.solgatos.com (pool-71-182-69-106.ptldor.fios.verizon.net [71.182.69.106]) by mx1.freebsd.org (Postfix) with ESMTP id 355108FC16; Sun, 21 Dec 2008 05:27:02 +0000 (UTC) (envelope-from freebsd@sopwith.solgatos.com) Received: by sopwith.solgatos.com (Postfix, from userid 66) id DF1C83F22; Sat, 20 Dec 2008 20:57:43 -0800 (PST) Received: from localhost by sopwith.solgatos.com (8.8.8/6.24) id FAA02070; Sun, 21 Dec 2008 05:24:23 GMT Message-Id: <200812210524.FAA02070@sopwith.solgatos.com> To: freebsd-firewire@freebsd.org, bug-followup@freebsd.org In-reply-to: Your message of "Sat, 20 Dec 2008 18:49:21 PST." <494DAEB1.1070909@miralink.com> Date: Sat, 20 Dec 2008 21:24:23 +0000 From: Dieter Cc: Subject: Re: kern/118093: firewire bus reset hogs CPU, causing data to be lost X-BeenThere: freebsd-firewire@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Firewire support in FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 21 Dec 2008 05:27:02 -0000 In message <494DAEB1.1070909@miralink.com>, Sean Bruno writes: > I setup my system to execute a bus reset every 1 second, simultaneously, > I started copying a large > file onto the system see if anything would happen. > > I saw no change to copy speed reported by SCP during the entire > transaction. I also see no change > to the system load while this is occurring. Does your system have a RS-232 console or VGA console? The problem might be specific to RS-232. > This seems indicative of "something else" going on. Any idea what this "something else" might be? Does anyone have a clue why my spl calls are returning 0 ? From owner-freebsd-firewire@FreeBSD.ORG Mon Dec 22 11:06:50 2008 Return-Path: Delivered-To: freebsd-firewire@FreeBSD.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id BB0D11065679 for ; Mon, 22 Dec 2008 11:06:50 +0000 (UTC) (envelope-from owner-bugmaster@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [IPv6:2001:4f8:fff6::28]) by mx1.freebsd.org (Postfix) with ESMTP id 8F8DB8FC12 for ; Mon, 22 Dec 2008 11:06:50 +0000 (UTC) (envelope-from owner-bugmaster@FreeBSD.org) Received: from freefall.freebsd.org (localhost [127.0.0.1]) by freefall.freebsd.org (8.14.3/8.14.3) with ESMTP id mBMB6o6P060550 for ; Mon, 22 Dec 2008 11:06:50 GMT (envelope-from owner-bugmaster@FreeBSD.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.14.3/8.14.3/Submit) id mBMB6opj060546 for freebsd-firewire@FreeBSD.org; Mon, 22 Dec 2008 11:06:50 GMT (envelope-from owner-bugmaster@FreeBSD.org) Date: Mon, 22 Dec 2008 11:06:50 GMT Message-Id: <200812221106.mBMB6opj060546@freefall.freebsd.org> X-Authentication-Warning: freefall.freebsd.org: gnats set sender to owner-bugmaster@FreeBSD.org using -f From: FreeBSD bugmaster To: freebsd-firewire@FreeBSD.org Cc: Subject: Current problem reports assigned to freebsd-firewire@FreeBSD.org X-BeenThere: freebsd-firewire@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Firewire support in FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 22 Dec 2008 11:06:50 -0000 Note: to view an individual PR, use: http://www.freebsd.org/cgi/query-pr.cgi?pr=(number). The following is a listing of current problems submitted by FreeBSD users. These represent problem reports covering all versions including experimental development code and obsolete releases. S Tracker Resp. Description -------------------------------------------------------------------------------- o kern/113785 firewire [firewire] dropouts when playing DV on firewire o kern/74238 firewire [firewire] fw_rcv: unknown response; firewire ad-hoc w 2 problems total. From owner-freebsd-firewire@FreeBSD.ORG Tue Dec 23 03:21:51 2008 Return-Path: Delivered-To: freebsd-firewire@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 78AE3106564A; Tue, 23 Dec 2008 03:21:51 +0000 (UTC) (envelope-from sbruno@miralink.com) Received: from plato.miralink.com (mail.miralink.com [70.103.185.20]) by mx1.freebsd.org (Postfix) with ESMTP id 4C3E48FC19; Tue, 23 Dec 2008 03:21:51 +0000 (UTC) (envelope-from sbruno@miralink.com) Received: from localhost (localhost.localdomain [127.0.0.1]) by plato.miralink.com (Postfix) with ESMTP id 8843F1A9135; Mon, 22 Dec 2008 20:21:49 -0800 (PST) X-Virus-Scanned: amavisd-new at X-Spam-Flag: NO X-Spam-Score: -4.399 X-Spam-Level: X-Spam-Status: No, score=-4.399 tagged_above=-10 required=6.6 tests=[ALL_TRUSTED=-1.8, BAYES_00=-2.599] Received: from plato.miralink.com ([127.0.0.1]) by localhost (plato.miralink.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id G5l4E3C5Raht; Mon, 22 Dec 2008 20:21:49 -0800 (PST) Received: from [10.47.1.6] (vpn.office.miralink.com [10.0.0.5]) by plato.miralink.com (Postfix) with ESMTP id E27541A90C8; Mon, 22 Dec 2008 20:21:48 -0800 (PST) Message-ID: <4950594D.50208@miralink.com> Date: Mon, 22 Dec 2008 19:21:49 -0800 From: Sean Bruno User-Agent: Thunderbird 2.0.0.18 (X11/20081119) MIME-Version: 1.0 To: Dieter References: <200812210524.FAA02070@sopwith.solgatos.com> In-Reply-To: <200812210524.FAA02070@sopwith.solgatos.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: freebsd-firewire@freebsd.org, bug-followup@freebsd.org Subject: Re: kern/118093: firewire bus reset hogs CPU, causing data to be lost X-BeenThere: freebsd-firewire@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Firewire support in FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 23 Dec 2008 03:21:51 -0000 Dieter wrote: > In message <494DAEB1.1070909@miralink.com>, Sean Bruno writes: > > >> I setup my system to execute a bus reset every 1 second, simultaneously, >> I started copying a large >> file onto the system see if anything would happen. >> >> I saw no change to copy speed reported by SCP during the entire >> transaction. I also see no change >> to the system load while this is occurring. >> > > Does your system have a RS-232 console or VGA console? > The problem might be specific to RS-232. > > I have both. I disabled my serial console to test, no change when using the VGA console only. >> This seems indicative of "something else" going on. >> > > Any idea what this "something else" might be? > > Does anyone have a clue why my spl calls are returning 0 ? > > I confirmed that spl's are complete no-ops since rel 5. So, you want to ignore them as they are just markers now where locking should be implemented. I went back in your original submission and I can see a significant drop in I/O when resetting the F/W bus. If I have the following running: dd if=/dev/zero of=/dev/ad6 bs=64k Then I see about 64MB/S normally. When I reset any firewire bus, I see the throughput drop as reported by iostat by a significant amount(2-4 MB/s). I am assuming that the firewire driver is holding a very heavy lock here that is cascading down to the printf(). At least, that would be my ASSumption. :) I will continue to poke around. You are not crazy Dieter. Sean From owner-freebsd-firewire@FreeBSD.ORG Tue Dec 23 06:01:56 2008 Return-Path: Delivered-To: freebsd-firewire@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 9ECFB106564A; Tue, 23 Dec 2008 06:01:56 +0000 (UTC) (envelope-from sbruno@miralink.com) Received: from plato.miralink.com (mail.miralink.com [70.103.185.20]) by mx1.freebsd.org (Postfix) with ESMTP id 70B1D8FC12; Tue, 23 Dec 2008 06:01:56 +0000 (UTC) (envelope-from sbruno@miralink.com) Received: from localhost (localhost.localdomain [127.0.0.1]) by plato.miralink.com (Postfix) with ESMTP id C8C321A913E; Mon, 22 Dec 2008 23:01:54 -0800 (PST) X-Virus-Scanned: amavisd-new at X-Spam-Flag: NO X-Spam-Score: -4.399 X-Spam-Level: X-Spam-Status: No, score=-4.399 tagged_above=-10 required=6.6 tests=[ALL_TRUSTED=-1.8, BAYES_00=-2.599] Received: from plato.miralink.com ([127.0.0.1]) by localhost (plato.miralink.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id niN+5poMFgWL; Mon, 22 Dec 2008 23:01:54 -0800 (PST) Received: from [10.47.1.6] (vpn.office.miralink.com [10.0.0.5]) by plato.miralink.com (Postfix) with ESMTP id 2438C1A913C; Mon, 22 Dec 2008 23:01:54 -0800 (PST) Message-ID: <49507ED3.9010006@miralink.com> Date: Mon, 22 Dec 2008 22:01:55 -0800 From: Sean Bruno User-Agent: Thunderbird 2.0.0.18 (X11/20081119) MIME-Version: 1.0 To: Dieter References: <200812210524.FAA02070@sopwith.solgatos.com> <4950594D.50208@miralink.com> In-Reply-To: <4950594D.50208@miralink.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: freebsd-firewire@freebsd.org, bug-followup@freebsd.org Subject: Re: kern/118093: firewire bus reset hogs CPU, causing data to be lost X-BeenThere: freebsd-firewire@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Firewire support in FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 23 Dec 2008 06:01:56 -0000 Sean Bruno wrote: > Dieter wrote: >> In message <494DAEB1.1070909@miralink.com>, Sean Bruno writes: >> >> >>> I setup my system to execute a bus reset every 1 second, >>> simultaneously, I started copying a large >>> file onto the system see if anything would happen. >>> >>> I saw no change to copy speed reported by SCP during the entire >>> transaction. I also see no change >>> to the system load while this is occurring. >>> >> >> Does your system have a RS-232 console or VGA console? >> The problem might be specific to RS-232. >> >> > I have both. I disabled my serial console to test, no change when using > the VGA console only. > >>> This seems indicative of "something else" going on. >>> >> >> Any idea what this "something else" might be? >> >> Does anyone have a clue why my spl calls are returning 0 ? >> >> > I confirmed that spl's are complete no-ops since rel 5. So, you want > to ignore > them as they are just markers now where locking should be implemented. > > I went back in your original submission and I can see a significant > drop in I/O > when resetting the F/W bus. If I have the following running: > dd if=/dev/zero of=/dev/ad6 bs=64k > > Then I see about 64MB/S normally. When I reset any firewire bus, I > see the throughput > drop as reported by iostat by a significant amount(2-4 MB/s). > > I am assuming that the firewire driver is holding a very heavy lock > here that is cascading > down to the printf(). At least, that would be my ASSumption. :) > > I will continue to poke around. You are not crazy Dieter. > > Sean > > Hrm ... Looking over the log messages that are generated during a bus reset, there's a mish-mash of printf() and device_printf() calls. I'm not sure what the impact of that is to real behavior, but /var/log/messages has a tendency to get garbled like this: Dec 22 16:00:18 home-test kernel: fwohci1: Initiate bus reset Dec 22 16:00:18 home-test kernel: fwohci1: BUS reset Dec 22 16:00:18 home-test kernel: fwohci1: node_id=0xc800ffc0, gen=8, CYCLEMASTER mode Dec 22 16:00:18 home-test kernel: firewi Dec 22 16:00:18 home-test kernel: re1: Dec 22 16:00:18 home-test kernel: 1 n Dec 22 16:00:18 home-test kernel: odes Dec 22 16:00:18 home-test kernel: , ma Dec 22 16:00:18 home-test kernel: xhop Dec 22 16:00:18 home-test kernel: <= Dec 22 16:00:18 home-test kernel: 0, c Dec 22 16:00:18 home-test kernel: able Dec 22 16:00:18 home-test kernel: IRM Dec 22 16:00:18 home-test kernel: = 0 Dec 22 16:00:18 home-test kernel: (me Dec 22 16:00:18 home-test kernel: ) Dec 22 16:00:18 home-test kernel: f Dec 22 16:00:18 home-test kernel: irew Dec 22 16:00:18 home-test kernel: ire1 Dec 22 16:00:18 home-test kernel: : bu Dec 22 16:00:18 home-test kernel: s ma Dec 22 16:00:18 home-test kernel: nage Dec 22 16:00:18 home-test kernel: r 0 Dec 22 16:00:18 home-test kernel: (me) Dec 22 16:00:18 home-test kernel: Let me try to eliminate this behaviour first. Sean From owner-freebsd-firewire@FreeBSD.ORG Fri Dec 26 06:25:03 2008 Return-Path: Delivered-To: freebsd-firewire@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 2F1461065670; Fri, 26 Dec 2008 06:25:03 +0000 (UTC) (envelope-from freebsd@sopwith.solgatos.com) Received: from sopwith.solgatos.com (pool-71-117-207-61.ptldor.fios.verizon.net [71.117.207.61]) by mx1.freebsd.org (Postfix) with ESMTP id 9897B8FC14; Fri, 26 Dec 2008 06:25:02 +0000 (UTC) (envelope-from freebsd@sopwith.solgatos.com) Received: by sopwith.solgatos.com (Postfix, from userid 66) id 32768B64F; Thu, 25 Dec 2008 22:21:06 -0800 (PST) Received: from localhost by sopwith.solgatos.com (8.8.8/6.24) id GAA20643; Fri, 26 Dec 2008 06:23:09 GMT Message-Id: <200812260623.GAA20643@sopwith.solgatos.com> To: Sean Bruno In-reply-to: Your message of "Mon, 22 Dec 2008 22:01:55 PST." <49507ED3.9010006@miralink.com> Date: Thu, 25 Dec 2008 22:23:09 +0000 From: Dieter Cc: freebsd-firewire@freebsd.org, bug-followup@freebsd.org Subject: Re: kern/118093: firewire bus reset hogs CPU, causing data to be lost X-BeenThere: freebsd-firewire@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Firewire support in FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 26 Dec 2008 06:25:03 -0000 > > I confirmed that spl's are complete no-ops since rel 5. So, you want > > to ignore > > them as they are just markers now where locking should be implemented. I hunted down the spl code, and you're right. Wow, I wonder how drivers still using spl calls work at all? > is to real behavior, but /var/log/messages has a tendency to get garbled > like this: > > Dec 22 16:00:18 home-test kernel: fwohci1: Initiate bus reset > Dec 22 16:00:18 home-test kernel: fwohci1: BUS reset > Dec 22 16:00:18 home-test kernel: fwohci1: node_id=0xc800ffc0, gen=8, > CYCLEMASTER mode > Dec 22 16:00:18 home-test kernel: firewi > Dec 22 16:00:18 home-test kernel: re1: > Dec 22 16:00:18 home-test kernel: 1 n > Dec 22 16:00:18 home-test kernel: odes > Dec 22 16:00:18 home-test kernel: , ma > Dec 22 16:00:18 home-test kernel: xhop > Dec 22 16:00:18 home-test kernel: <= > Dec 22 16:00:18 home-test kernel: 0, c > Dec 22 16:00:18 home-test kernel: able Do the lines get folded on the console, or only in /var/log/messages?