On Thu, 15 Jan 2004, Axel Waggershauser wrote:
> The new printk's in uhci_clear_next_interrupt() and in
> uhci_set_next_interrupt() revealed the following trace:
>
>
> Jan 14 23:33:26 koffer kernel: >>> uhci_urb_dequeue cf02d560
> Jan 14 23:33:26 koffer kernel: >>> uhci_set_next_interrupt
> Jan 14 23:33:26 koffer kernel: << uhci_set_next_interrupt
> Jan 14 23:33:26 koffer kernel: uhci_urb_dequeue cf02d560 list_empty == true
> Jan 14 23:33:26 koffer kernel: >>> uhci_set_next_interrupt
> Jan 14 23:33:26 koffer kernel: << uhci_set_next_interrupt
> Jan 14 23:33:26 koffer kernel: << uhci_urb_dequeue cf02d560
> Jan 14 23:33:26 koffer kernel: uhci_hcd 0000:00:07.2: shutdown urb cf02d560 pipe
> c0020380 ep4in-bulk
>
> beyond that point there comes no uhci_clear_next_interrput and no
> uhci_irq call. (there follow a few more disable_endpoint calls and the
> mentioned givebacks for the status URBs, thats all)
>
> So I guess that is bad (meaning the hardware is buggy?).
I would hesitate to make that conclusion, but it's certainly a
possibility. The best test would be to try running your driver on a
different computer.
Another possibility is that, for some reason, the controller isn't running
when uhci_urb_dequeue() is called. In your printk at the end of the
routine, try displaying the value of uhci->state. However, if the
controller had stopped there ought to be a message in your system log
saying so. Something like:
kernel: d400: suspend_hc
And the controller shouldn't stop as long as your device is plugged in.
> I would like to mention some other observations I have made, which I
> don't understand in the context of what I learned about the controller
> so far. Maybe they give some more hints:
>
> -----------
> 1. From what you told me I understood that the set_next and clear_next
> calls should only occur in pairs (set_next -> uhci_irq gets called and
> calls clear_next)
No, that's not true. There's no counter or anything like that involved.
All that matters is which one runs last. So even if set_next is called 10
times, if clear_next is called it will cancel the effect.
> when I look at a normal URB transfer, of the same type
> I am investigating, I get following trace:
>
> # this first line is the last successful URB completion
> # the ">>>" mean entry, the " <<" mean exit
> Jan 14 23:33:26 koffer kernel: spheroncam.c: spheroncam_complete urb:
> cf02d560 status: 0
> Jan 14 23:33:26 koffer kernel: << giveback cf02d560
> Jan 14 23:33:26 koffer kernel: << uhci_finish_urb cf02d560
>
> # now I get uhci_irq calls...
> Jan 14 23:33:26 koffer kernel: uhci_irq status 32
Status 32? That means the controller _is_ stopped! But then _nothing_
should be working...
> Jan 14 23:33:26 koffer kernel: >>> uhci_clear_next_interrupt
> Jan 14 23:33:26 koffer kernel: << uhci_clear_next_interrupt
> Jan 14 23:33:26 koffer kernel: uhci_irq status 1
> Jan 14 23:33:26 koffer kernel: >>> uhci_clear_next_interrupt
> Jan 14 23:33:26 koffer kernel: << uhci_clear_next_interrupt
>
> # the last 4 lines repeat usually 3 or 4 times, then follows...
> Jan 14 23:33:26 koffer kernel: >>> uhci_set_next_interrupt
> Jan 14 23:33:26 koffer kernel: << uhci_set_next_interrupt
> Jan 14 23:33:26 koffer kernel: >>> uhci_finish_urb cf02d560
> Jan 14 23:33:26 koffer kernel: >>> uhci_set_next_interrupt
> Jan 14 23:33:26 koffer kernel: << uhci_set_next_interrupt
>
> # here I get the next successful completion...
> Jan 14 23:33:26 koffer kernel: >>> giveback cf02d560
> Jan 14 23:33:26 koffer kernel: spheroncam.c: spheroncam_complete urb:
> cf02d560 status: 0
>
> So I see 6 to 8 clear_next calls and then 2 set_next calls. Is that like
> it is supposed to be?
Yes, especially since uhci_irq() includes a call to clear_next. But you
shouldn't have seen status = 32!
> 2. The controller does not always behave like that. Approximately one
> out of 5 times it actually completes the URB when unlinking the device
> with an appropriate return value (-84). The trace in this case looks
> pretty much the same like above except the last uhci_irq call before the
> giveback reads a status value of 2 instead of 1. looks like this:
>
> # here I see the same 32 -> 1 -> 32 -> 1 -> .. pattern as above and then
> Jan 14 23:27:03 koffer kernel: uhci_irq status 32
> Jan 14 23:27:03 koffer kernel: >>> uhci_clear_next_interrupt
> Jan 14 23:27:03 koffer kernel: << uhci_clear_next_interrupt
> Jan 14 23:27:03 koffer kernel: uhci_irq status 2
> Jan 14 23:27:03 koffer kernel: >>> uhci_clear_next_interrupt
> Jan 14 23:27:03 koffer kernel: << uhci_clear_next_interrupt
> Jan 14 23:27:03 koffer kernel: >>> uhci_set_next_interrupt
> Jan 14 23:27:03 koffer kernel: << uhci_set_next_interrupt
> Jan 14 23:27:03 koffer kernel: >>> uhci_finish_urb cf02dbc0
> Jan 14 23:27:03 koffer kernel: >>> uhci_set_next_interrupt
> Jan 14 23:27:03 koffer kernel: << uhci_set_next_interrupt
> Jan 14 23:27:03 koffer kernel: >>> giveback cf02dbc0
> Jan 14 23:27:03 koffer kernel: spheroncam.c: spheroncam_complete urb:
> cf02dbc0 status: -84
>
> I have to point out that in this case there are no calls like
> disable_endpoint or uhci_urb_dequeue involved. Like as if its not the
> hub that detects the disconnect.
In this case it wasn't. The -84 (-EILSEQ) means that the controller
detected a violation of the USB protocol. Likewise, status = 2 means that
the interrupt occurred because of an error. Perhaps electrical noise from
unplugging the cable was interpreted as an illegal signal, before the hub
driver saw the disconnect.
Alan Stern
-------------------------------------------------------
The SF.Net email is sponsored by EclipseCon 2004
Premiere Conference on Open Tools Development and Integration
See the breadth of Eclipse activity. February 3-5 in Anaheim, CA.
http://www.eclipsecon.org/osdn
_______________________________________________
[EMAIL PROTECTED]
To unsubscribe, use the last form field at:
https://lists.sourceforge.net/lists/listinfo/linux-usb-devel
