Subject: Re: [PATCH] usb: reducing an usb-port auto-resume latency.
To: Alan Stern <stern@rowland.harvard.edu>,
        Mathias Nyman <mathias.nyman@linux.intel.com>
References: <Pine.LNX.4.44L0.1708231026490.1617-100000@iolanthe.rowland.org>
Cc: anshuman.gupta@intel.com, linux-usb@vger.kernel.org,
        linux-kernel@vger.kernel.org, gregkh@linuxfoundation.org
From: Mathias Nyman <mathias.nyman@intel.com>
Message-ID: <599DA6A1.8070801@intel.com>
Date: Wed, 23 Aug 2017 19:00:33 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101
 Thunderbird/38.8.0
MIME-Version: 1.0
In-Reply-To: <Pine.LNX.4.44L0.1708231026490.1617-100000@iolanthe.rowland.org>
Content-Type: text/plain; charset=windows-1252; format=flowed
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Content-Length: 3697
Lines: 87

On 23.08.2017 17:30, Alan Stern wrote:
> On Wed, 23 Aug 2017, Mathias Nyman wrote:
>
>> On 23.08.2017 09:18, anshuman.gupta@intel.com wrote:
>>> From: Anshuman Gupta <anshuman.gupta@intel.com>
>>>
>>> This patch will improve the variable auto-resume latency of an usb-port.
>>>
>>> When xhci gets a port status change event interrupt due to PORT_PLC
>>> (port link state transition), linux Host controller driver drives the
>>> resume signalling on the bus for the amount of time defined by
>>> USB_REUME_TIMEOUT(40ms) macro.
>>>
>>> This 40ms delay for resume signalling is in acceptable limit, but
>>> it get worse when xhci goes for polling mode in order to detect other
>>> events on its ports and modify rh_timer timer with a variable time out of
>>> 1ms to (HZ/4)ms.
>>>
>>> drivers/usb/core/hcd.c line 799
>>> mod_timer (&hcd->rh_timer, (jiffies/(HZ/4) + 1) * (HZ/4)).
>>>
>>> Due to above variable timeout usb auto-resume latency varies from
>>> 40ms to ~300ms.
>>>
>>> Log Snippet:
>>> ~128ms latency
>>> [   53.112049] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
>>> [   53.229200] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0004
>>> [   53.240177] usb 1-2: usb wakeup-resume
>>> [   53.240195] usb 1-2: finish resume
>>> [   53.240357] usb usb1-port2: resume, status 0
>>> -----------------------------------------------------------------
>>> ~300ms latency
>>> [   59.946620] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
>>> [   59.979341] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
>>> [   60.229342] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0004
>>> [   60.251321] usb 1-2: usb wakeup-resume
>>> [   60.251335] usb 1-2: finish resume
>>> [   60.251539] usb usb1-port2: resume, status 0
>>>
>>> This variable resume latency can be optimized, as in case of PORT_PLC
>>> change event rh_timer has already been modified with USB_RESUME_TIMEOUT
>>> (40ms) delay,leaving the rest to GetPortStatus and started polling for
>>> root hub status (invoking usb_hcd_poll_rh_status).
>>> We can avoid polling as we have already modified rh_timer with
>>> delay of 40ms.
>>>
>>> This patch set the HCD_FLAG_POLL_RH to hcd->flags after modification of
>>> rh_timer, and avoids polling of root hub status. so rh_timer can fire
>>> after 40ms and usb device auto-resuem latency will be around 40ms.
>>>
>>> Signed-off-by: Anshuman Gupta <anshuman.gupta@intel.com>
>>> ---
>>
>> Thanks,
>> adding and sending forward after 4.14-rc1
>
> This patch description doesn't make sense.  If you want to avoid
> resetting the root-hub timer by 250 ms, you should _clear_ the
> HCD_FLAG_POLL_RH flag, not _set_ it!  See this (slightly tricky) code
> in usb_hcd_poll_rh_status():
>
> 	if (hcd->uses_new_polling ? HCD_POLL_RH(hcd) :
> 			(length == 0 && hcd->status_urb != NULL))
> 		mod_timer (&hcd->rh_timer, (jiffies/(HZ/4) + 1) * (HZ/4));
>
> Since xhci-hcd does set the uses_new_polling flag, the "if" condition
> just tests the HCD_FLAG_POLL_RH bit.

The description could be a bit clearer, I agree, but the issue it
fixes seems correct.

We want start the rh polling when a HS port is found in resume state,
and we want to time it so that the it runs just after resume is complete (40ms)
This is why we have the mod_timer(&hcd->rh_timer, bus_state->resume_done[faked_port_index]);

This would all be fine, but the xhci event handler has a bug and it calls
usb_hcd_poll_rh_status(hcd) manually right after modifying rh_timer.

This causes hub thread to read port status before resume is ready, and we
need to wait for another 250ms before the rh thread can handle the port.

What this patch in the end does is just removing the manual usb_hcd_poll_rh_status(hcd)
in this case.

Thanks
-Mathias