Re: PROBLEM: Long Workqueue delays.

[Jim Baxter]

On 17/08/2020 12:57, Greg KH wrote:
> On Mon, Aug 17, 2020 at 12:40:03PM +0100, Jim Baxter wrote:
>> We have issues with the workqueue of the kernel overloading the CPU 0 
>> when we we disconnect a USB stick.
>>
>> This results in other items on the shared workqueue being delayed by
>> around 6.5 seconds with a default kernel configuration and 2.3 seconds
>> on a config tailored for our RCar embedded platform.
>>
> 
> Is this data really flushed out to the device?
> 
I am unsure if the delay is due to a single system or a combination of memory,
usb or filesystem operations, the delay also occurs if the device is mounted
as ro and using the sync option.

Using umount stops the issue occurring but is unfortunately not guaranteed in
our particular system.

>> - Disconnect the USB stick:
>> [ 1551.796792] usb 2-1: USB disconnect, device number 2
>> [ 1558.625517] DELAY: 6782
>>
>>
>> The Delay output 6782 is in milliseconds.
> 
> What USB workqueue is taking so long?> 
> The one trying to deal with the filesystem flushing out the data that it
> can't do now that the device is removed?  :)
> 
>From my analysis it is the hub_event workqueue shown to be using most of the CPU,
the kworker/0:1+usb thread uses around 98% of the CPU.

I have traced the workqueue:workqueue_queue_work function while unplugging the USB
but not found a particular workqueue function being called a lot.

Using perf Iidentified the hub_events workqueue was spending a lot of time in
invalidate_partition(), I have included a cut down the captured data from perf in
[2] which shows the additional functions where the kworker spends most of its time.


I realise that not unmounting the USB stick is not ideal, though I wonder what 
additional work is done when unplugging the USB stick compared to unmounting it.
I guess it may be waiting for a time-out during the operation without the unmount.


Thanks,
Jim Baxter

> thanks,
> 
> greg k-h
> 

[2] perf trace:
    95.22%     0.00%  kworker/0:2-eve  [kernel.kallsyms]
    |
    ---ret_from_fork
       kthread
       worker_thread
       |          
        --95.15%--process_one_work
		  |          
		   --94.99%--hub_event
			 |          
			  --94.99%--usb_disconnect
			  <snip>
				|  
				--94.90%--invalidate_partition
				   __invalidate_device
				   |          
				   |--64.55%--invalidate_bdev
				   |  |          
				   |   --64.13%--invalidate_mapping_pages
				   |     |          
				   |     |--24.09%--invalidate_inode_page
				   |     |   |          
				   |     |   --23.44%--remove_mapping
				   |     |     |          
				   |     |      --23.20%--__remove_mapping
				   |     |        |          
				   |     |         --21.90%--arch_local_irq_restore
				   |     |          
				   |     |--22.44%--arch_local_irq_enable
				   |          
					--30.35%--shrink_dcache_sb 
					<snip>
					  |      
					  --30.17%--truncate_inode_pages_range