From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-8.2 required=3.0 tests=BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,NICE_REPLY_A,SPF_HELO_NONE, SPF_PASS,USER_AGENT_SANE_1 autolearn=unavailable autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 0A277C433DF for ; Tue, 18 Aug 2020 16:45:44 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id E8B512080C for ; Tue, 18 Aug 2020 16:45:43 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726985AbgHRQph (ORCPT ); Tue, 18 Aug 2020 12:45:37 -0400 Received: from esa1.mentor.iphmx.com ([68.232.129.153]:11863 "EHLO esa1.mentor.iphmx.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726806AbgHRQpg (ORCPT ); Tue, 18 Aug 2020 12:45:36 -0400 IronPort-SDR: QGvGC+94m2CHtZyrNvUzm1RSd62BiUYpgiHrN4129CMNbKP2FTxlEpMvz76wrBSlktM9srnqtt yeR6WJsj4I4oLhU4273mwWNWT4j7wiEiEhSjhwM+HJ/ChMIYIQ3UraidHYHKFsr8DJlbp0ktTL j3vjkR7KsmP2/nayyGWU1FT4NuVEPKiZ5I4e4uJxzPbcloeoIzz9H9MpnM4fRkcCb5XTGcDTcE 0MP1O1jN10QZ10Ox9ypYMa5HpSv7SRT/1+UCYMhLr9d2fyxfxQhTgOkbIvHRq2TIhA2gC/lE0k HLI= X-IronPort-AV: E=Sophos;i="5.76,328,1592899200"; d="scan'208";a="54210262" Received: from orw-gwy-02-in.mentorg.com ([192.94.38.167]) by esa1.mentor.iphmx.com with ESMTP; 18 Aug 2020 08:45:35 -0800 IronPort-SDR: LNzWom/QVpUDAc+OGyrCLYIWndKeE6BAPtIoPS0YTQcsEU9gt1mjI+ag3y2MS7X9PG5fNyV83j IcP6A+JgWGbKaLNnB47T5jbK6jdokew0r5JLGAjl3nb+ehqLOXZwnJyuDBdkXUcndM2MrmC6Z3 6LW5QBs+CkAJPQxmBkqM5xr/wFfxyifzJkuUaVBM+wIPIVyRGVJOtLvwPVyogr9rngsVOsp1EX SbqB2TUpUKFe6Fv5ljkwovsRyZ9LiJC+EP4QYNbGgqXsNsYXqgTcPHfCNJnEqWRApL4FfmOdJ7 WcA= Subject: Re: PROBLEM: Long Workqueue delays V2 From: Jim Baxter To: , , , CC: "Resch Carsten (CM/ESO6)" , "Rosca, Eugeniu (ADITG/ESB)" References: <625615f2-3a6b-3136-35f9-2f2fb3c110cf@mentor.com> Message-ID: Date: Tue, 18 Aug 2020 17:45:29 +0100 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Thunderbird/68.10.0 MIME-Version: 1.0 In-Reply-To: <625615f2-3a6b-3136-35f9-2f2fb3c110cf@mentor.com> Content-Type: text/plain; charset="utf-8" Content-Language: en-GB Content-Transfer-Encoding: 7bit X-Originating-IP: [137.202.0.90] X-ClientProxiedBy: SVR-IES-MBX-08.mgc.mentorg.com (139.181.222.8) To SVR-IES-MBX-03.mgc.mentorg.com (139.181.222.3) Sender: linux-fsdevel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-fsdevel@vger.kernel.org Added linux-block List which may also be relevant to this issue. On 18 Aug 2020 12:58, Jim Baxter wrote: > I am asking this question again to include the fs-devel list. > > > 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. > > > > We first noticed this issue on custom hardware and we have recreated it > on an RCar Starter Kit using a test module [1] to replicate the > behaviour, the test module outputs any delays of greater then 9ms. > > To run the test we have a 4GB random file on a USB stick and perform > the following test. > The stick is mounted as R/O and we are copying data from the stick: > > - Mount the stick. > mount -o ro,remount /dev/sda1 > > - Load the Module: > # taskset -c 0 modprobe latency-mon > > - Copy large amount of data from the stick: > # dd if=/run/media/sda1/sample.txt of=/dev/zero > [ 1437.517603] DELAY: 10 > 8388607+1 records in > 8388607+1 records out > > > - 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. > > > > Using umount stops the issue occurring but is unfortunately not guaranteed > in our particular system. > > > From my analysis the hub_event workqueue kworker/0:1+usb thread uses around > 98% of the CPU. > > I have traced the workqueue:workqueue_queue_work function while unplugging the USB > and there is no particular workqueue function being executed a lot more then the > others for the kworker/0:1+usb thread. > > > Using perf I identified 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 am aware there will be delays on the shared workqueue, are the delays > we are seeing considered normal? > > > Is there any way to mitigate or identify where the delay is? > I am unsure if this is a memory or filesystem subsystem issue. > > > Thank you for you help. > > Thanks, > Jim Baxter > > [1] Test Module: > // SPDX-License-Identifier: GPL-2.0 > /* > * Simple WQ latency monitoring > * > * Copyright (C) 2020 Advanced Driver Information Technology. > */ > > #include > #include > #include > > #define PERIOD_MS 100 > > static struct delayed_work wq; > static u64 us_save; > > static void wq_cb(struct work_struct *work) > { > u64 us = ktime_to_us(ktime_get()); > u64 us_diff = us - us_save; > u64 us_print = 0; > > if (!us_save) > goto skip_print; > > > us_print = us_diff / 1000 - PERIOD_MS; > if (us_print > 9) > pr_crit("DELAY: %lld\n", us_print); > > skip_print: > us_save = us; > schedule_delayed_work(&wq, msecs_to_jiffies(PERIOD_MS)); > } > > static int latency_mon_init(void) > { > us_save = 0; > INIT_DELAYED_WORK(&wq, wq_cb); > schedule_delayed_work(&wq, msecs_to_jiffies(PERIOD_MS)); > > return 0; > } > > static void latency_mon_exit(void) > { > cancel_delayed_work_sync(&wq); > pr_info("%s\n", __func__); > } > > module_init(latency_mon_init); > module_exit(latency_mon_exit); > MODULE_AUTHOR("Eugeniu Rosca "); > MODULE_LICENSE("GPL"); > > > [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 > > | > --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 > > | > --30.17%--truncate_inode_pages_range >