Re: autosuspend issues with the Intel Bluetooth device [8087:07dc]

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> writes:
> On Thu, 4 Jul 2013, Bjørn Mork wrote:
>
>> > It may be that the device simply takes longer to resume than it should.  
>> > Or longer than btusb expects it to, which may not be the same thing.
>> 
>> Yes, that is what it looks like.  But the URBs are submitted as part of
>> the resume callback.  Shouldn't the device be alive and kicking when
>> this is called?  At least from the USB point of view, which is all the
>> driver can possibly know anything about? Is the problem that the
>> firmware finishes the USB resume before actually being ready to respond
>> to the HCI command?
>
> I don't know.  The USB spec gives devices 10 ms to recover during a 
> resume; after that they are supposed to be ready to operate normally.  
> This delay is already built into usbcore and it is visible in your 
> usbmon trace.
>
> There is one notable difference between your failure and success 
> traces.  Failure:
>
>> ffff88021ace62c0 3675041611 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
>> ffff88022228d140 3675041721 S Co:002:00 s 01 0b 0000 0001 0000 0
>> ffff88021ace62c0 3675042361 C Co:002:00 0 3 >
>> ffff88022228d140 3675042409 C Co:002:00 0 0
>> ffff88020c40f380 3675043359 C Ii:002:01 0 6 = 0f040101 010b
>> ffff88020c40f380 3675043429 S Ii:002:01 -115 64 <
>
> Success:
>
>> ffff88020c40f200 88163963 S Co:002:00 s 20 00 0000 0000 0003 3 = 011000
>> ffff88020c752980 88165215 C Ii:002:01 0 14 = 0e0c0101 10000600 05060200 0005
>> ffff88020c752980 88165281 S Ii:002:01 -115 64 <
>> ffff88020c40f200 88165327 C Co:002:00 0 3 >
>
> In the failure case, a Set-Interface request gets sent before the 
> interrupt URB completes.  Maybe that accounts for the unexpected 
> behavior.

Maybe.  But the device does send a message which translates as a valid
HCI message, so it looks like everything is OK up to and including the
USB layer.

I tried to figure out the exact meaning of that message, but that's not
straight forward unless you are familiar with the Bluetooth specs. Which
I'm certainly not.  What I did find out is only what the HCI debug code
also could tell me:

 0f - HCI_EV_CMD_STATUS
 04 - length: 4
 01 - status: 1
 01 - ncmds: 1
 010b - opcode: 0x0b01

Enabling the dynamic debugging in hci_core and hci_event makes this
clear, along with the fact that HCI core ignores this event:


Jul  5 12:27:21 nemi kernel: [44750.608222] btusb_tx_complete:574: hci1 urb ffff880231a10c00 status 0 count 3
Jul  5 12:27:21 nemi kernel: [44750.609223] btusb_intr_complete:281: hci1 urb ffff880231a109c0 status 0 count 6
Jul  5 12:27:21 nemi kernel: [44750.609297] hci_rx_work:3463: hci1
Jul  5 12:27:21 nemi kernel: [44750.609346] hci_rx_work:3492: hci1 Event packet
Jul  5 12:27:21 nemi kernel: [44750.609361] hci_cmd_status_evt:2418: hci1 opcode 0x0b01
Jul  5 12:27:21 nemi kernel: [44750.609371] hci_req_cmd_complete:3406: opcode 0x0b01 status 0x01
Jul  5 12:27:21 nemi kernel: [44750.609641] hci_dev_get:691: 1


The "hci_cmd_status_evt" message shows that we hit the default
do-nothing handler for events unknown to hci_event.c.  For some reason
this cancels the command timer:

	if (opcode != HCI_OP_NOP)
		del_timer(&hdev->cmd_timer);

But changing that only leads to the timer expiring ang logging

Jul  5 12:27:23 nemi kernel: [44752.532142] Bluetooth: hci1 command 0x1001 tx timeout
Jul  5 12:27:23 nemi kernel: [44752.532233] hci_cmd_work:3519: hci1 cmd_cnt 1 cmd queued 0

a few seconds later (0x1001 is HCI_OP_READ_LOCAL_VERSION, so that's the
command we're waiting for). Proper handling of the 0x0b01 event is most
likely required to continue here.

I do assume the device means to signal something by sending that 0x0b01
event, and based on the observed behaviour and existing code I guess
that something translates to "not ready yet - please resend last
command" or similar.  But I haven't been able to find any definition of
that event anywhere, so this is based on pure speculation.

Anyway, unless someone from the Bluetooth list shouts out, then I am
going to conclude that the device, USB core and btusb all behave
correctly, but that waking up this device (and likely other recent
devices) can fail because the HCI core fails to handle a link state
event it should handle.

I don't have any proposed fix, except ugly hacks to let the device have
some more time.  So I am hoping someone knowing Bluetooth will come up
with better ideas.



Bjørn
--
To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html




[Index of Archives]     [Bluez Devel]     [Linux Wireless Networking]     [Linux Wireless Personal Area Networking]     [Linux ATH6KL]     [Linux USB Devel]     [Linux Media Drivers]     [Linux Audio Users]     [Linux Kernel]     [Linux SCSI]     [Big List of Linux Books]

  Powered by Linux