Re: for-next hangs on test srp/012

[Jens Axboe <axboe@kernel.dk>]

On 12/11/18 6:23 PM, 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 <snitzer@redhat.com> wrote:
>>>>
>>>> On Tue, Dec 11 2018 at  7:19pm -0500,
>>>> Ming Lei <tom.leiming@gmail.com> wrote:
>>>>
>>>>> On Wed, Dec 12, 2018 at 8:04 AM Jens Axboe <axboe@kernel.dk> 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?

This one should be complete. The former should fix the case, this one
just adds the last two cases where we ignored ->cleared. For some of
them we'll never hit it since deferred isn't used for that, but I
think we're better off with full coverage.


diff --git a/lib/sbitmap.c b/lib/sbitmap.c
index 2261136ae067..5b3e56d68dab 100644
--- a/lib/sbitmap.c
+++ b/lib/sbitmap.c
@@ -20,6 +20,47 @@
 #include <linux/sbitmap.h>
 #include <linux/seq_file.h>
 
+/*
+ * 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;
@@ -242,7 +249,7 @@ bool sbitmap_any_bit_set(const struct sbitmap *sb)
 	unsigned int i;
 
 	for (i = 0; i < sb->map_nr; i++) {
-		if (sb->map[i].word)
+		if (sb->map[i].word & ~sb->map[i].cleared)
 			return true;
 	}
 	return false;
@@ -255,9 +262,10 @@ bool sbitmap_any_bit_clear(const struct sbitmap *sb)
 
 	for (i = 0; i < sb->map_nr; i++) {
 		const struct sbitmap_word *word = &sb->map[i];
+		unsigned long mask = word->word & ~word->cleared;
 		unsigned long ret;
 
-		ret = find_first_zero_bit(&word->word, word->depth);
+		ret = find_first_zero_bit(&mask, word->depth);
 		if (ret < word->depth)
 			return true;
 	}

-- 
Jens Axboe