ohci1394: aborting transmission

ohci1394: aborting transmission

[Christian Kujau]

Hello lkml, hello linux1394-devel,

I've noticed a *very* long delay upon booting current -mm kernels. 
Here's a snippet from netconsole with 2.6.17-mm6:

------------snip--------------------
  [   50.651945] ACPI: PCI Interrupt 0000:01:00.0[A] -> Link [APC1] -> GSI 16 (level, low) -> IRQ 16
  [   50.655774] NVRM: loading NVIDIA Linux x86_64 Kernel Module  1.0-7182  Wed Apr 19 13:55:00 PDT 2006
  [   50.763074] ACPI: PCI Interrupt 0000:00:06.0[A] -> Link [APCJ] -> GSI 23 (level, high) -> IRQ 23
  [   51.078391] intel8x0_measure_ac97_clock: measured 50730 usecs
  [   51.082255] intel8x0: clocking to 46828
  [   51.651890] ohci1394: fw-host0: AT dma reset ctx=0, aborting transmission
  [  229.450216] input: USB HIDBP Keyboard 046a:0001 as /class/input/input0
  [  229.458201] usbcore: registered new driver usbkbd
  [  229.462264] drivers/usb/input/usbkbd.c: :USB HID Boot Protocol keyboard driver
  [  229.473883] input: Logitech USB-PS/2 Optical Mouse as /class/input/input1
  [  229.479629] usbcore: registered new driver usbmouse
------------snap--------------------

So, we're waiting 3 minutes from 'ohci1394: aborting transmission' until 
'input: USB HIDBP' kicks in and boot continues as usual. Unfortunately 
I'm not sure since when this unusual delay is present as I don't
monitor the box' startups closely. With 2.6.18-rc1 it's:

------------snip------------
[   48.318107] intel8x0_measure_ac97_clock: measured 50655 usecs
[   48.322011] intel8x0: clocking to 46909
[   48.748826] ieee1394: Host added: ID:BUS[0-00:1023] GUID[0010dc00009b6e48]
[  226.073196] input: USB HIDBP Keyboard 046a:0001 as /class/input/input0
[  226.080945] usbcore: registered new driver usbkbd
[  226.084830] drivers/usb/input/usbkbd.c: :USB HID Boot Protocol keyboard driver
------------snip------------

Full logs/config/lspci here: http://nerdbynature.de/bits/2.6.17-mm6/

While I'm trying to find out the first kernelversion with these 
symptoms: any ideas on this one?

I can see the "[PATCH 2.6.17-rc5-mm2 00/18] ieee1394: misc updates" 
patchset, maybe I'll start with this one....

Thanks,
Christian.
-- 
BOFH excuse #54:

Evil dogs hypnotised the night shift

Re: ohci1394: aborting transmission

[Stefan Richter]

Christian Kujau wrote:
> I've noticed a *very* long delay upon booting current -mm kernels. 
> Here's a snippet from netconsole with 2.6.17-mm6:
> 
> ------------snip--------------------
>   [   50.651945] ACPI: PCI Interrupt 0000:01:00.0[A] -> Link [APC1] -> GSI 16 (level, low) -> IRQ 16
>   [   50.655774] NVRM: loading NVIDIA Linux x86_64 Kernel Module  1.0-7182  Wed Apr 19 13:55:00 PDT 2006
>   [   50.763074] ACPI: PCI Interrupt 0000:00:06.0[A] -> Link [APCJ] -> GSI 23 (level, high) -> IRQ 23
>   [   51.078391] intel8x0_measure_ac97_clock: measured 50730 usecs
>   [   51.082255] intel8x0: clocking to 46828
>   [   51.651890] ohci1394: fw-host0: AT dma reset ctx=0, aborting transmission
>   [  229.450216] input: USB HIDBP Keyboard 046a:0001 as /class/input/input0
>   [  229.458201] usbcore: registered new driver usbkbd
>   [  229.462264] drivers/usb/input/usbkbd.c: :USB HID Boot Protocol keyboard driver
>   [  229.473883] input: Logitech USB-PS/2 Optical Mouse as /class/input/input1
>   [  229.479629] usbcore: registered new driver usbmouse
> ------------snap--------------------
> 
> So, we're waiting 3 minutes from 'ohci1394: aborting transmission' until 
> 'input: USB HIDBP' kicks in and boot continues as usual. Unfortunately 
> I'm not sure since when this unusual delay is present as I don't
> monitor the box' startups closely. With 2.6.18-rc1 it's:

[...also delayed but without "AT dma reset ctx=0, aborting
transmission", and it gets to "ieee1394: Host added"...]

> While I'm trying to find out the first kernelversion with these 
> symptoms: any ideas on this one?

No idea here. I don't have an idea what could cause a delay with a
timeout of 3 minutes in the 1394 drivers.

Perhaps you should add a printk at the beginning of input's init
function. The delay could happen during the startup of the input layer
instead of the 1394 drivers.

> I can see the "[PATCH 2.6.17-rc5-mm2 00/18] ieee1394: misc updates" 
> patchset, maybe I'll start with this one....

In order to avoid patch mismerges, you could grab the broken-out patches
from
ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17/2.6.17-mm6/
and start bisecting within the set of 1394 patches. Among them, the
patches to sbp2, dv1394, and raw1394 are unrelated to the problem. Note
that "origin.patch" touches drivers/ieee1394/ too.

You could also test Linux 2.6.17.x with patchkit v121 from
http://me.in-berlin.de/~s5r6/linux1394/updates/ applied. As far as
drivers/ieee1394/ is concerned, this is the same as the 1394 drivers in
2.6.17-mm6, and I believe 2.6.18-rc1-mm1 too.

If 2.6.17.x + latest 1394 has the delay, try original 2.6.17.x too
unless you didn't already.

If 2.6.17.x + latest 1394 does not have the delay, then the 1394 updates
are _perhaps_ not to blame.

The VIA VT6306 OHCI controller which you have according to your lspci
output is known to work; yours doesn't even have the small quirk
mentioned in http://www.linux1394.org/view_device.php?id=713 .
-- 
Stefan Richter
-=====-=-==- -=== -=-=-
http://arcgraph.de/sr/

Re: ohci1394: aborting transmission

[Christian Kujau]

On Mon, 10 Jul 2006, Stefan Richter wrote:
> Perhaps you should add a printk at the beginning of input's init
> function. The delay could happen during the startup of the input layer
> instead of the 1394 drivers.

yeah, I'll try to do this later on....getting some sleep first...

> ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17/2.6.17-mm6/
> and start bisecting within the set of 1394 patches. Among them, the
> patches to sbp2, dv1394, and raw1394 are unrelated to the problem. Note
> that "origin.patch" touches drivers/ieee1394/ too.

OK, thanks for the hint.

> The VIA VT6306 OHCI controller which you have according to your lspci
> output is known to work; yours doesn't even have the small quirk
> mentioned in http://www.linux1394.org/view_device.php?id=713 .

yes, it worked before with no delay and even now all seems to be 
fine after the delay....

Thanks,
Christian.
-- 
BOFH excuse #193:

Did you pay the new Support Fee?

Re: ohci1394: aborting transmission

[Stefan Richter]

> On Mon, 10 Jul 2006, Stefan Richter wrote:
>> Perhaps you should add a printk at the beginning of input's init
>> function. The delay could happen during the startup of the input layer
>> instead of the 1394 drivers.

PS: Another simple test would be to boot with IEEE 1394 modules moved
away so that they are not loaded.
-- 
Stefan Richter
-=====-=-==- -=== -=-=-
http://arcgraph.de/sr/

[x86_64] strange delays since 2.6.15 (was: Re: ohci1394: aborting transmission)

[Christian Kujau]

Hello Stefan, hello all,

sorry for not getting back to you earlier. I was not asleep though and 
the problem has not gone away - it has become worse, much worse and it 
turns out that it might not have anything to do with ohci1394 at all, 
but read on (if you're curious):

I've noticed the strange delay during bootup in 2.6.17-mm6 and thought 
"hm, this did not occur in 2.6.16...right?" but I really I have not paid 
attention to the bootup process of this box. in fact, i had no access to 
this box for a few month and have not tracked -current for a while and 
when I got access again we were somewhere at 2.6.17-rc* and I have not 
paid attention to the bootup at all.

I am currently in the middle of bisecting and I found out that
    - 2.6.14 is fine, no delays during bootup
    - 2.6.15-rc1 is showing these delays

"git-bisect log" shows (uh, linewraps):

git-bisect start
# bad: [c80dc60b03d633047c7f96be87fd59cdcdbb929f] Merge branch 'release' of git://git.kernel.org/pub/scm/linux/kernel/git/lenb/linux-acpi-2.6
git-bisect bad c80dc60b03d633047c7f96be87fd59cdcdbb929f
# good: [2b10839e32c4c476e9d94492756bb1a3e1ec4aa8] Linux v2.6.14
git-bisect good 2b10839e32c4c476e9d94492756bb1a3e1ec4aa8
# bad: [c89f2ee5f9223b864725f7344f24a037dfa76568] NFS: make iocb available everywhere in direct write path
git-bisect bad c89f2ee5f9223b864725f7344f24a037dfa76568
# bad: [27441127b086230cc4c57d6cd9a615272fb47bcd] [ALSA] Remove snd_legacy_auto_probe()
git-bisect bad 27441127b086230cc4c57d6cd9a615272fb47bcd
# bad: [7a77d918ad8fb152312525b70780f6e0052b3ee3] m68knommu: FEC ethernet header support for the ColdFire 5208
git-bisect bad 7a77d918ad8fb152312525b70780f6e0052b3ee3
# bad: [b38c6845b695141259019e2b7c0fe6c32a6e720d] mm: uml kill unused
git-bisect bad b38c6845b695141259019e2b7c0fe6c32a6e720d
# bad: [c9c7746dd333c12f482af2f1e63ea7eafc7cd529] USB: ftdi: Artemis and ATIK based USB astronomical CCD cameras
git-bisect bad c9c7746dd333c12f482af2f1e63ea7eafc7cd529
# good: [e5dfa9282f3db461a896a6692b529e1823ba98c6] Merge branch 'upstream' of master.kernel.org:/pub/scm/linux/kernel/git/jgarzik/netdev-2.6
git-bisect good e5dfa9282f3db461a896a6692b529e1823ba98c6
# bad: [6fbfddcb52d8d9fa2cd209f5ac2a1c87497d55b5] Merge ../bleed-2.6
git-bisect bad 6fbfddcb52d8d9fa2cd209f5ac2a1c87497d55b5
# good: [9be16a03928642f944915b8c05945fd87b7a15cb] Merge branch 'sx8' of master.kernel.org:/pub/scm/linux/kernel/git/jgarzik/misc-2.6
git-bisect good 9be16a03928642f944915b8c05945fd87b7a15cb
# good: [049eb3298a832a63c55bc8d8ea4cc881ab99f84b] [ARM] 3041/1: AAEC-2000 - CLCD controller platform glue
git-bisect good 049eb3298a832a63c55bc8d8ea4cc881ab99f84b
# bad: [b7df3910c1298fee8ed7b9dfd2da74b85df5539c] drivers/media: convert to dynamic input_dev allocation
git-bisect bad b7df3910c1298fee8ed7b9dfd2da74b85df5539c


So, b7df3910c1298fee8ed7b9dfd2da74b85df5539c is bad, meaning it shows 
these delays. I've done another "git-bisect bad" after this but now 
compiling fails (see below) and now I'm stuck again.

I shall remove the ohci1394 guys from the Cc: and hope that some 
git-guru can help out, when compiling a git-bisect'ed kernel fails not 
because of being "bad" but because of compile-breakage :(

just for the record:

On Mon, 10 Jul 2006, Stefan Richter wrote:
> PS: Another simple test would be to boot with IEEE 1394 modules moved
> away so that they are not loaded.

yes, I've done that with 2.6.17-*, did not help...


Thanks,
Christian.


b7df3910c1298fee8ed7b9dfd2da74b85df5539c breaks with:

   CC      drivers/char/mem.o
/mnt/hda2/scratch/linux-2.6-git/drivers/char/mem.c: In function 
'chr_dev_init':
/mnt/hda2/scratch/linux-2.6-git/drivers/char/mem.c:924: warning: passing 
argument 2 of 'class_device_create' makes pointer from integer without a 
cast
/mnt/hda2/scratch/linux-2.6-git/drivers/char/mem.c:924: warning: passing 
argument 3 of 'class_device_create' makes integer from pointer without a 
cast
/mnt/hda2/scratch/linux-2.6-git/drivers/char/mem.c:924: warning: passing 
argument 4 of 'class_device_create' from incompatible pointer type
/mnt/hda2/scratch/linux-2.6-git/drivers/char/mem.c:924: error: too few 
arguments to function 'class_device_create'
make[3]: *** [drivers/char/mem.o] Error 1
make[2]: *** [drivers/char] Error 2
make[1]: *** [drivers] Error 2
make: *** [_all] Error 2
-- 
BOFH excuse #27:

radiosity depletion

Re: [x86_64] strange delays since 2.6.15 (was: Re: ohci1394: aborting transmission)

[Christian Kujau]

Hello all,

I am still having these strange boot-delays which I reported in [0] when 
I was under the assumption that ohci1394 was to blame, simply because 
"ohci1394: aborting transmission" was the last message before the 
3minute delay during bootup happened. I've found out that the actual 
problem started way earlier (2.6.14->2.6.15) and I have bisected my way 
down to this patchset:

a7fd67062efc5b0fc9a61368c607fa92d1d57f9e is first bad commit
diff-tree a7fd67062efc5b0fc9a61368c607fa92d1d57f9e (from 
d8539d81aeee4dbdc0624a798321e822fb2df7ae)
Author: Kay Sievers <kay.sievers@suse.de>
Date:   Sat Oct 1 14:49:43 2005 +0200

     [PATCH] add sysfs attr to re-emit device hotplug event

     A "coldplug + udevstart" can be simple like this:
       for i in /sys/block/*/*/uevent; do echo 1 > $i; done
       for i in /sys/class/*/*/uevent; do echo 1 > $i; done
       for i in /sys/bus/*/devices/*/uevent; do echo 1 > $i; done

     Signed-off-by: Kay Sievers <kay.sievers@suse.de>
     Signed-off-by: Greg Kroah-Hartman <gregkh@suse.de>

:040000 040000 7edb92ad6f55113bac2e1919e6b2364e17dfaa0b 43b3108675db828a2ce7df87f08a26aa7d7ac0fc M      drivers
:040000 040000 382f692398a9fe4bea4ab5333dea67f8151b0b82 58bb09d0051236695e6987f12e389ce75387ddf7 M      fs
:040000 040000 72bcc7fddd5087cadf70b9d2582c7faea7ebb364 2ec812818920645cb58f1694818019516ea6e3b6 M      include

Wtihout this patch, booting is fine, no delays. With this patchset, I 
notice a 3 minute delay.

However, as the patch-description tells me, it only introduces something 
in /sys/..../*/uevent and the delay is in fact triggered by userspace!
My distribution of choice (Ubuntu/6.06 LTS) does "something" in /sys 
during execution of /etc/init.d/udev (from: udev-079-0ubuntu34). Please 
see this url for details, logs, .config and more:

http://nerdbynature.de/bits/2.6.15/

Many thanks for hints on what to do here. This issue is 100% 
reproducible and is kinda annoying now that I happen to be on-site when 
the machine boots up. As mentioned earlier I had no access to the box 
for a few months and did not pay attention to the boot-process and did 
not track -current too, that's why I'm whining about 2.6.15-problems 
when we're actually at 2.6.18-* already....

Thanks,
Christian.

[0] http://www.ussg.iu.edu/hypermail/linux/kernel/0607.1/1708.html
-- 
BOFH excuse #156:

Zombie processes haunting the computer

Re: [x86_64] strange delays since 2.6.15 (was: Re: ohci1394: aborting transmission)

[Kay Sievers]

On Wed, 2006-07-12 at 22:01 +0100, Christian Kujau wrote:
> Hello all,
> 
> I am still having these strange boot-delays which I reported in [0] when 
> I was under the assumption that ohci1394 was to blame, simply because 
> "ohci1394: aborting transmission" was the last message before the 
> 3minute delay during bootup happened. I've found out that the actual 
> problem started way earlier (2.6.14->2.6.15) and I have bisected my way 
> down to this patchset:
> 
> a7fd67062efc5b0fc9a61368c607fa92d1d57f9e is first bad commit
> diff-tree a7fd67062efc5b0fc9a61368c607fa92d1d57f9e (from 
> d8539d81aeee4dbdc0624a798321e822fb2df7ae)
> Author: Kay Sievers <kay.sievers@suse.de>
> Date:   Sat Oct 1 14:49:43 2005 +0200
> 
>      [PATCH] add sysfs attr to re-emit device hotplug event

Looks like a broken udev/system-init setup, which may hang until a
timeout, while it tries to coldplug devices. When you back out the
patch, coldplug will just fail, that's why the behavior is different.

I'm pretty sure, it has nothing to do with this patch itself. You may
want to look in your bootscripts where it hangs, not in the kernel.

Kay

Re: [x86_64] strange delays since 2.6.15 (was: Re: ohci1394: aborting transmission)

[Christian Kujau]

On Wed, 12 Jul 2006, Kay Sievers wrote:
>
> I'm pretty sure, it has nothing to do with this patch itself. You may
> want to look in your bootscripts where it hangs, not in the kernel.

strange though, that the script did not change but the kernel. But as 
it's triggered by userspace it has to be fixed in userspace. It was 
quite a good exercise to use git-bisect: from 1500+ changesets down to 1 
single diff in a few hours...very cool!

Christian.
-- 
BOFH excuse #369:

Virus transmitted from computer to sysadmins.