[PATCH v2] scsi_debug: randomize command duration option + %p

[PATCH v2] scsi_debug: randomize command duration option + %p

[Douglas Gilbert]

Add an option to use the given command delay (in nanoseconds)
as the upper limit for command durations. A pseudo random
number generator chooses each duration from the range:
      [0..delay_in_ns)

Main benefit: allows testing with out-of-order responses.

Change the only %p (print a kernel pointer) in the driver
to %pK as the former seems to have no usefulness in recent
kernels.

---

The new %p would be more useful if it didn't randomize NULL
pointers and gave an indicative output for ERR_PTR(-ENOENT)
type pointers. Hard to imagine how that will help the black
hats. Probably all printk()s in the SCSI subsystem should be
changed to %pK or some variant of that.

Signed-off-by: Douglas Gilbert <dgilbert@interlog.com>
---
 drivers/scsi/scsi_debug.c | 43 +++++++++++++++++++++++++++++++++++----
 1 file changed, 39 insertions(+), 4 deletions(-)

diff --git a/drivers/scsi/scsi_debug.c b/drivers/scsi/scsi_debug.c
index d323523f5f9d..92b982158ec3 100644
--- a/drivers/scsi/scsi_debug.c
+++ b/drivers/scsi/scsi_debug.c
@@ -38,6 +38,7 @@
 #include <linux/hrtimer.h>
 #include <linux/uuid.h>
 #include <linux/t10-pi.h>
+#include <linux/random.h>
 
 #include <net/checksum.h>
 
@@ -125,6 +126,7 @@ static const char *sdebug_version_date = "20190125";
 #define DEF_PHYSBLK_EXP 0
 #define DEF_OPT_XFERLEN_EXP 0
 #define DEF_PTYPE   TYPE_DISK
+#define DEF_RANDOM false
 #define DEF_REMOVABLE false
 #define DEF_SCSI_LEVEL   7    /* INQUIRY, byte2 [6->SPC-4; 7->SPC-5] */
 #define DEF_SECTOR_SIZE 512
@@ -655,6 +657,7 @@ static unsigned int sdebug_unmap_max_blocks = DEF_UNMAP_MAX_BLOCKS;
 static unsigned int sdebug_unmap_max_desc = DEF_UNMAP_MAX_DESC;
 static unsigned int sdebug_write_same_length = DEF_WRITESAME_LENGTH;
 static int sdebug_uuid_ctl = DEF_UUID_CTL;
+static bool sdebug_random = DEF_RANDOM;
 static bool sdebug_removable = DEF_REMOVABLE;
 static bool sdebug_clustering;
 static bool sdebug_host_lock = DEF_HOST_LOCK;
@@ -4354,9 +4357,21 @@ static int schedule_resp(struct scsi_cmnd *cmnd, struct sdebug_dev_info *devip,
 		ktime_t kt;
 
 		if (delta_jiff > 0) {
-			kt = ns_to_ktime((u64)delta_jiff * (NSEC_PER_SEC / HZ));
-		} else
-			kt = ndelay;
+			u64 ns = (u64)delta_jiff * (NSEC_PER_SEC / HZ);
+
+			if (sdebug_random && ns < U32_MAX) {
+				ns = prandom_u32_max((u32)ns);
+			} else if (sdebug_random) {
+				ns >>= 10;	/* divide by 1024 */
+				if (ns < U32_MAX)  /* an hour and a bit */
+					ns = prandom_u32_max((u32)ns);
+				ns <<= 10;
+			}
+			kt = ns_to_ktime(ns);
+		} else {
+			kt = sdebug_random ? prandom_u32_max((u32)ndelay) :
+					     (u32)ndelay;
+		}
 		if (!sd_dp->init_hrt) {
 			sd_dp->init_hrt = true;
 			sqcp->sd_dp = sd_dp;
@@ -4451,6 +4466,7 @@ module_param_named(opts, sdebug_opts, int, S_IRUGO | S_IWUSR);
 module_param_named(physblk_exp, sdebug_physblk_exp, int, S_IRUGO);
 module_param_named(opt_xferlen_exp, sdebug_opt_xferlen_exp, int, S_IRUGO);
 module_param_named(ptype, sdebug_ptype, int, S_IRUGO | S_IWUSR);
+module_param_named(random, sdebug_random, bool, S_IRUGO | S_IWUSR);
 module_param_named(removable, sdebug_removable, bool, S_IRUGO | S_IWUSR);
 module_param_named(scsi_level, sdebug_scsi_level, int, S_IRUGO);
 module_param_named(sector_size, sdebug_sector_size, int, S_IRUGO);
@@ -4511,6 +4527,7 @@ MODULE_PARM_DESC(opts, "1->noise, 2->medium_err, 4->timeout, 8->recovered_err...
 MODULE_PARM_DESC(physblk_exp, "physical block exponent (def=0)");
 MODULE_PARM_DESC(opt_xferlen_exp, "optimal transfer length granularity exponent (def=physblk_exp)");
 MODULE_PARM_DESC(ptype, "SCSI peripheral type(def=0[disk])");
+MODULE_PARM_DESC(random, "1-> command duration chosen from [0..delay_in_ns) (def=0)");
 MODULE_PARM_DESC(removable, "claim to have removable media (def=0)");
 MODULE_PARM_DESC(scsi_level, "SCSI level to simulate(def=7[SPC-5])");
 MODULE_PARM_DESC(sector_size, "logical block size in bytes (def=512)");
@@ -5101,6 +5118,23 @@ static ssize_t map_show(struct device_driver *ddp, char *buf)
 }
 static DRIVER_ATTR_RO(map);
 
+static ssize_t random_show(struct device_driver *ddp, char *buf)
+{
+	return scnprintf(buf, PAGE_SIZE, "%d\n", sdebug_random ? 1 : 0);
+}
+static ssize_t random_store(struct device_driver *ddp, const char *buf,
+			    size_t count)
+{
+	int n;
+
+	if (count > 0 && 1 == sscanf(buf, "%d", &n) && n >= 0) {
+		sdebug_random = (n > 0);
+		return count;
+	}
+	return -EINVAL;
+}
+static DRIVER_ATTR_RW(random);
+
 static ssize_t removable_show(struct device_driver *ddp, char *buf)
 {
 	return scnprintf(buf, PAGE_SIZE, "%d\n", sdebug_removable ? 1 : 0);
@@ -5211,6 +5245,7 @@ static struct attribute *sdebug_drv_attrs[] = {
 	&driver_attr_guard.attr,
 	&driver_attr_ato.attr,
 	&driver_attr_map.attr,
+	&driver_attr_random.attr,
 	&driver_attr_removable.attr,
 	&driver_attr_host_lock.attr,
 	&driver_attr_ndelay.attr,
@@ -5338,7 +5373,7 @@ static int __init scsi_debug_init(void)
 		dif_size = sdebug_store_sectors * sizeof(struct t10_pi_tuple);
 		dif_storep = vmalloc(dif_size);
 
-		pr_err("dif_storep %u bytes @ %p\n", dif_size, dif_storep);
+		pr_err("dif_storep %u bytes @ %pK\n", dif_size, dif_storep);
 
 		if (dif_storep == NULL) {
 			pr_err("out of mem. (DIX)\n");
-- 
2.23.0

Re: [PATCH v2] scsi_debug: randomize command duration option + %p

[Bart Van Assche]

On 9/27/19 7:04 AM, Douglas Gilbert wrote:
> Add an option to use the given command delay (in nanoseconds)
> as the upper limit for command durations. A pseudo random
> number generator chooses each duration from the range:
>        [0..delay_in_ns)
> 
> Main benefit: allows testing with out-of-order responses.

Please clarify which code you want to test. I think out-of-order 
response handling in the SCSI core and block layer core is already being 
triggered by many storage workloads.

> @@ -4354,9 +4357,21 @@ static int schedule_resp(struct scsi_cmnd *cmnd, struct sdebug_dev_info *devip,
>   		ktime_t kt;
>   
>   		if (delta_jiff > 0) {
> -			kt = ns_to_ktime((u64)delta_jiff * (NSEC_PER_SEC / HZ));
> -		} else
> -			kt = ndelay;
> +			u64 ns = (u64)delta_jiff * (NSEC_PER_SEC / HZ);

Has it been considered to use jiffies_to_nsecs() instead of open-coding 
that function?

> +			if (sdebug_random && ns < U32_MAX) {
> +				ns = prandom_u32_max((u32)ns);
> +			} else if (sdebug_random) {
> +				ns >>= 10;	/* divide by 1024 */
> +				if (ns < U32_MAX)  /* an hour and a bit */
> +					ns = prandom_u32_max((u32)ns);
> +				ns <<= 10;
> +			}
> +			kt = ns_to_ktime(ns);

Is it really necessary to use nanosecond resolution? Can the above code 
be simplified by using microseconds as time unit instead of nanoseconds?

> +MODULE_PARM_DESC(random, "1-> command duration chosen from [0..delay_in_ns) (def=0)");

Would this description become more clear if it would be changed into 
something like the following: "If set, uniformly randomize command 
duration between 0 and delay_in_ns" ?

> +static ssize_t random_show(struct device_driver *ddp, char *buf)
> +{
> +	return scnprintf(buf, PAGE_SIZE, "%d\n", sdebug_random ? 1 : 0);
> +}

Since sdebug_random is either 0 or 1, is the "? 1 : 0" part necessary?

> +static ssize_t random_store(struct device_driver *ddp, const char *buf,
> +			    size_t count)
> +{
> +	int n;
> +
> +	if (count > 0 && 1 == sscanf(buf, "%d", &n) && n >= 0) {
> +		sdebug_random = (n > 0);
> +		return count;
> +	}
> +	return -EINVAL;
> +}

Has this patch been verified with checkpatch? I'm asking since 
checkpatch should complain about "1 == sscanf(...)". See also commit 
c5595fa2f1ce ("checkpatch: add constant comparison on left side test").

> @@ -5338,7 +5373,7 @@ static int __init scsi_debug_init(void)
>   		dif_size = sdebug_store_sectors * sizeof(struct t10_pi_tuple);
>   		dif_storep = vmalloc(dif_size);
>   
> -		pr_err("dif_storep %u bytes @ %p\n", dif_size, dif_storep);
> +		pr_err("dif_storep %u bytes @ %pK\n", dif_size, dif_storep);
>   
>   		if (dif_storep == NULL) {
>   			pr_err("out of mem. (DIX)\n");

Is it useful to print the kernel pointer 'dif_storep'?

Thanks,

Bart.

Re: [PATCH v2] scsi_debug: randomize command duration option + %p

[Douglas Gilbert]

On 2019-09-30 11:46 a.m., Bart Van Assche wrote:
> On 9/27/19 7:04 AM, Douglas Gilbert wrote:
>> Add an option to use the given command delay (in nanoseconds)
>> as the upper limit for command durations. A pseudo random
>> number generator chooses each duration from the range:
>>        [0..delay_in_ns)
>>
>> Main benefit: allows testing with out-of-order responses.
> 
> Please clarify which code you want to test. I think out-of-order response 
> handling in the SCSI core and block layer core is already being triggered by 
> many storage workloads.

Short answer: in the current scsi_debug driver all responses arrive in
submission order. So there is a large class of errors that it won't find.


Longer answer:
Core dumps and log messages often occur well after the misstep in the code
that caused them.

In my case, I was looking for a bug in the sg driver associated with
request sharing for a disk to disk copy (reference:
http://sg.danny.cz/sg/sg_v40.html Figure 6). I ran the sg app (sgh_dd)
for several weeks tweaking this and that without any sign of failure.
However if I ran it using real SSDs then the error would occur but at
such a low frequency (say once per day) it was difficult to isolate.
I suspected the error occurred when at least one response arrived out
of submission order. Hence the patch presented here. In a relatively
short period of time (say between several seconds and several minutes)
the error occurred with 'ndelay=20000 random=1". This allowed me to
work back and find the faulty state transition.

So I assumed this technique might be more generally useful for those who
test with scsi_debug.

> 
>> @@ -4354,9 +4357,21 @@ static int schedule_resp(struct scsi_cmnd *cmnd, struct 
>> sdebug_dev_info *devip,
>>           ktime_t kt;
>>           if (delta_jiff > 0) {
>> -            kt = ns_to_ktime((u64)delta_jiff * (NSEC_PER_SEC / HZ));
>> -        } else
>> -            kt = ndelay;
>> +            u64 ns = (u64)delta_jiff * (NSEC_PER_SEC / HZ);
> 
> Has it been considered to use jiffies_to_nsecs() instead of open-coding that 
> function?

I'll look into it.

>> +            if (sdebug_random && ns < U32_MAX) {
>> +                ns = prandom_u32_max((u32)ns);
>> +            } else if (sdebug_random) {
>> +                ns >>= 10;    /* divide by 1024 */
>> +                if (ns < U32_MAX)  /* an hour and a bit */
>> +                    ns = prandom_u32_max((u32)ns);
>> +                ns <<= 10;
>> +            }
>> +            kt = ns_to_ktime(ns);
> 
> Is it really necessary to use nanosecond resolution? Can the above code be 
> simplified by using microseconds as time unit instead of nanoseconds?

The driver follows kernel conventions and does time keeping in either
milliseconds or nanoseconds. A minor disadvantage of nanosecond timekeeping
and 32 bit integers (e.g. as used by the sg driver for duration) is that
the largest duration it can represent is around 4.2 seconds. If one is
simulating READs and WRITEs on a SSD then 4 seconds is more than enough
but not for FORMAT UNIT. Hence the code above. This problem doesn't
completely disappear with microsecond resolution as its 32 bit maximum
(~ 4200 seconds) may still be too low for simulating FORMAT UNIT.

While I agree that microsecond precision is sufficient for logs ***
I find it useful to look at nanosecond precision when debugging the sg
and scsi_debug drivers. Arnd Bergmann warned me that there is a (slight)
time penalty when reading the high precision counters on some
architectures. That is why there are "_coarse_" variants in some of
the timekeeping headers.

>> +MODULE_PARM_DESC(random, "1-> command duration chosen from [0..delay_in_ns) 
>> (def=0)");
> 
> Would this description become more clear if it would be changed into something 
> like the following: "If set, uniformly randomize command duration between 0 and 
> delay_in_ns" ?

checkpatch.pl seems inconsistent when strings violate the Fortran punch card
line length limit. Sometimes checkpatch complains and sometimes it follows
the kernel coding standards and doesn't complain. It complained about my
original effort, so I abridged it.
Yes, your suggestion is clearer (and longer).

>> +static ssize_t random_show(struct device_driver *ddp, char *buf)
>> +{
>> +    return scnprintf(buf, PAGE_SIZE, "%d\n", sdebug_random ? 1 : 0);
>> +}
> 
> Since sdebug_random is either 0 or 1, is the "? 1 : 0" part necessary?

No.
Why didn't you complain when MKP wrote that? That is where I cut and
pasted that code from (sdebug_removable).

>> +static ssize_t random_store(struct device_driver *ddp, const char *buf,
>> +                size_t count)
>> +{
>> +    int n;
>> +
>> +    if (count > 0 && 1 == sscanf(buf, "%d", &n) && n >= 0) {
>> +        sdebug_random = (n > 0);
>> +        return count;
>> +    }
>> +    return -EINVAL;
>> +}
> 
> Has this patch been verified with checkpatch? I'm asking since checkpatch should 
> complain about "1 == sscanf(...)". See also commit c5595fa2f1ce ("checkpatch: 
> add constant comparison on left side test").

Yes. And it complained, but not about that :-)
Again, copy and paste from MKP's code (which no doubt was a copy + paste from
my earlier code).

>> @@ -5338,7 +5373,7 @@ static int __init scsi_debug_init(void)
>>           dif_size = sdebug_store_sectors * sizeof(struct t10_pi_tuple);
>>           dif_storep = vmalloc(dif_size);
>> -        pr_err("dif_storep %u bytes @ %p\n", dif_size, dif_storep);
>> +        pr_err("dif_storep %u bytes @ %pK\n", dif_size, dif_storep);
>>           if (dif_storep == NULL) {
>>               pr_err("out of mem. (DIX)\n");
> 
> Is it useful to print the kernel pointer 'dif_storep'?

Ask MKP, it's his code. All I do know is that doing a printk("%p" ...) is
useless in lk 5.3 (and probably lk 5.2). Taking the above snippet, if
vmalloc() returned NULL then the existing pr_err() would print out
a random number rather than <null>. Sick ...

Thanks
Doug Gilbert


*** If anyone wants microsecond in syslog and friends, comment out this line:

	$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

     in /etc/sysctl.conf . Obvious, isn't it ....

Re: [PATCH v2] scsi_debug: randomize command duration option + %p

[Martin K. Petersen]

Doug,

>> Since sdebug_random is either 0 or 1, is the "? 1 : 0" part necessary?
>
> No.
> Why didn't you complain when MKP wrote that? That is where I cut and
> pasted that code from (sdebug_removable).

[...]

> Again, copy and paste from MKP's code (which no doubt was a copy +
> paste from my earlier code).

I'll be the first to admit that I make mistakes and almost always
blindly copy surrounding plumbing when I hack on scsi_debug. However, I
am not responsible for the commit that introduced any of this code.

Also, in defense of the original author, our coding practices were
obviously different when this was written many years ago.

>>> @@ -5338,7 +5373,7 @@ static int __init scsi_debug_init(void)
>>>           dif_size = sdebug_store_sectors * sizeof(struct t10_pi_tuple);
>>>           dif_storep = vmalloc(dif_size);
>>> -        pr_err("dif_storep %u bytes @ %p\n", dif_size, dif_storep);
>>> +        pr_err("dif_storep %u bytes @ %pK\n", dif_size, dif_storep);
>>>           if (dif_storep == NULL) {
>>>               pr_err("out of mem. (DIX)\n");
>>
>> Is it useful to print the kernel pointer 'dif_storep'?
>
> Ask MKP, it's his code. All I do know is that doing a printk("%p" ...)
> is useless in lk 5.3 (and probably lk 5.2). Taking the above snippet,
> if vmalloc() returned NULL then the existing pr_err() would print out
> a random number rather than <null>. Sick ...

This used to be somewhat useful for debugging purposes in combination
with the ability to dump the buffer to inspect the PI. In this day and
age with obfuscated kernel pointers, not so much. I suggest just
removing the line. Or--if people feel the size is valuable
information--just zap the pointer. Also, since this is unrelated to the
duration randomization it should be a separate patch.

Thanks!

-- 
Martin K. Petersen	Oracle Linux Engineering