kern/118093: firewire bus reset hogs CPU, causing data to be lost

[Sean Bruno]

Sean Bruno wrote:
> Dieter wrote:
>> In message <494DAEB1.1070909 at 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