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=-7.0 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=no 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 0C8B7C433E1 for ; Thu, 27 Aug 2020 12:06:59 +0000 (UTC) Received: from kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by mail.kernel.org (Postfix) with ESMTP id CA285207F7 for ; Thu, 27 Aug 2020 12:06:58 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org CA285207F7 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=mentor.com Authentication-Results: mail.kernel.org; spf=pass smtp.mailfrom=owner-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix) id 61CD88E0018; Thu, 27 Aug 2020 08:06:58 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 5F3C28E0006; Thu, 27 Aug 2020 08:06:58 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id 4E2548E0018; Thu, 27 Aug 2020 08:06:58 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from forelay.hostedemail.com (smtprelay0023.hostedemail.com [216.40.44.23]) by kanga.kvack.org (Postfix) with ESMTP id 3857F8E0006 for ; Thu, 27 Aug 2020 08:06:58 -0400 (EDT) Received: from smtpin20.hostedemail.com (10.5.19.251.rfc1918.com [10.5.19.251]) by forelay03.hostedemail.com (Postfix) with ESMTP id ED2B9824934B for ; Thu, 27 Aug 2020 12:06:57 +0000 (UTC) X-FDA: 77196222474.20.uncle12_2b01ebf2706d Received: from filter.hostedemail.com (10.5.16.251.rfc1918.com [10.5.16.251]) by smtpin20.hostedemail.com (Postfix) with ESMTP id 11341180C0F74 for ; Thu, 27 Aug 2020 12:06:49 +0000 (UTC) X-HE-Tag: uncle12_2b01ebf2706d X-Filterd-Recvd-Size: 8641 Received: from esa2.mentor.iphmx.com (esa2.mentor.iphmx.com [68.232.141.98]) by imf16.hostedemail.com (Postfix) with ESMTP for ; Thu, 27 Aug 2020 12:06:47 +0000 (UTC) IronPort-SDR: k97R73RFQoQzWGc4oKm2cN5aK9ctx0vKzH8cS1yfyNfjhdrPXGcr00kpM44GppoM6jpURZPgfW oChncwA+qLhoI9Y0Jga+oa/LPb/cICpZd1LEgEA75OD0o7fmK4/BGtFyFTWImA3a6nSOKWEKxt 9CUIuGsWNRUVMQ4xAcL1iJwXRWxtWb2lgkbEuE13P8VR4c9xKQy7fVr6E01vuGkkEUgsjOBdrR qNb5+xxNTnheujKhKM8AFxycEGTDqMEHuivdp01FCOH4u5cIivVGNJI9CMV/AcLn94BOeZkiQc eVI= X-IronPort-AV: E=Sophos;i="5.76,359,1592899200"; d="scan'208";a="52331555" Received: from orw-gwy-02-in.mentorg.com ([192.94.38.167]) by esa2.mentor.iphmx.com with ESMTP; 27 Aug 2020 04:06:45 -0800 IronPort-SDR: 8VB2H+hJ/+U8lqR67sLBmUJ/+z+Qwbylgkedv2al+v2XOSu4h0w3bSdbrI+bmPeAij+7jQD9wS t5TMIn4sN+UQeIV3QTfw/Em+JiccVrtY03SP4XN0FyIe492zKnsl7okA7FoiD25gwQOiBekLQ0 Xrgbfu9hu4OXhQRVWZlPAhwOFTvX+HFd0s4SzU8fHFF076Dy5pkpU/diaQENp2de/p/PfvFkPe wxhgLwyZvAzEGDHmM070yIQo1HZ5H9SlFkXNwTHsmUSjwVs4IBBScgqmZ8z695HKTlf3+zdFkb 72o= Subject: Re: PROBLEM: Long Workqueue delays V2 From: Jim Baxter To: , , , References: <625615f2-3a6b-3136-35f9-2f2fb3c110cf@mentor.com> <066753ec-eddc-d7f6-5cc8-fe282baba6ec@mentor.com> CC: , "Frkuska, Joshua" , "Resch Carsten (CM/ESO6)" , "Rosca, Eugeniu (ADITG/ESB)" , "Craske, Mark" , "Brown, Michael" Message-ID: Date: Thu, 27 Aug 2020 13:06:39 +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: <066753ec-eddc-d7f6-5cc8-fe282baba6ec@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) X-Rspamd-Queue-Id: 11341180C0F74 X-Spamd-Result: default: False [0.00 / 100.00] X-Rspamd-Server: rspam01 X-Bogosity: Ham, tests=bogofilter, spamicity=0.000000, version=1.2.4 Sender: owner-linux-mm@kvack.org Precedence: bulk X-Loop: owner-majordomo@kvack.org List-ID: Has anyone any ideas of how to investigate this delay further? Comparing the perf output for unplugging the USB stick and using umount which does not cause these delays in other workqueues the main difference is that the problem case is executing the code in invalidate_mapping_pages() and a large part of that arch_local_irq_restore() which is part of releasing a lock, I would usually expect that requesting a lock would be where delays may occur. --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 Best regards, Jim -------- Original Message -------- Subject: Re: PROBLEM: Long Workqueue delays V2 From: Jim Baxter To: Date: Wed Aug 19 2020 14:12:24 GMT+0100 (British Summer Time) > Added linux-block List which may also be relevant to this issue. > > -------- Original Message -------- > Subject: PROBLEM: Long Workqueue delays V2 > From: Jim Baxter > To: linux-fsdevel@vger.kernel.org, linux-kernel@vger.kernel.org, linux-mm@kvack.org > CC: "Resch Carsten (CM/ESO6)" , "Rosca, Eugeniu (ADITG/ESB)" > Date: Tue, 18 Aug 2020 12:58:13 +0100 > >> 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 >>