Bug 212305 - blktests block/009 fails on linux-next next-20210304 failure rate 1/669
Summary: blktests block/009 fails on linux-next next-20210304 failure rate 1/669
Status: NEW
Alias: None
Product: IO/Storage
Classification: Unclassified
Component: Block Layer (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Jens Axboe
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-03-16 17:01 UTC by Luis Chamberlain
Modified: 2021-03-19 19:16 UTC (History)
0 users

See Also:
Kernel Version: 5.12.0-rc1-next-20210304
Tree: Mainline
Regression: No


Attachments

Description Luis Chamberlain 2021-03-16 17:01:40 UTC
While using kdevops [0] to test block layer with blktests to create a baseline I found that the test block/009 can fail on linux-next tag next-20210304 after running the test 669 times in a loop.

To reproduce you can get blktest set up with kdevops:

make menuconfig # configure and enable blktests, only enable to test block and select to test linux-next
make bringup # bring up kvm guests to test
make blktests # build and install blktests 

Typically one can just run a test against the known baseline with:

make blktests-baseline

But since we just want to busy loop test block/009:

ssh blktests-baseline
cd /usr/local/blktests/
i=1; while true; do ./check block/009; if [[ $? -ne 0 ]]; then echo "FAIL at $i"; break; else echo "OK at $i"; fi; let i=$i+1; done

Below are the details 
mcgrof@bicho ~/devel/kdevops (git::master)$ cat workflows/blktests/results/5.12.0-rc1-next-20210304/nodev/block/009
runtime	1.504s
description	check page-cache coherency after BLKDISCARD
exit_status	0
reason	output
date	2021-03-16 16:25:28
status	fail
mcgrof@bicho ~/devel/kdevops (git::master)$ cat workflows/blktests/results/5.12.0-rc1-next-20210304/nodev/block/009.out.bad 
Running block/009
0000000 0000 0000 0000 0000 0000 0000 0000 0000
*
0002000 aaaa aaaa aaaa aaaa aaaa aaaa aaaa aaaa
*
0040000 0000 0000 0000 0000 0000 0000 0000 0000
*
2000000
0000000 0000 0000 0000 0000 0000 0000 0000 0000
*
2000000
Test complete
mcgrof@bicho ~/devel/kdevops (git::master)$ cat workflows/blktests/results/5.12.0-rc1-next-20210304/nodev/block/009.full 
wrote 33554432/33554432 bytes at offset 0
32 MiB, 16 ops; 0.1188 sec (269.333 MiB/sec and 134.6665 ops/sec)
wrote 10485760/10485760 bytes at offset 2097152
10 MiB, 5 ops; 0.0091 sec (1.062 GiB/sec and 543.5964 ops/sec)
8192+0 records in
8192+0 records out
33554432 bytes (34 MB, 32 MiB) copied, 0.126594 s, 265 MB/s
8+0 records in
8+0 records out
33554432 bytes (34 MB, 32 MiB) copied, 0.121211 s, 277 MB/s

[0] https://github.com/mcgrof/kdevops
Comment 1 Luis Chamberlain 2021-03-16 17:04:01 UTC
(In reply to Luis Chamberlain from comment #0)
> But since we just want to busy loop test block/009:
> 
> ssh blktests-baseline

Sorry this should be:

ssh kdevops-blktests-block
Comment 2 Luis Chamberlain 2021-03-16 17:19:47 UTC
Hit a second failure at failure rate 1/614, that is, a failure after 614 tests. So failure rate average now 1/641
Comment 3 Jens Axboe 2021-03-16 17:21:21 UTC
Luis, can you just post this on linux-block? Nobody really looks here, it seems... I'd also make sure that error still persists in a current tree first, instead of one that's 2 weeks old.
Comment 4 Luis Chamberlain 2021-03-16 17:33:26 UTC
Hit a third failure now at 1/61, failure rate average bumps to: 1/448
Comment 5 Luis Chamberlain 2021-03-16 17:34:03 UTC
(In reply to Jens Axboe from comment #3)
> Luis, can you just post this on linux-block? Nobody really looks here, it
> seems... I'd also make sure that error still persists in a current tree
> first, instead of one that's 2 weeks old.

I was going to, but figured I'd first jot down as much as I could over the issue. Will do so now.
Comment 6 Luis Chamberlain 2021-03-16 17:39:49 UTC
(In reply to Luis Chamberlain from comment #0)
> While using kdevops [0] to test block layer with blktests to create a
> baseline I found that the test block/009 can fail on linux-next tag
> next-20210304 after running the test 669 times in a loop.
> 
> To reproduce you can get blktest set up with kdevops:
> 
> make menuconfig # configure and enable blktests, only enable to test block
> and select to test linux-next
> make bringup # bring up kvm guests to test
> make blktests # build and install blktests 

I forgot to provide instructions on how to get to linux-next on the guest once configured:

make linux
Comment 7 Luis Chamberlain 2021-03-16 18:46:44 UTC
Confirmed on linux-next as of today so tag next-20210316 as well at failure rate 1/1008:

root@kdevops-blktests-block /usr/local/blktests # uname -r
5.12.0-rc3-next-20210316
block/009 (check page-cache coherency after BLKDISCARD)      [failed]
    runtime  0.960s  ...  1.011s
    --- tests/block/009.out     2021-02-22 16:58:00.235209631 +0000
    +++ /usr/local/blktests/results/nodev/block/009.out.bad     2021-03-16 18:38:31.792430532 +0000
    @@ -1,6 +1,10 @@
     Running block/009
     0000000 0000 0000 0000 0000 0000 0000 0000 0000
     *
    +003e000 aaaa aaaa aaaa aaaa aaaa aaaa aaaa aaaa
    +*
    +0040000 0000 0000 0000 0000 0000 0000 0000 0000
    +*
    ...
    (Run 'diff -u tests/block/009.out /usr/local/blktests/results/nodev/block/009.out.bad' to see the entire diff)
FAIL at 1008
root@kdevops-blktests-block /usr/local/blktests # cat /usr/local/blktests/results/nodev/block/009.out.bad
Running block/009
0000000 0000 0000 0000 0000 0000 0000 0000 0000
*
003e000 aaaa aaaa aaaa aaaa aaaa aaaa aaaa aaaa
*
0040000 0000 0000 0000 0000 0000 0000 0000 0000
*
2000000
0000000 0000 0000 0000 0000 0000 0000 0000 0000
*
2000000
Test complete
Comment 8 Luis Chamberlain 2021-03-16 19:07:18 UTC
Once again hit a failure on linux-next 20210316 with failure rate of 1/862.
Comment 9 Luis Chamberlain 2021-03-16 19:33:05 UTC
3rd failure on linux-next 20210316 at failure rate 1/255
Comment 10 Luis Chamberlain 2021-03-16 20:18:56 UTC
Also fails even if CONFIG_SCSI_SCAN_ASYNC is disabled

root@kdevops-blktests-block /usr/local/blktests # cat /sys/module/scsi_mod/parameters/scan
sync

Failure rate 1/1185
Comment 11 Luis Chamberlain 2021-03-18 19:43:12 UTC
In case this is a scsi_debug issue, I tried the following:

diff --git a/common/scsi_debug b/common/scsi_debug
index b48cdc9..ecdbcc6 100644
--- a/common/scsi_debug
+++ b/common/scsi_debug
@@ -8,13 +8,42 @@ _have_scsi_debug() {
 	_have_modules scsi_debug
 }
 
+# As per korg#212337 [0] we must do more work in userspace to settle
+# scsi_debug devices a bit more carefully.
+
+# [0] https://bugzilla.kernel.org/show_bug.cgi?id=212337
+_settle_scsi_debug_device() {
+	SCSI_DEBUG_MAX_WAIT=10
+	SCSI_DEBUG_COUNT_WAIT_LOOP=0
+	while true ; do
+		if [[ -b $1 ]]; then
+			SCSI_DEBUG_LSOF_COUNT=$(lsof $1 | wc -l)
+			if [[ $SCSI_DEBUG_LSOF_COUNT -ne 0 ]]; then
+				sleep 1;
+			else
+				break
+			fi
+		else
+			# Let device come up
+			sleep 1
+
+			let SCSI_DEBUG_COUNT_WAIT_LOOP=$SCSI_DEBUG_COUNT_WAIT_LOOP+1
+			if [[ $SCSI_DEBUG_COUNT_WAIT_LOOP -ge $SCSI_DEBUG_MAX_WAIT ]]; then
+				break
+			fi
+		fi
+	done
+}
+
 _init_scsi_debug() {
 	if ! modprobe -r scsi_debug || ! modprobe scsi_debug "$@"; then
 		return 1
 	fi
-
 	udevadm settle
 
+	# Allow dependencies to load
+	sleep 1
+
 	local host_sysfs host target_sysfs target
 	SCSI_DEBUG_HOSTS=()
 	SCSI_DEBUG_TARGETS=()
@@ -43,6 +72,10 @@ _init_scsi_debug() {
 		return 1
 	fi
 
+	for i in $SCSI_DEBUG_DEVICES ; do
+		_settle_scsi_debug_device /dev/$i
+	done
+
 	return 0
 }
 


But I still managed to reproduce a failure, with a failure rate of 1/1705 on linux-next tag next-20210316.
Comment 12 Luis Chamberlain 2021-03-19 19:16:00 UTC
Given the predicament with scsi_debug leaves initialization in a questionable state still, I decided to try a bigger sledge hammer to try do disprove if this issue can be blamed on scsi_debug. The above patch for common/scsi_debug on blktests was modified where it says "Allow for dependencies to load" where it sleeps for just 1 second, I set a sleep for 5 seconds. I kept the other stuff, the new settle_scsi_debug_device()... This together should be *sufficient* IMHO to really try to settle the simple created scsi_debug device created by block/009.

And I still was able to reproduce a failure, this time at a failure rate of 1/5276:

block/009 (check page-cache coherency after BLKDISCARD)      [failed]
    runtime  6.060s  ...  7.471s
    --- tests/block/009.out     2021-02-22 16:58:00.235209631 +0000
    +++ /usr/local/blktests/results/nodev/block/009.out.bad     2021-03-19 04:56:01.123720333 +0000
    @@ -1,6 +1,10 @@
     Running block/009
     0000000 0000 0000 0000 0000 0000 0000 0000 0000
     *
    +002f000 aaaa aaaa aaaa aaaa aaaa aaaa aaaa aaaa
    +*
    +0040000 0000 0000 0000 0000 0000 0000 0000 0000
    +*
    ...
    (Run 'diff -u tests/block/009.out /usr/local/blktests/results/nodev/block/009.out.bad' to see the entire diff)


root@kdevops-blktests-block /usr/local/blktests # cat /usr/local/blktests/results/nodev/block/009.out.bad
Running block/009
0000000 0000 0000 0000 0000 0000 0000 0000 0000
*
002f000 aaaa aaaa aaaa aaaa aaaa aaaa aaaa aaaa
*
0040000 0000 0000 0000 0000 0000 0000 0000 0000
*
2000000
0000000 0000 0000 0000 0000 0000 0000 0000 0000
*
2000000
Test complete

Note You need to log in before you can comment on or make changes to this bug.