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=-0.8 required=3.0 tests=DKIM_SIGNED,DKIM_VALID, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS 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 86D73C2D0CA for ; Thu, 12 Dec 2019 07:34:32 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 5E89D2465E for ; Thu, 12 Dec 2019 07:34:32 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=unipv-it.20150623.gappssmtp.com header.i=@unipv-it.20150623.gappssmtp.com header.b="lmtQeDO0" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1728140AbfLLHeb (ORCPT ); Thu, 12 Dec 2019 02:34:31 -0500 Received: from mail-wr1-f68.google.com ([209.85.221.68]:45927 "EHLO mail-wr1-f68.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1728134AbfLLHeb (ORCPT ); Thu, 12 Dec 2019 02:34:31 -0500 Received: by mail-wr1-f68.google.com with SMTP id j42so1505432wrj.12 for ; Wed, 11 Dec 2019 23:34:29 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=unipv-it.20150623.gappssmtp.com; s=20150623; h=message-id:subject:from:to:cc:date:in-reply-to:references :user-agent:mime-version:content-transfer-encoding; bh=Ouu20+mE9n/tPYHmfkHzcHWK0RTLjVdq3889eJu3VP0=; b=lmtQeDO0RVMVq5UaQ/yHPY07AfXs62TQ590bzWxxhQaAA/OaOB21aNqrC1Zlo45s+i 0vqOpszc8Sfm2BBuncYr8tlj7W9bIc7EYH4J1UDr3BBFEYge7eIFNYAJWO2NQIzACRy8 sSVzNMIr1hZEY5iikGTDJf2NPrHPoeHl5AG5OylC98AeaeJw96Euvod9mMvblTCJGjD9 6qsE8uOYHKRAsu1xmiY5Az/7p9YfDoB1FtlTfUJDUJsN9RxZJ0sIKI+lDVR/bCYUud7F n3m5AqVOLGyqEbqy9t5Cdr6E/ifNMpVhVtWyCb8LVjExB3CRLPxurspWLQshKirl27l9 TJtA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:message-id:subject:from:to:cc:date:in-reply-to :references:user-agent:mime-version:content-transfer-encoding; bh=Ouu20+mE9n/tPYHmfkHzcHWK0RTLjVdq3889eJu3VP0=; b=lJMtT10wlC9v3QbhptlcqxzGxJxXvE7FpwNLYj6odBakZDV1dh/WShnBE0Oa8V3bzq oTOV2CP7/JnY4vi6IBBnLX6Hojo4paZheMJBkTm1aTj1O2MOQaOSVg5fe8vOv9kxV0OX jIrbpsklri8cThm+PJPGHw/irgX4m8L1cz5LUVgFOdmEKZsSl38PQcPLyRD5b3/OnPZR cP1JK4do2J6N/qFcRs6S1Wzsi1p2VYmfdTTRVL3FBIGcUwZpvv5U0Z4RQ0rtxgyBzrBk zEVe6lkp9IaYfG2lXEcaR1GSPnSjfVUJzs4ARnS347yrQCldS5a2n7lyvhcPzHJOVDQN nxHA== X-Gm-Message-State: APjAAAWduuFUlHu8tiadtS4vY6bpqVQfPtvNL0O/Kr4KnIzDGg3n4FoY l86yjT5tGCCI7IS/K1s9qIDtAw== X-Google-Smtp-Source: APXvYqwlTzWP0XWOqGIJf4UvsmxnRFuIxB+FV85xriWGt31SdJo44/OLaYrtTWBOIOO+0sMh8wDsnw== X-Received: by 2002:a5d:6802:: with SMTP id w2mr4385600wru.353.1576136068427; Wed, 11 Dec 2019 23:34:28 -0800 (PST) Received: from angus.unipv.it (angus.unipv.it. [193.206.67.163]) by smtp.gmail.com with ESMTPSA id o66sm1101251wmo.20.2019.12.11.23.34.27 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 11 Dec 2019 23:34:27 -0800 (PST) Message-ID: <430b562eeba371ef3b917193246b9eb6c46be71e.camel@unipv.it> Subject: Re: AW: Slow I/O on USB media after commit f664a3cc17b7d0a2bc3b3ab96181e1029b0ec0e6 From: Andrea Vai To: Ming Lei , "Theodore Y. Ts'o" Cc: "Schmid, Carsten" , Finn Thain , Damien Le Moal , Alan Stern , Jens Axboe , Johannes Thumshirn , USB list , SCSI development list , Himanshu Madhani , Hannes Reinecke , Omar Sandoval , "Martin K. Petersen" , Greg KH , Hans Holmberg , Kernel development list , linux-ext4@vger.kernel.org, linux-fsdevel@vger.kernel.org Date: Thu, 12 Dec 2019 08:34:26 +0100 In-Reply-To: <20191211213316.GA14983@ming.t460p> References: <20191129005734.GB1829@ming.t460p> <20191129023555.GA8620@ming.t460p> <320b315b9c87543d4fb919ecbdf841596c8fbcea.camel@unipv.it> <20191203022337.GE25002@ming.t460p> <8196b014b1a4d91169bf3b0d68905109aeaf2191.camel@unipv.it> <20191210080550.GA5699@ming.t460p> <20191211024137.GB61323@mit.edu> <20191211040058.GC6864@ming.t460p> <20191211160745.GA129186@mit.edu> <20191211213316.GA14983@ming.t460p> Content-Type: text/plain; charset="UTF-8" User-Agent: Evolution 3.32.5 (3.32.5-1.fc30) MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Sender: linux-ext4-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-ext4@vger.kernel.org Il giorno gio, 12/12/2019 alle 05.33 +0800, Ming Lei ha scritto: > On Wed, Dec 11, 2019 at 11:07:45AM -0500, Theodore Y. Ts'o wrote: > > On Wed, Dec 11, 2019 at 12:00:58PM +0800, Ming Lei wrote: > > > I didn't reproduce the issue in my test environment, and follows > > > Andrea's test commands[1]: > > > > > > mount UUID=$uuid /mnt/pendrive 2>&1 |tee -a $logfile > > > SECONDS=0 > > > cp $testfile /mnt/pendrive 2>&1 |tee -a $logfile > > > umount /mnt/pendrive 2>&1 |tee -a $logfile > > > > > > The 'cp' command supposes to open/close the file just once, > however > > > ext4_release_file() & write pages is observed to run for 4358 > times > > > when executing the above 'cp' test. > > > > Why are we sure the ext4_release_file() / _fput() is coming from > the > > cp command, as opposed to something else that might be running on > the > > system under test? _fput() is called by the kernel when the last > > Please see the log: > > https://lore.kernel.org/linux-scsi/3af3666920e7d46f8f0c6d88612f143ffabc743c.camel@unipv.it/2-log_ming.zip > > Which is collected by: > > #!/bin/sh > MAJ=$1 > MIN=$2 > MAJ=$(( $MAJ << 20 )) > DEV=$(( $MAJ | $MIN )) > > /usr/share/bcc/tools/trace -t -C \ > 't:block:block_rq_issue (args->dev == '$DEV') "%s %d %d", args- > >rwbs, args->sector, args->nr_sector' \ > 't:block:block_rq_insert (args->dev == '$DEV') "%s %d %d", args- > >rwbs, args->sector, args->nr_sector' > > $MAJ:$MIN points to the USB storage disk. > > From the above IO trace, there are two write paths, one is from cp, > another is from writeback wq. > > The stackcount trace[1] is consistent with the IO trace log since it > only shows two IO paths, that is why I concluded that the write done > via > ext4_release_file() is from 'cp'. > > [1] > https://lore.kernel.org/linux-scsi/320b315b9c87543d4fb919ecbdf841596c8fbcea.camel@unipv.it/2-log_ming_20191129_150609.zip > > > reference to a struct file is released. (Specifically, if you > have a > > fd which is dup'ed, it's only when the last fd corresponding to > the > > struct file is closed, and the struct file is about to be > released, > > does the file system's f_ops->release function get called.) > > > > So the first question I'd ask is whether there is anything else > going > > on the system, and whether the writes are happening to the USB > thumb > > drive, or to some other storage device. And if there is something > > else which is writing to the pendrive, maybe that's why no one > else > > has been able to reproduce the OP's complaint.... > > OK, we can ask Andrea to confirm that via the following trace, which > will add pid/comm info in the stack trace: > > /usr/share/bcc/tools/stackcount blk_mq_sched_request_inserted > > Andrea, could you collect the above log again when running new/bad > kernel for confirming if the write done by ext4_release_file() is > from > the 'cp' process? Yes, I will try to do it as soon as possible and let you know. I will also try xfs or btrfs, as you suggested in another message. Thanks, and bye Andrea