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=-5.4 required=3.0 tests=HEADER_FROM_DIFFERENT_DOMAINS, INCLUDES_PATCH,MAILING_LIST_MULTI,SPF_PASS,URIBL_BLOCKED,USER_AGENT_MUTT autolearn=ham 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 ED3B9C6783B for ; Wed, 12 Dec 2018 01:37:42 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id AB5CE2081B for ; Wed, 12 Dec 2018 01:37:42 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org AB5CE2081B Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=redhat.com Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=linux-block-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726220AbeLLBhm (ORCPT ); Tue, 11 Dec 2018 20:37:42 -0500 Received: from mx1.redhat.com ([209.132.183.28]:35116 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726201AbeLLBhm (ORCPT ); Tue, 11 Dec 2018 20:37:42 -0500 Received: from smtp.corp.redhat.com (int-mx06.intmail.prod.int.phx2.redhat.com [10.5.11.16]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 564FA3084294; Wed, 12 Dec 2018 01:37:41 +0000 (UTC) Received: from ming.t460p (ovpn-8-17.pek2.redhat.com [10.72.8.17]) by smtp.corp.redhat.com (Postfix) with ESMTPS id 713BA5C888; Wed, 12 Dec 2018 01:37:31 +0000 (UTC) Date: Wed, 12 Dec 2018 09:37:26 +0800 From: Ming Lei To: Jens Axboe Cc: Ming Lei , Mike Snitzer , Bart Van Assche , linux-block Subject: Re: for-next hangs on test srp/012 Message-ID: <20181212013725.GA541@ming.t460p> References: <1544569107.185366.391.camel@acm.org> <0688562b-7776-7efe-10dd-caf2a6a4f274@kernel.dk> <20181212002759.GC20445@redhat.com> <41d15b87-d32e-9c6d-d68e-03bd5e7b74b0@kernel.dk> <05be643a-46b8-c836-11bf-005dbb0df9e4@kernel.dk> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <05be643a-46b8-c836-11bf-005dbb0df9e4@kernel.dk> User-Agent: Mutt/1.9.1 (2017-09-22) X-Scanned-By: MIMEDefang 2.79 on 10.5.11.16 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.40]); Wed, 12 Dec 2018 01:37:41 +0000 (UTC) Sender: linux-block-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-block@vger.kernel.org On Tue, Dec 11, 2018 at 06:23:31PM -0700, Jens Axboe wrote: > On 12/11/18 6:05 PM, Jens Axboe wrote: > > On 12/11/18 5:38 PM, Ming Lei wrote: > >> On Wed, Dec 12, 2018 at 8:28 AM Mike Snitzer wrote: > >>> > >>> On Tue, Dec 11 2018 at 7:19pm -0500, > >>> Ming Lei wrote: > >>> > >>>> On Wed, Dec 12, 2018 at 8:04 AM Jens Axboe wrote: > >>>>> > >>>>> On 12/11/18 3:58 PM, Bart Van Assche wrote: > >>>>>> Hi Jens, > >>>>>> > >>>>>> If I run the following subset of blktests: > >>>>>> > >>>>>> while :; do ./check -q srp && ./check -q nvmeof-mp; done > >>>>>> > >>>>>> against today's for-next branch (commit dd2bf2df85a7) then after some > >>>>>> time the following hang is reported: > >>>>>> > >>>>>> INFO: task fio:14869 blocked for more than 120 seconds. > >>>>>> Not tainted 4.20.0-rc6-dbg+ #1 > >>>>>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > >>>>>> fio D25272 14869 14195 0x00000000 > >>>>>> Call Trace: > >>>>>> __schedule+0x401/0xe50 > >>>>>> schedule+0x4e/0xd0 > >>>>>> io_schedule+0x21/0x50 > >>>>>> blk_mq_get_tag+0x46d/0x640 > >>>>>> blk_mq_get_request+0x7c0/0xa00 > >>>>>> blk_mq_make_request+0x241/0xa70 > >>>>>> generic_make_request+0x411/0x950 > >>>>>> submit_bio+0x9b/0x250 > >>>>>> blkdev_direct_IO+0x7fb/0x870 > >>>>>> generic_file_direct_write+0x119/0x210 > >>>>>> __generic_file_write_iter+0x11c/0x280 > >>>>>> blkdev_write_iter+0x13c/0x220 > >>>>>> aio_write+0x204/0x310 > >>>>>> io_submit_one+0x9c6/0xe70 > >>>>>> __x64_sys_io_submit+0x115/0x340 > >>>>>> do_syscall_64+0x71/0x210 > >>>>>> entry_SYSCALL_64_after_hwframe+0x49/0xbe > >>>>>> > >>>>>> When that hang occurs my list-pending-block-requests script does not show > >>>>>> any pending requests: > >>>>>> > >>>>>> # list-pending-block-requests > >>>>>> dm-0 > >>>>>> loop0 > >>>>>> loop1 > >>>>>> loop2 > >>>>>> loop3 > >>>>>> loop4 > >>>>>> loop5 > >>>>>> loop6 > >>>>>> loop7 > >>>>>> nullb0 > >>>>>> nullb1 > >>>>>> sda > >>>>>> sdb > >>>>>> sdc > >>>>>> sdd > >>>>>> vda > >>>>>> vdb > >>>>>> > >>>>>> Enabling fail_if_no_path mode did not resolve the hang so I don't think > >>>>>> that the root cause is in any of the dm drivers used in this test: > >>>>>> > >>>>>> # dmsetup ls | while read dm rest; do dmsetup message $dm 0 fail_if_no_path; done; dmsetup remove_all; dmsetup table > >>>>>> 360014056e756c6c62300000000000000: 0 65536 multipath 0 1 alua 1 1 service-time 0 1 2 8:16 1 1 > >>>>>> > >>>>>> The same test passes against kernel v4.20-rc6. > >>>>> > >>>>> What device is this being run on? > >>>> > >>>> I saw this issue on usb storage too. > >>>> > >>>> Seems it is introduced by commit ea86ea2cdced ("sbitmap: ammortize cost of > >>>> clearing bits"). When the IO hang happens, .cleared is 2, and .busy is 0 on > >>>> the sched_tag's sbitmap queue. > >>> > >>> You saw this running the same tests as Bart? > >> > >> Not the srp test as done by Bart, I just run 'parted' test on usb storage disk, > >> see the attached test script. > >> > >> Mostly it can be triggered in one run, sometimes it needs more. > > > > I'll take a look. The ->cleared doesn't make sense for QD=1, or on > > one word in general. But I'd like to try and understand why it hangs. > > > > Are you using a scheduler? > > OK, I think I see what it is, the shallow is missing the deferred clear. > On top of this, probably worth to check at what depths deferred starts > to make sense. For QD == 1, definitely not. But that should be on top of > the fix. > > Can you try this one? > > > diff --git a/lib/sbitmap.c b/lib/sbitmap.c > index 2261136ae067..d98ba7af6bce 100644 > --- a/lib/sbitmap.c > +++ b/lib/sbitmap.c > @@ -20,6 +20,47 @@ > #include > #include > > +/* > + * See if we have deferred clears that we can batch move > + */ > +static inline bool sbitmap_deferred_clear(struct sbitmap *sb, int index) > +{ > + unsigned long mask, val; > + unsigned long __maybe_unused flags; > + bool ret = false; > + > + /* Silence bogus lockdep warning */ > +#if defined(CONFIG_LOCKDEP) > + local_irq_save(flags); > +#endif > + spin_lock(&sb->map[index].swap_lock); > + > + if (!sb->map[index].cleared) > + goto out_unlock; > + > + /* > + * First get a stable cleared mask, setting the old mask to 0. > + */ > + do { > + mask = sb->map[index].cleared; > + } while (cmpxchg(&sb->map[index].cleared, mask, 0) != mask); > + > + /* > + * Now clear the masked bits in our free word > + */ > + do { > + val = sb->map[index].word; > + } while (cmpxchg(&sb->map[index].word, val, val & ~mask) != val); > + > + ret = true; > +out_unlock: > + spin_unlock(&sb->map[index].swap_lock); > +#if defined(CONFIG_LOCKDEP) > + local_irq_restore(flags); > +#endif > + return ret; > +} > + > int sbitmap_init_node(struct sbitmap *sb, unsigned int depth, int shift, > gfp_t flags, int node) > { > @@ -70,6 +111,9 @@ void sbitmap_resize(struct sbitmap *sb, unsigned int depth) > unsigned int bits_per_word = 1U << sb->shift; > unsigned int i; > > + for (i = 0; i < sb->map_nr; i++) > + sbitmap_deferred_clear(sb, i); > + > sb->depth = depth; > sb->map_nr = DIV_ROUND_UP(sb->depth, bits_per_word); > > @@ -112,47 +156,6 @@ static int __sbitmap_get_word(unsigned long *word, unsigned long depth, > return nr; > } > > -/* > - * See if we have deferred clears that we can batch move > - */ > -static inline bool sbitmap_deferred_clear(struct sbitmap *sb, int index) > -{ > - unsigned long mask, val; > - unsigned long __maybe_unused flags; > - bool ret = false; > - > - /* Silence bogus lockdep warning */ > -#if defined(CONFIG_LOCKDEP) > - local_irq_save(flags); > -#endif > - spin_lock(&sb->map[index].swap_lock); > - > - if (!sb->map[index].cleared) > - goto out_unlock; > - > - /* > - * First get a stable cleared mask, setting the old mask to 0. > - */ > - do { > - mask = sb->map[index].cleared; > - } while (cmpxchg(&sb->map[index].cleared, mask, 0) != mask); > - > - /* > - * Now clear the masked bits in our free word > - */ > - do { > - val = sb->map[index].word; > - } while (cmpxchg(&sb->map[index].word, val, val & ~mask) != val); > - > - ret = true; > -out_unlock: > - spin_unlock(&sb->map[index].swap_lock); > -#if defined(CONFIG_LOCKDEP) > - local_irq_restore(flags); > -#endif > - return ret; > -} > - > static int sbitmap_find_bit_in_index(struct sbitmap *sb, int index, > unsigned int alloc_hint, bool round_robin) > { > @@ -215,6 +218,7 @@ int sbitmap_get_shallow(struct sbitmap *sb, unsigned int alloc_hint, > index = SB_NR_TO_INDEX(sb, alloc_hint); > > for (i = 0; i < sb->map_nr; i++) { > +again: > nr = __sbitmap_get_word(&sb->map[index].word, > min(sb->map[index].depth, shallow_depth), > SB_NR_TO_BIT(sb, alloc_hint), true); > @@ -223,6 +227,9 @@ int sbitmap_get_shallow(struct sbitmap *sb, unsigned int alloc_hint, > break; > } > > + if (sbitmap_deferred_clear(sb, index)) > + goto again; > + > /* Jump to next index. */ > index++; > alloc_hint = index << sb->shift; Yeah, this one does work. thanks, Ming