212337 – scsi_debug: race at module load and module unload

Bug 212337 - scsi_debug: race at module load and module unload

Summary: scsi_debug: race at module load and module unload

Status:	REOPENED

Alias:	None

Product:	SCSI Drivers
Classification:	Unclassified
Component:	Other (show other bugs)
Hardware:	All Linux

Importance:	P1 normal
Assignee:	scsi_drivers-other

URL:
Keywords:

Depends on:
Blocks:

Reported:	2021-03-18 17:09 UTC by Luis Chamberlain
Modified:	2021-08-10 05:19 UTC (History)
CC List:	0 users

See Also:
Kernel Version:	5.12.0 linux-next 20210304
Subsystem:
Regression:	No
Bisected commit-id:

Attachments
Dealing with scsi_debug module removal / load races (1021 bytes, application/x-shellscript) 2021-03-18 17:43 UTC, Luis Chamberlain	Details
Add an attachment (proposed patch, testcase, etc.)

Description Luis Chamberlain 2021-03-18 17:09:50 UTC

Removing the scsi_module can *very often* fail:

modprobe scsi_debug; rmmod scsi_debug
rmmod: ERROR: Module scsi_debug is in use

The removal will fail complaining that the scsi_debug module is still in use. Both fstests and blktests rely on scsi_debug for many tests, and so likely some false positives failures from those tests may be coming up. I've looked into this issue and am going to use this bug report to track the observations, and possible solutions.

Comment 1 Luis Chamberlain 2021-03-18 17:38:16 UTC

At first glance this might seem like a problem with scsi's async probe, and so one might believe disabling CONFIG_SCSI_SCAN_ASYNC could help, however it does not. Linux scsi doesn't have semantics to allow only one driver to prefer to probe asynchronously, but we can shoe-horn this in as follows:

diff --git a/drivers/scsi/scsi_debug.c b/drivers/scsi/scsi_debug.c
index 3cdeaeb92933..d970050ae866 100644
--- a/drivers/scsi/scsi_debug.c
+++ b/drivers/scsi/scsi_debug.c
@@ -857,6 +857,8 @@ static const int device_qfull_result =
 
 static const int condition_met_result = SAM_STAT_CONDITION_MET;
 
+MODULE_IMPORT_NS(SCSI_PRIVATE);
+int scsi_complete_async_scans(void);
 
 /* Only do the extra work involved in logical block provisioning if one or
  * more of the lbpu, lbpws or lbpws10 parameters are given and we are doing
@@ -6851,6 +6853,7 @@ static int __init scsi_debug_init(void)
 			}
 		}
 	}
+	scsi_complete_async_scans();
 	if (sdebug_verbose)
 		pr_info("built %d host(s)\n", sdebug_num_hosts);
 
Even with this present though we still have he refcnt issue. A better way to see what is going on is to trace the kernel module calls after boot and see why perhaps certain refcounts for the module are high at times and why they are not in most other cases.

Enable module tracing

# for i in $(sudo find /sys/kernel/debug/tracing/events/module/ -name "enable"); do echo 1 > $i; done

Run a loop to test modprobe / rmmod, and fail if either fails. In this case let's assume a success of rmmod once and then a failure on the second removal. We get the following ftrace, I'll provide some comments in areas where this may be useful

# cat trace /sys/kernel/tracing
# tracer: nop
#
# entries-in-buffer/entries-written: 355/355   #P:8
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
        modprobe-902     [005] ....    45.731217: module_get: scsi_mod call_site=resolve_symbol refcnt=6
        modprobe-902     [005] ....    45.732844: module_load: scsi_debug E
        modprobe-902     [005] ....    45.732850: module_get: scsi_debug call_site=sdebug_add_store [scsi_debug] refcnt=3
        modprobe-902     [005] ....    45.733589: module_put: scsi_debug call_site=sdebug_add_store [scsi_debug] refcnt=2
        modprobe-902     [005] ....    45.733963: module_get: scsi_debug call_site=sdebug_driver_probe [scsi_debug] refcnt=3
        modprobe-902     [001] ....    45.738246: module_put: scsi_debug call_site=sdebug_driver_probe [scsi_debug] refcnt=2
   kworker/u16:3-173     [002] ....    45.738790: module_get: scsi_debug call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=3
   kworker/u16:3-173     [002] ....    45.739943: module_put: scsi_debug call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=2
   kworker/u16:3-173     [007] ....    45.748555: module_get: scsi_debug call_site=scsi_debug_slave_configure [scsi_debug] refcnt=3
   kworker/u16:3-173     [007] .N..    45.749962: module_put: scsi_debug call_site=scsi_debug_slave_configure [scsi_debug] refcnt=2
   kworker/u16:3-173     [000] d...    45.766235: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=3
   kworker/u16:3-173     [000] d...    45.769197: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=4
   kworker/u16:3-173     [000] ....    45.769197: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=3
   kworker/u16:3-173     [000] ....    45.769198: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=2
   kworker/u16:3-173     [000] d...    45.769199: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=3
   kworker/u16:3-173     [000] ....    45.769785: module_put: scsi_debug call_site=__scsi_iterate_devices [scsi_mod] refcnt=2
        modprobe-902     [001] ....    45.773492: module_put: scsi_debug call_site=do_init_module refcnt=1

So we can escape initialization early in one case as sg module is not yet available.

   systemd-udevd-907     [001] ....    45.773818: module_get: scsi_mod call_site=resolve_symbol refcnt=7
   systemd-udevd-907     [001] ....    45.774708: module_load: sg E
   systemd-udevd-907     [001] ....    45.776173: module_put: sg call_site=do_init_module refcnt=1
   systemd-udevd-907     [001] ....    45.778501: module_get: scsi_mod call_site=resolve_symbol refcnt=8
   systemd-udevd-907     [001] ....    45.778569: module_get: t10_pi call_site=resolve_symbol refcnt=3
   systemd-udevd-907     [001] ....    45.779733: module_load: sd_mod E
   systemd-udevd-907     [001] ....    45.828660: module_put: sd_mod call_site=do_init_module refcnt=1
           rmmod-908     [003] ....    45.921238: module_free: scsi_debug

We remove the scsi_debug module here fine before systemd-udevd has opened the device.

           rmmod-908     [003] ....    45.921442: module_put: scsi_mod call_site=module_unload_free refcnt=7
        modprobe-914     [006] ....    45.944276: module_get: scsi_mod call_site=resolve_symbol refcnt=8

        modprobe-914     [006] ....    45.945820: module_load: scsi_debug E
        modprobe-914     [006] ....    45.945825: module_get: scsi_debug call_site=sdebug_add_store [scsi_debug] refcnt=3
        modprobe-914     [006] ....    45.946553: module_put: scsi_debug call_site=sdebug_add_store [scsi_debug] refcnt=2
        modprobe-914     [006] ....    45.947044: module_get: scsi_debug call_site=sdebug_driver_probe [scsi_debug] refcnt=3
        modprobe-914     [006] ....    45.952509: module_put: scsi_debug call_site=sdebug_driver_probe [scsi_debug] refcnt=2
   kworker/u16:3-173     [006] ....    45.953257: module_get: scsi_debug call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=3
   kworker/u16:3-173     [006] .N..    45.954616: module_put: scsi_debug call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=2
   kworker/u16:3-173     [006] ....    45.964402: module_get: scsi_debug call_site=scsi_debug_slave_configure [scsi_debug] refcnt=3
   kworker/u16:3-173     [006] .N..    45.965695: module_put: scsi_debug call_site=scsi_debug_slave_configure [scsi_debug] refcnt=2
   kworker/u16:3-173     [005] d...    46.213491: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=3
   kworker/u16:3-173     [005] d...    46.215346: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=4
   kworker/u16:3-173     [005] ....    46.215347: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=3
   kworker/u16:3-173     [005] ....    46.215348: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=2
   kworker/u16:3-173     [005] d...    46.215350: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=3
   kworker/u16:3-173     [005] ....    46.220794: module_put: scsi_debug call_site=__scsi_iterate_devices [scsi_mod] refcnt=2
   kworker/u16:4-174     [004] ....    46.224892: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] ....    46.224893: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] ....    46.224894: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.228906: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.228907: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.228907: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] ....    46.230926: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] ....    46.230926: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] ....    46.230927: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.234937: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.234938: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.234938: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] .N..    46.246062: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] .N..    46.246064: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] .N..    46.246065: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.250071: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.250072: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.250072: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] ....    46.252943: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] ....    46.252943: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] ....    46.252944: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.256956: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.256957: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.256957: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] ....    46.258547: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] ....    46.258547: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] ....    46.258548: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.262558: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.262558: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.262559: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] .N..    46.266484: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] .N..    46.266484: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] .N..    46.266485: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.270492: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.270492: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.270493: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] ....    46.272381: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] ....    46.272382: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] ....    46.272382: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.276393: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.276393: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.276394: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] ....    46.278258: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
   kworker/u16:4-174     [004] ....    46.278259: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [004] ....    46.278259: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.282269: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
          <idle>-0       [004] d.h.    46.282270: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
          <idle>-0       [004] d.h.    46.282270: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
   kworker/u16:4-174     [004] ....    46.374616: module_get: sd_mod call_site=blkdev_get_no_open refcnt=2
   kworker/u16:4-174     [004] ....    46.374617: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=3
    kworker/4:1H-189     [004] ....    46.376457: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
    kworker/4:1H-189     [004] ....    46.376457: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
    kworker/4:1H-189     [004] ....    46.376458: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
     kworker/4:1-62      [004] d.h.    46.380469: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
     kworker/4:1-62      [004] d.h.    46.380470: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
     kworker/4:1-62      [004] d.h.    46.380470: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
    kworker/0:1H-89      [000] ....    46.383278: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
    kworker/0:1H-89      [000] ....    46.383279: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
    kworker/0:1H-89      [000] ....    46.383280: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.387291: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [000] d.h.    46.387292: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.387292: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
    kworker/0:1H-89      [000] ....    46.389080: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
    kworker/0:1H-89      [000] ....    46.389081: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
    kworker/0:1H-89      [000] ....    46.389081: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.393090: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [000] d.h.    46.393091: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.393091: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   kworker/u16:4-174     [000] ....    46.393170: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=2
   kworker/u16:4-174     [000] ....    46.393171: module_put: sd_mod call_site=blkdev_put refcnt=1
   systemd-udevd-907     [003] ....    46.393476: module_get: sd_mod call_site=blkdev_get_no_open refcnt=2
   systemd-udevd-907     [003] ....    46.393477: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=3
   kworker/u16:4-174     [000] ....    46.395771: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.395772: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.395773: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.399789: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [000] d.h.    46.399790: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.399790: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   kworker/u16:4-174     [000] ....    46.402067: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.402068: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.402069: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.406078: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [000] d.h.    46.406079: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [000] d.h.    46.406079: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
       multipath-926     [005] ....    46.409545: module_get: sd_mod call_site=blkdev_get_no_open refcnt=3
       multipath-926     [005] ....    46.409547: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=4
       multipath-926     [005] ....    46.409649: module_get: dm_mod call_site=misc_open refcnt=2
       multipath-926     [005] ....    46.409773: module_put: dm_mod call_site=__fput refcnt=1
       multipath-926     [005] ....    46.410096: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=3
       multipath-926     [005] ....    46.410097: module_put: sd_mod call_site=blkdev_put refcnt=2
   systemd-udevd-907     [003] ....    46.410279: module_get: sd_mod call_site=blkdev_get_no_open refcnt=3
   systemd-udevd-907     [003] ....    46.410280: module_get: scsi_debug call_site=scsi_device_get [scsi_mod] refcnt=4
   systemd-udevd-907     [003] ....    46.413760: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.413760: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.413760: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.417764: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
          <idle>-0       [003] d.h.    46.417764: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.417764: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.438981: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.438981: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   kworker/u16:4-174     [000] ....    46.438982: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.439875: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.439875: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=7
   systemd-udevd-907     [003] ....    46.439876: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.442992: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
          <idle>-0       [000] d.h.    46.442993: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.442994: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.443880: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
          <idle>-0       [003] d.h.    46.443880: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.443880: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.444546: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.444547: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   kworker/u16:4-174     [000] ....    46.444548: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.445450: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.445450: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=7
   systemd-udevd-907     [003] ....    46.445450: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.448558: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
          <idle>-0       [000] d.h.    46.448559: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.448559: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.449452: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
          <idle>-0       [003] d.h.    46.449453: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.449453: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.450135: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.450136: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   kworker/u16:4-174     [000] ....    46.450136: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.451003: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.451003: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=7
   systemd-udevd-907     [003] ....    46.451004: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.454147: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
          <idle>-0       [000] d.h.    46.454148: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.454148: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.455008: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
          <idle>-0       [003] d.h.    46.455008: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.455008: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.455910: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.455910: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   kworker/u16:4-174     [000] ....    46.455911: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.456804: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.456805: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=7
   systemd-udevd-907     [003] ....    46.456805: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.459920: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
          <idle>-0       [000] d.h.    46.459921: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.459921: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.460808: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
          <idle>-0       [003] d.h.    46.460809: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.460809: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.461664: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.461664: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   kworker/u16:4-174     [000] ....    46.461665: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.462544: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.462545: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=7
   systemd-udevd-907     [003] ....    46.462545: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.465674: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
          <idle>-0       [000] d.h.    46.465675: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.465675: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.466547: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
          <idle>-0       [003] d.h.    46.466548: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.466548: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
   kworker/u16:4-174     [000] ....    46.467413: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   kworker/u16:4-174     [000] ....    46.467413: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   kworker/u16:4-174     [000] ....    46.467414: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.468319: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.468319: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=7
   systemd-udevd-907     [003] ....    46.468319: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.471425: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
          <idle>-0       [000] d.h.    46.471426: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
          <idle>-0       [000] d.h.    46.471426: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.472322: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
          <idle>-0       [003] d.h.    46.472323: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.472323: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.473538: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.473538: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=6
   systemd-udevd-907     [003] ....    46.473538: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
        modprobe-914     [006] ....    46.474870: module_put: scsi_debug call_site=do_init_module refcnt=4

          <idle>-0       [003] d.h.    46.477540: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.477541: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.477541: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.478789: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.478789: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.478790: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.482795: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.482796: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.482796: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.483713: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.483713: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.483714: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.487723: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.487723: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.487724: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.488736: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.488737: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.488737: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.492740: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.492741: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.492741: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.493621: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.493621: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.493621: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.497627: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.497628: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.497628: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.498631: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.498632: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.498632: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.502634: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.502635: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.502635: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.503506: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.503507: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.503507: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.507513: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.507513: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.507514: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.508540: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.508540: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.508541: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.512543: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.512543: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.512543: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.513421: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.513421: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.513421: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.517425: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.517425: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.517425: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.518504: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.518505: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.518505: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.522509: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.522509: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.522509: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.523418: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.523418: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.523418: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.527420: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.527420: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.527420: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.528436: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.528437: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.528437: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.532440: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.532441: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.532441: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.533324: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.533324: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.533324: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.537329: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.537330: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.537330: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.538373: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.538374: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.538374: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.542376: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.542377: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.542377: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.543259: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.543260: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.543260: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.547268: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.547269: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.547269: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.548246: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.548246: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.548247: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.552251: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.552251: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.552251: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.553258: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.553258: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.553258: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.557264: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.557264: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.557264: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.558294: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.558295: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.558295: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.562299: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.562300: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.562300: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.563242: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.563242: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.563242: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.567248: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.567248: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.567249: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.568196: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.568196: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.568197: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.572204: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.572205: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.572205: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.573125: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.573125: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.573126: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.577132: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.577133: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.577133: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.578070: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.578071: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.578071: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.582079: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.582080: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.582080: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.583013: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
   systemd-udevd-907     [003] ....    46.583013: module_get: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=5
   systemd-udevd-907     [003] ....    46.583014: module_put: scsi_debug call_site=schedule_resp [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.587025: module_get: scsi_debug call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
          <idle>-0       [003] d.h.    46.587026: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
          <idle>-0       [003] d.h.    46.587026: module_put: scsi_debug call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
   systemd-udevd-907     [003] ....    46.587080: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=2
   systemd-udevd-907     [003] ....    46.587081: module_put: sd_mod call_site=blkdev_put refcnt=2
   systemd-udevd-907     [003] ....    46.588154: module_put: scsi_debug call_site=scsi_device_put [scsi_mod] refcnt=1
   systemd-udevd-907     [003] ....    46.588155: module_put: sd_mod call_site=blkdev_put refcnt=1

One might be at first motivated to implment sledge hammers as follows:

static void sdebug_wait_empty_num_in_q(void)
{
	struct sdebug_host_info *sdbg_host;
	struct Scsi_Host *shost;
	struct scsi_device *sdev;
	struct sdebug_dev_info *devip;
	int count, max_wait = 5, k;
	bool busy;

	while (true) {
		busy = false;
		spin_lock(&sdebug_host_list_lock);
		list_for_each_entry(sdbg_host, &sdebug_host_list, host_list) {
			shost = sdbg_host->shost;
			shost_for_each_device(sdev, shost) {
				devip = (struct sdebug_dev_info *)sdev->hostdata;
				if (atomic_read(&devip->num_in_q) != 0)
					busy = true;
				k = find_first_bit(devip->uas_bm, SDEBUG_NUM_UAS);
				if (k != SDEBUG_NUM_UAS)
					busy = true;
			}
		}
		spin_unlock(&sdebug_host_list_lock);
		if (!busy || count >= max_wait) {
			break;
		}
		ssleep(1);
		count++;
	}
}

/* Waits for all pending commands to complete. */
static void wait_all_queued(void)
{
	int j, k;
	struct sdebug_queue *sqp;
	bool busy;

	while (true) {
		busy = false;
		for (j = 0, sqp = sdebug_q_arr; j < submit_queues; ++j, ++sqp) {
			k = find_first_bit(sqp->in_use_bm, sdebug_max_queue);
			if (k != sdebug_max_queue)
				busy = true;
		}
		if (!busy)
			break;
		ssleep(1);
	}
}

static void sync_qc_helper(struct sdebug_defer *sd_dp,
			   enum sdeb_defer_type defer_t)
{
	if (!sd_dp)
		return;
	if (defer_t == SDEB_DEFER_HRT) {
		hrtimer_forward_now(&sd_dp->hrt, 2 * hrtimer_get_remaining(&sd_dp->hrt));
	} else if (defer_t == SDEB_DEFER_WQ) {
		flush_work(&sd_dp->ew.work);
	}
}

static void scsi_debug_sync_queued_cmnd(void)
{
	unsigned long iflags;
	int j, k, qmax, r_qmax;
	enum sdeb_defer_type l_defer_t;
	struct sdebug_queue *sqp;
	struct sdebug_queued_cmd *sqcp;
	struct sdebug_defer *sd_dp;

	for (j = 0, sqp = sdebug_q_arr; j < submit_queues; ++j, ++sqp) {
		spin_lock_irqsave(&sqp->qc_lock, iflags);
		qmax = sdebug_max_queue;
		r_qmax = atomic_read(&retired_max_queue);
		if (r_qmax > qmax)
			qmax = r_qmax;
		for (k = 0; k < qmax; ++k) {
			if (test_bit(k, sqp->in_use_bm)) {
				sqcp = &sqp->qc_arr[k];
				sd_dp = sqcp->sd_dp;
				if (sd_dp)
					l_defer_t = sd_dp->defer_t;
				else
					l_defer_t = SDEB_DEFER_NONE;
				spin_unlock_irqrestore(&sqp->qc_lock, iflags);
				sync_qc_helper(sd_dp, l_defer_t);
				spin_lock_irqsave(&sqp->qc_lock, iflags);
			}
		}
		spin_unlock_irqrestore(&sqp->qc_lock, iflags);
	}
}

static void wait_for_ready(void)
{
	struct scsi_sense_hdr sense_hdr;
	struct sdebug_host_info *sdbg_host;
	struct Scsi_Host *shost;
	struct scsi_device *sdev;
	int ret;
	bool all_ready;

	spin_lock(&sdebug_host_list_lock);
	while (true) {
		all_ready = true;
		list_for_each_entry(sdbg_host, &sdebug_host_list, host_list) {
			shost = sdbg_host->shost;
			shost_for_each_device(sdev, shost) {
				ret = scsi_internal_device_block_nowait(sdev);
				if (ret)
					all_ready = false;
	 			ret = scsi_internal_device_unblock_nowait(sdev, SDEV_RUNNING);
				if (ret)
					all_ready = false;
				ret = scsi_test_unit_ready(sdev, 5 * HZ, 100, &sense_hdr);
				if (ret != 0)
					all_ready = false;
			}
		}
		if (all_ready)
			break;
		ssleep(1);
	}
	spin_unlock(&sdebug_host_list_lock);
}

And use these on scsi_debug_init() but that does not suffice, and the reason is that userspace can open the scsi devices after initialization, namely in this case we see evidence of userspace processes such as systemd-udevd and multipath which will try to open the device.

There are a few solutions possible, using sync, or sg_sync is not one of them as we have to ensure we have no userspace application accessing the devices still.

You can use lsof for this purpose. Below is an example script which can be used.

#!/bin/bash

LOOP=1

while true; do
	modprobe scsi_debug
	if [[ $? -ne 0 ]]; then
		echo "scsi_debug modprobe failed at count $LOOP"
		exit 1
	fi
	while true; do
		# Let other modules which scsi_debug depends on like sg
		# and t10_pi load first to ensure any commands sent to
		# the device are sent.
		sleep 1

		# Now wait until userspace such as systemd-udevd and multipath
		# are done inspecting the newly exposed devices.
		COUNT=$(lsof /dev/sda | wc -l)
		if [[ $COUNT -ne 0 ]]; then
			echo "Sleeping ..."
			sleep 1;
		fi
		break
	done
	# Now you are safe to use scsi_debug exposed devices.

	# You are also free to remove it.
	rmmod scsi_debug
	if [[ $? -ne 0 ]]; then
		echo "scsi_debug rmmod failed at count $LOOP"
		exit 1
	else
		echo "Loop $LOOP: OK!"
	fi
	let LOOP=$LOOP+1
done


Marking this bug as resolved and won't fix as this should hopefully suffice to document why we can't wait on scsi_debug_init() to fix this issue, and it must be addressed in userspace.

Comment 2 Luis Chamberlain 2021-03-18 17:43:47 UTC

Created attachment 295929 [details]
Dealing with scsi_debug module removal / load races

Just for document ion purposes, providing a simple script which demos what can be done to properly deal with the scsi_debug module load / unload races.

Comment 3 d gilbert 2021-03-18 18:42:14 UTC

On 2021-03-18 1:38 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=212337
> 
> Luis Chamberlain (mcgrof@kernel.org) changed:
> 
>             What    |Removed                     |Added
> ----------------------------------------------------------------------------
>               Status|NEW                         |RESOLVED
>           Resolution|---                         |WILL_NOT_FIX
> 
> --- Comment #1 from Luis Chamberlain (mcgrof@kernel.org) ---
> 
> At first glance this might seem like a problem with scsi's async probe, and
> so
> one might believe disabling CONFIG_SCSI_SCAN_ASYNC could help, however it
> does
> not. Linux scsi doesn't have semantics to allow only one driver to prefer to
> probe asynchronously, but we can shoe-horn this in as follows:
> 
> diff --git a/drivers/scsi/scsi_debug.c b/drivers/scsi/scsi_debug.c
> index 3cdeaeb92933..d970050ae866 100644
> --- a/drivers/scsi/scsi_debug.c
> +++ b/drivers/scsi/scsi_debug.c
> @@ -857,6 +857,8 @@ static const int device_qfull_result =
> 
>   static const int condition_met_result = SAM_STAT_CONDITION_MET;
> 
> +MODULE_IMPORT_NS(SCSI_PRIVATE);
> +int scsi_complete_async_scans(void);
> 
>   /* Only do the extra work involved in logical block provisioning if one or
>    * more of the lbpu, lbpws or lbpws10 parameters are given and we are doing
> @@ -6851,6 +6853,7 @@ static int __init scsi_debug_init(void)
>                          }
>                  }
>          }
> +       scsi_complete_async_scans();
>          if (sdebug_verbose)
>                  pr_info("built %d host(s)\n", sdebug_num_hosts);
> 
> Even with this present though we still have he refcnt issue. A better way to
> see what is going on is to trace the kernel module calls after boot and see
> why
> perhaps certain refcounts for the module are high at times and why they are
> not
> in most other cases.

Hi,
Interesting analysis. There have been many changes to the scsi_debug driver
during the last 6 months, but none that I can remember in module
initialization area. Do you think this is a problem introduced by those
changes or may it have been there for a longer period? Could it be that
the scsi_debug driver is exposing the async nature of the scanning code.
Of course, commencing device teardown during an async scan is stress testing
that code. It would be an improvement IMO, if rmmod alerted the module
in question when it rejects a removal attempt with "device busy".

To stop any higher levels setting up SCSI devices before the async scans
are complete, the scsi_debug can set TEST UNIT READY to return an error
along the lines of: not ready, device in process of becoming ready
BTW that is what real devices do, but scsi_debug does not do that by default.

The scsi_debug module option that is already in place is:
   tur_ms_to_ready: TEST UNIT READY millisecs before initial good status (def=0)

So it's just a fixed delay at the moment. Perhaps you could experiment with that
option to see if it improves things.

The post is cc-ed to Hannes Reinecke who does most of the work in the async
scanning area.

Doug Gilbert


> Enable module tracing
> 
> # for i in $(sudo find /sys/kernel/debug/tracing/events/module/ -name
> "enable"); do echo 1 > $i; done
> 
> Run a loop to test modprobe / rmmod, and fail if either fails. In this case
> let's assume a success of rmmod once and then a failure on the second
> removal.
> We get the following ftrace, I'll provide some comments in areas where this
> may
> be useful
> 
> # cat trace /sys/kernel/tracing
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 355/355   #P:8
> #
> #                                _-----=> irqs-off
> #                               / _----=> need-resched
> #                              | / _---=> hardirq/softirq
> #                              || / _--=> preempt-depth
> #                              ||| /     delay
> #           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
> #              | |         |   ||||      |         |
>          modprobe-902     [005] ....    45.731217: module_get: scsi_mod
> call_site=resolve_symbol refcnt=6
>          modprobe-902     [005] ....    45.732844: module_load: scsi_debug E
>          modprobe-902     [005] ....    45.732850: module_get: scsi_debug
> call_site=sdebug_add_store [scsi_debug] refcnt=3
>          modprobe-902     [005] ....    45.733589: module_put: scsi_debug
> call_site=sdebug_add_store [scsi_debug] refcnt=2
>          modprobe-902     [005] ....    45.733963: module_get: scsi_debug
> call_site=sdebug_driver_probe [scsi_debug] refcnt=3
>          modprobe-902     [001] ....    45.738246: module_put: scsi_debug
> call_site=sdebug_driver_probe [scsi_debug] refcnt=2
>     kworker/u16:3-173     [002] ....    45.738790: module_get: scsi_debug
> call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=3
>     kworker/u16:3-173     [002] ....    45.739943: module_put: scsi_debug
> call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=2
>     kworker/u16:3-173     [007] ....    45.748555: module_get: scsi_debug
> call_site=scsi_debug_slave_configure [scsi_debug] refcnt=3
>     kworker/u16:3-173     [007] .N..    45.749962: module_put: scsi_debug
> call_site=scsi_debug_slave_configure [scsi_debug] refcnt=2
>     kworker/u16:3-173     [000] d...    45.766235: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=3
>     kworker/u16:3-173     [000] d...    45.769197: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=4
>     kworker/u16:3-173     [000] ....    45.769197: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=3
>     kworker/u16:3-173     [000] ....    45.769198: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=2
>     kworker/u16:3-173     [000] d...    45.769199: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=3
>     kworker/u16:3-173     [000] ....    45.769785: module_put: scsi_debug
> call_site=__scsi_iterate_devices [scsi_mod] refcnt=2
>          modprobe-902     [001] ....    45.773492: module_put: scsi_debug
> call_site=do_init_module refcnt=1
> 
> So we can escape initialization early in one case as sg module is not yet
> available.
> 
>     systemd-udevd-907     [001] ....    45.773818: module_get: scsi_mod
> call_site=resolve_symbol refcnt=7
>     systemd-udevd-907     [001] ....    45.774708: module_load: sg E
>     systemd-udevd-907     [001] ....    45.776173: module_put: sg
> call_site=do_init_module refcnt=1
>     systemd-udevd-907     [001] ....    45.778501: module_get: scsi_mod
> call_site=resolve_symbol refcnt=8
>     systemd-udevd-907     [001] ....    45.778569: module_get: t10_pi
> call_site=resolve_symbol refcnt=3
>     systemd-udevd-907     [001] ....    45.779733: module_load: sd_mod E
>     systemd-udevd-907     [001] ....    45.828660: module_put: sd_mod
> call_site=do_init_module refcnt=1
>             rmmod-908     [003] ....    45.921238: module_free: scsi_debug
> 
> We remove the scsi_debug module here fine before systemd-udevd has opened the
> device.
> 
>             rmmod-908     [003] ....    45.921442: module_put: scsi_mod
> call_site=module_unload_free refcnt=7
>          modprobe-914     [006] ....    45.944276: module_get: scsi_mod
> call_site=resolve_symbol refcnt=8
> 
>          modprobe-914     [006] ....    45.945820: module_load: scsi_debug E
>          modprobe-914     [006] ....    45.945825: module_get: scsi_debug
> call_site=sdebug_add_store [scsi_debug] refcnt=3
>          modprobe-914     [006] ....    45.946553: module_put: scsi_debug
> call_site=sdebug_add_store [scsi_debug] refcnt=2
>          modprobe-914     [006] ....    45.947044: module_get: scsi_debug
> call_site=sdebug_driver_probe [scsi_debug] refcnt=3
>          modprobe-914     [006] ....    45.952509: module_put: scsi_debug
> call_site=sdebug_driver_probe [scsi_debug] refcnt=2
>     kworker/u16:3-173     [006] ....    45.953257: module_get: scsi_debug
> call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=3
>     kworker/u16:3-173     [006] .N..    45.954616: module_put: scsi_debug
> call_site=scsi_debug_slave_alloc [scsi_debug] refcnt=2
>     kworker/u16:3-173     [006] ....    45.964402: module_get: scsi_debug
> call_site=scsi_debug_slave_configure [scsi_debug] refcnt=3
>     kworker/u16:3-173     [006] .N..    45.965695: module_put: scsi_debug
> call_site=scsi_debug_slave_configure [scsi_debug] refcnt=2
>     kworker/u16:3-173     [005] d...    46.213491: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=3
>     kworker/u16:3-173     [005] d...    46.215346: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=4
>     kworker/u16:3-173     [005] ....    46.215347: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=3
>     kworker/u16:3-173     [005] ....    46.215348: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=2
>     kworker/u16:3-173     [005] d...    46.215350: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=3
>     kworker/u16:3-173     [005] ....    46.220794: module_put: scsi_debug
> call_site=__scsi_iterate_devices [scsi_mod] refcnt=2
>     kworker/u16:4-174     [004] ....    46.224892: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] ....    46.224893: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] ....    46.224894: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.228906: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.228907: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.228907: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] ....    46.230926: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] ....    46.230926: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] ....    46.230927: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.234937: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.234938: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.234938: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] .N..    46.246062: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] .N..    46.246064: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] .N..    46.246065: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.250071: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.250072: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.250072: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] ....    46.252943: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] ....    46.252943: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] ....    46.252944: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.256956: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.256957: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.256957: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] ....    46.258547: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] ....    46.258547: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] ....    46.258548: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.262558: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.262558: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.262559: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] .N..    46.266484: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] .N..    46.266484: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] .N..    46.266485: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.270492: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.270492: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.270493: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] ....    46.272381: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] ....    46.272382: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] ....    46.272382: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.276393: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.276393: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.276394: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] ....    46.278258: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>     kworker/u16:4-174     [004] ....    46.278259: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [004] ....    46.278259: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.282269: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=4
>            <idle>-0       [004] d.h.    46.282270: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>            <idle>-0       [004] d.h.    46.282270: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=2
>     kworker/u16:4-174     [004] ....    46.374616: module_get: sd_mod
> call_site=blkdev_get_no_open refcnt=2
>     kworker/u16:4-174     [004] ....    46.374617: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=3
>      kworker/4:1H-189     [004] ....    46.376457: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>      kworker/4:1H-189     [004] ....    46.376457: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>      kworker/4:1H-189     [004] ....    46.376458: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>       kworker/4:1-62      [004] d.h.    46.380469: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>       kworker/4:1-62      [004] d.h.    46.380470: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>       kworker/4:1-62      [004] d.h.    46.380470: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>      kworker/0:1H-89      [000] ....    46.383278: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>      kworker/0:1H-89      [000] ....    46.383279: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>      kworker/0:1H-89      [000] ....    46.383280: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.387291: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [000] d.h.    46.387292: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.387292: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>      kworker/0:1H-89      [000] ....    46.389080: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>      kworker/0:1H-89      [000] ....    46.389081: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>      kworker/0:1H-89      [000] ....    46.389081: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.393090: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [000] d.h.    46.393091: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.393091: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     kworker/u16:4-174     [000] ....    46.393170: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=2
>     kworker/u16:4-174     [000] ....    46.393171: module_put: sd_mod
> call_site=blkdev_put refcnt=1
>     systemd-udevd-907     [003] ....    46.393476: module_get: sd_mod
> call_site=blkdev_get_no_open refcnt=2
>     systemd-udevd-907     [003] ....    46.393477: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=3
>     kworker/u16:4-174     [000] ....    46.395771: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.395772: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.395773: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.399789: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [000] d.h.    46.399790: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.399790: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     kworker/u16:4-174     [000] ....    46.402067: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.402068: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.402069: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.406078: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [000] d.h.    46.406079: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [000] d.h.    46.406079: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>         multipath-926     [005] ....    46.409545: module_get: sd_mod
> call_site=blkdev_get_no_open refcnt=3
>         multipath-926     [005] ....    46.409547: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=4
>         multipath-926     [005] ....    46.409649: module_get: dm_mod
> call_site=misc_open refcnt=2
>         multipath-926     [005] ....    46.409773: module_put: dm_mod
> call_site=__fput refcnt=1
>         multipath-926     [005] ....    46.410096: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=3
>         multipath-926     [005] ....    46.410097: module_put: sd_mod
> call_site=blkdev_put refcnt=2
>     systemd-udevd-907     [003] ....    46.410279: module_get: sd_mod
> call_site=blkdev_get_no_open refcnt=3
>     systemd-udevd-907     [003] ....    46.410280: module_get: scsi_debug
> call_site=scsi_device_get [scsi_mod] refcnt=4
>     systemd-udevd-907     [003] ....    46.413760: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.413760: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.413760: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.417764: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
>            <idle>-0       [003] d.h.    46.417764: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.417764: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.438981: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.438981: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     kworker/u16:4-174     [000] ....    46.438982: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.439875: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.439875: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=7
>     systemd-udevd-907     [003] ....    46.439876: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.442992: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
>            <idle>-0       [000] d.h.    46.442993: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.442994: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.443880: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
>            <idle>-0       [003] d.h.    46.443880: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.443880: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.444546: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.444547: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     kworker/u16:4-174     [000] ....    46.444548: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.445450: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.445450: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=7
>     systemd-udevd-907     [003] ....    46.445450: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.448558: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
>            <idle>-0       [000] d.h.    46.448559: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.448559: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.449452: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
>            <idle>-0       [003] d.h.    46.449453: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.449453: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.450135: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.450136: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     kworker/u16:4-174     [000] ....    46.450136: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.451003: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.451003: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=7
>     systemd-udevd-907     [003] ....    46.451004: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.454147: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
>            <idle>-0       [000] d.h.    46.454148: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.454148: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.455008: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
>            <idle>-0       [003] d.h.    46.455008: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.455008: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.455910: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.455910: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     kworker/u16:4-174     [000] ....    46.455911: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.456804: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.456805: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=7
>     systemd-udevd-907     [003] ....    46.456805: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.459920: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
>            <idle>-0       [000] d.h.    46.459921: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.459921: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.460808: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
>            <idle>-0       [003] d.h.    46.460809: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.460809: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.461664: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.461664: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     kworker/u16:4-174     [000] ....    46.461665: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.462544: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.462545: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=7
>     systemd-udevd-907     [003] ....    46.462545: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.465674: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
>            <idle>-0       [000] d.h.    46.465675: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.465675: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.466547: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
>            <idle>-0       [003] d.h.    46.466548: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.466548: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>     kworker/u16:4-174     [000] ....    46.467413: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     kworker/u16:4-174     [000] ....    46.467413: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     kworker/u16:4-174     [000] ....    46.467414: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.468319: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.468319: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=7
>     systemd-udevd-907     [003] ....    46.468319: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.471425: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=7
>            <idle>-0       [000] d.h.    46.471426: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=6
>            <idle>-0       [000] d.h.    46.471426: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.472322: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=6
>            <idle>-0       [003] d.h.    46.472323: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.472323: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.473538: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.473538: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=6
>     systemd-udevd-907     [003] ....    46.473538: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>          modprobe-914     [006] ....    46.474870: module_put: scsi_debug
> call_site=do_init_module refcnt=4
> 
>            <idle>-0       [003] d.h.    46.477540: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.477541: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.477541: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.478789: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.478789: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.478790: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.482795: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.482796: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.482796: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.483713: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.483713: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.483714: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.487723: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.487723: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.487724: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.488736: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.488737: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.488737: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.492740: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.492741: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.492741: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.493621: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.493621: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.493621: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.497627: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.497628: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.497628: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.498631: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.498632: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.498632: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.502634: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.502635: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.502635: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.503506: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.503507: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.503507: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.507513: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.507513: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.507514: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.508540: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.508540: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.508541: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.512543: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.512543: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.512543: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.513421: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.513421: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.513421: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.517425: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.517425: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.517425: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.518504: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.518505: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.518505: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.522509: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.522509: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.522509: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.523418: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.523418: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.523418: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.527420: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.527420: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.527420: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.528436: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.528437: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.528437: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.532440: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.532441: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.532441: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.533324: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.533324: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.533324: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.537329: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.537330: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.537330: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.538373: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.538374: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.538374: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.542376: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.542377: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.542377: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.543259: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.543260: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.543260: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.547268: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.547269: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.547269: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.548246: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.548246: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.548247: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.552251: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.552251: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.552251: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.553258: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.553258: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.553258: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.557264: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.557264: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.557264: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.558294: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.558295: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.558295: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.562299: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.562300: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.562300: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.563242: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.563242: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.563242: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.567248: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.567248: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.567249: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.568196: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.568196: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.568197: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.572204: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.572205: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.572205: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.573125: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.573125: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.573126: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.577132: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.577133: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.577133: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.578070: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.578071: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.578071: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.582079: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.582080: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.582080: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.583013: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>     systemd-udevd-907     [003] ....    46.583013: module_get: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=5
>     systemd-udevd-907     [003] ....    46.583014: module_put: scsi_debug
> call_site=schedule_resp [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.587025: module_get: scsi_debug
> call_site=sdebug_q_cmd_complete [scsi_debug] refcnt=5
>            <idle>-0       [003] d.h.    46.587026: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=4
>            <idle>-0       [003] d.h.    46.587026: module_put: scsi_debug
> call_site=sdebug_q_cmd_hrt_complete [scsi_debug] refcnt=3
>     systemd-udevd-907     [003] ....    46.587080: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=2
>     systemd-udevd-907     [003] ....    46.587081: module_put: sd_mod
> call_site=blkdev_put refcnt=2
>     systemd-udevd-907     [003] ....    46.588154: module_put: scsi_debug
> call_site=scsi_device_put [scsi_mod] refcnt=1
>     systemd-udevd-907     [003] ....    46.588155: module_put: sd_mod
> call_site=blkdev_put refcnt=1
> 
> One might be at first motivated to implment sledge hammers as follows:
> 
> static void sdebug_wait_empty_num_in_q(void)
> {
>          struct sdebug_host_info *sdbg_host;
>          struct Scsi_Host *shost;
>          struct scsi_device *sdev;
>          struct sdebug_dev_info *devip;
>          int count, max_wait = 5, k;
>          bool busy;
> 
>          while (true) {
>                  busy = false;
>                  spin_lock(&sdebug_host_list_lock);
>                  list_for_each_entry(sdbg_host, &sdebug_host_list, host_list)
>                  {
>                          shost = sdbg_host->shost;
>                          shost_for_each_device(sdev, shost) {
>                                  devip = (struct sdebug_dev_info
> *)sdev->hostdata;
>                                  if (atomic_read(&devip->num_in_q) != 0)
>                                          busy = true;
>                                  k = find_first_bit(devip->uas_bm,
> SDEBUG_NUM_UAS);
>                                  if (k != SDEBUG_NUM_UAS)
>                                          busy = true;
>                          }
>                  }
>                  spin_unlock(&sdebug_host_list_lock);
>                  if (!busy || count >= max_wait) {
>                          break;
>                  }
>                  ssleep(1);
>                  count++;
>          }
> }
> 
> /* Waits for all pending commands to complete. */
> static void wait_all_queued(void)
> {
>          int j, k;
>          struct sdebug_queue *sqp;
>          bool busy;
> 
>          while (true) {
>                  busy = false;
>                  for (j = 0, sqp = sdebug_q_arr; j < submit_queues; ++j,
>                  ++sqp)
> {
>                          k = find_first_bit(sqp->in_use_bm,
>                          sdebug_max_queue);
>                          if (k != sdebug_max_queue)
>                                  busy = true;
>                  }
>                  if (!busy)
>                          break;
>                  ssleep(1);
>          }
> }
> 
> static void sync_qc_helper(struct sdebug_defer *sd_dp,
>                             enum sdeb_defer_type defer_t)
> {
>          if (!sd_dp)
>                  return;
>          if (defer_t == SDEB_DEFER_HRT) {
>                  hrtimer_forward_now(&sd_dp->hrt, 2 *
> hrtimer_get_remaining(&sd_dp->hrt));
>          } else if (defer_t == SDEB_DEFER_WQ) {
>                  flush_work(&sd_dp->ew.work);
>          }
> }
> 
> static void scsi_debug_sync_queued_cmnd(void)
> {
>          unsigned long iflags;
>          int j, k, qmax, r_qmax;
>          enum sdeb_defer_type l_defer_t;
>          struct sdebug_queue *sqp;
>          struct sdebug_queued_cmd *sqcp;
>          struct sdebug_defer *sd_dp;
> 
>          for (j = 0, sqp = sdebug_q_arr; j < submit_queues; ++j, ++sqp) {
>                  spin_lock_irqsave(&sqp->qc_lock, iflags);
>                  qmax = sdebug_max_queue;
>                  r_qmax = atomic_read(&retired_max_queue);
>                  if (r_qmax > qmax)
>                          qmax = r_qmax;
>                  for (k = 0; k < qmax; ++k) {
>                          if (test_bit(k, sqp->in_use_bm)) {
>                                  sqcp = &sqp->qc_arr[k];
>                                  sd_dp = sqcp->sd_dp;
>                                  if (sd_dp)
>                                          l_defer_t = sd_dp->defer_t;
>                                  else
>                                          l_defer_t = SDEB_DEFER_NONE;
>                                  spin_unlock_irqrestore(&sqp->qc_lock,
>                                  iflags);
>                                  sync_qc_helper(sd_dp, l_defer_t);
>                                  spin_lock_irqsave(&sqp->qc_lock, iflags);
>                          }
>                  }
>                  spin_unlock_irqrestore(&sqp->qc_lock, iflags);
>          }
> }
> 
> static void wait_for_ready(void)
> {
>          struct scsi_sense_hdr sense_hdr;
>          struct sdebug_host_info *sdbg_host;
>          struct Scsi_Host *shost;
>          struct scsi_device *sdev;
>          int ret;
>          bool all_ready;
> 
>          spin_lock(&sdebug_host_list_lock);
>          while (true) {
>                  all_ready = true;
>                  list_for_each_entry(sdbg_host, &sdebug_host_list, host_list)
>                  {
>                          shost = sdbg_host->shost;
>                          shost_for_each_device(sdev, shost) {
>                                  ret =
>                                  scsi_internal_device_block_nowait(sdev);
>                                  if (ret)
>                                          all_ready = false;
>                                  ret =
>                                  scsi_internal_device_unblock_nowait(sdev,
> SDEV_RUNNING);
>                                  if (ret)
>                                          all_ready = false;
>                                  ret = scsi_test_unit_ready(sdev, 5 * HZ,
>                                  100,
> &sense_hdr);
>                                  if (ret != 0)
>                                          all_ready = false;
>                          }
>                  }
>                  if (all_ready)
>                          break;
>                  ssleep(1);
>          }
>          spin_unlock(&sdebug_host_list_lock);
> }
> 
> And use these on scsi_debug_init() but that does not suffice, and the reason
> is
> that userspace can open the scsi devices after initialization, namely in this
> case we see evidence of userspace processes such as systemd-udevd and
> multipath
> which will try to open the device.
> 
> There are a few solutions possible, using sync, or sg_sync is not one of them
> as we have to ensure we have no userspace application accessing the devices
> still.
> 
> You can use lsof for this purpose. Below is an example script which can be
> used.
> 
> #!/bin/bash
> 
> LOOP=1
> 
> while true; do
>          modprobe scsi_debug
>          if [[ $? -ne 0 ]]; then
>                  echo "scsi_debug modprobe failed at count $LOOP"
>                  exit 1
>          fi
>          while true; do
>                  # Let other modules which scsi_debug depends on like sg
>                  # and t10_pi load first to ensure any commands sent to
>                  # the device are sent.
>                  sleep 1
> 
>                  # Now wait until userspace such as systemd-udevd and
>                  multipath
>                  # are done inspecting the newly exposed devices.
>                  COUNT=$(lsof /dev/sda | wc -l)
>                  if [[ $COUNT -ne 0 ]]; then
>                          echo "Sleeping ..."
>                          sleep 1;
>                  fi
>                  break
>          done
>          # Now you are safe to use scsi_debug exposed devices.
> 
>          # You are also free to remove it.
>          rmmod scsi_debug
>          if [[ $? -ne 0 ]]; then
>                  echo "scsi_debug rmmod failed at count $LOOP"
>                  exit 1
>          else
>                  echo "Loop $LOOP: OK!"
>          fi
>          let LOOP=$LOOP+1
> done
> 
> 
> Marking this bug as resolved and won't fix as this should hopefully suffice
> to
> document why we can't wait on scsi_debug_init() to fix this issue, and it
> must
> be addressed in userspace.
>

Comment 4 Luis Chamberlain 2021-03-18 19:14:37 UTC

(In reply to d gilbert from comment #3)
> On 2021-03-18 1:38 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> > https://bugzilla.kernel.org/show_bug.cgi?id=212337
> > 
> > Luis Chamberlain (mcgrof@kernel.org) changed:
> > 
> >             What    |Removed                     |Added
> >
> ----------------------------------------------------------------------------
> >               Status|NEW                         |RESOLVED
> >           Resolution|---                         |WILL_NOT_FIX
> > 
> > --- Comment #1 from Luis Chamberlain (mcgrof@kernel.org) ---
> > 
> > At first glance this might seem like a problem with scsi's async probe, and
> > so
> > one might believe disabling CONFIG_SCSI_SCAN_ASYNC could help, however it
> > does
> > not. Linux scsi doesn't have semantics to allow only one driver to prefer
> to
> > probe asynchronously, but we can shoe-horn this in as follows:
> > 
> > diff --git a/drivers/scsi/scsi_debug.c b/drivers/scsi/scsi_debug.c
> > index 3cdeaeb92933..d970050ae866 100644
> > --- a/drivers/scsi/scsi_debug.c
> > +++ b/drivers/scsi/scsi_debug.c
> > @@ -857,6 +857,8 @@ static const int device_qfull_result =
> > 
> >   static const int condition_met_result = SAM_STAT_CONDITION_MET;
> > 
> > +MODULE_IMPORT_NS(SCSI_PRIVATE);
> > +int scsi_complete_async_scans(void);
> > 
> >   /* Only do the extra work involved in logical block provisioning if one
> or
> >    * more of the lbpu, lbpws or lbpws10 parameters are given and we are
> doing
> > @@ -6851,6 +6853,7 @@ static int __init scsi_debug_init(void)
> >                          }
> >                  }
> >          }
> > +       scsi_complete_async_scans();
> >          if (sdebug_verbose)
> >                  pr_info("built %d host(s)\n", sdebug_num_hosts);
> > 
> > Even with this present though we still have he refcnt issue. A better way
> to
> > see what is going on is to trace the kernel module calls after boot and see
> > why
> > perhaps certain refcounts for the module are high at times and why they are
> > not
> > in most other cases.
> 
> Hi,
> Interesting analysis. There have been many changes to the scsi_debug driver
> during the last 6 months, but none that I can remember in module
> initialization area. Do you think this is a problem introduced by those
> changes or may it have been there for a longer period?\

This problem has existed since it was decided to do loading of things at init. Its a terribly bad idea t do a lot work at init.

> Could it be that
> the scsi_debug driver is exposing the async nature of the scanning code.

Nope. That's not it. I tried by disabling async scan and also forcing it as I mentioned by exporting the function to wait.

> Of course, commencing device teardown during an async scan is stress testing
> that code.

I'm afraid scsi_debug is filled with bug bombs bound to happen, because it was written without certain consideration of races now coming up as tangible with syfs / driver load. Namely, if you hold a lock at init and also use it on sysfs attributes you can easily deadlock. I discovered this issue first with the zram driver, and fixed the issue with try_module_get()'s on each driver sysfs attribute, I posted patches for that, for discussion on that see the post [0] [1], although discussion is mostly on the first patch, the patch you want to look at is the second one [1].

[0] https://lkml.kernel.org/r/20210306022035.11266-2-mcgrof@kernel.org
[1] https://lkml.kernel.org/r/20210306022035.11266-3-mcgrof@kernel.org

I considered fixing scsi_debug in light of this, but given that module initialization is *also* calling helpers used by syfs attributes, *and* this is also true at module removal, I'm afraid much more care is needed here. In my patch to zram for the sysfs issue I mention ways to trigger the deadlock, if you're up for the task to fix that, it would be wonderful. But hey, these are separate issues. just figured you should be aware.

> It would be an improvement IMO, if rmmod alerted the module
> in question when it rejects a removal attempt with "device busy".

rmmod does just that when it can find that. In this case it can just provide a refcount.

> To stop any higher levels setting up SCSI devices before the async scans
> are complete, the scsi_debug can set TEST UNIT READY to return an error
> along the lines of: not ready, device in process of becoming ready

OK cool, we could try this, but I'm afraid it would not fix the issue, given that you may have userspace applications such as multipath mucking with the device on init, and you won't know when its done. So I still think that the onus is on userspace here.

Ideally I'd actually just remove the damn setup stuff on init, but since we have old users, I'm afraid that's not possible now. Granted, scsi_debug is a developer tool, so perhaps its OK to deprecate that. But still, you end up with the same requirements to verify the refcnt is 1 before trying to remove it.

> BTW that is what real devices do, but scsi_debug does not do that by default.

Why not?

> The scsi_debug module option that is already in place is:
>    tur_ms_to_ready: TEST UNIT READY millisecs before initial good status
> (def=0)
> 
> So it's just a fixed delay at the moment. Perhaps you could experiment with
> that
> option to see if it improves things.

fstests / blktests relies on scsi_debug for a few tests, we need a solution documented / in palce for both upstream / older kernels. If setting the not-ready thing on init works, we would still need to verify a solution for older kernels.

Comment 5 Luis Chamberlain 2021-03-18 19:20:00 UTC

(In reply to Luis Chamberlain from comment #4)
> (In reply to d gilbert from comment #3)
> > Of course, commencing device teardown during an async scan is stress
> testing
> > that code.
> 
> I'm afraid scsi_debug is filled with bug bombs bound to happen, because it
> was written without certain consideration of races now coming up as tangible
> with syfs / driver load. Namely, if you hold a lock at init and also use it
> on sysfs attributes you can easily deadlock. I discovered this issue first
> with the zram driver, and fixed the issue with try_module_get()'s on each
> driver sysfs attribute, I posted patches for that, for discussion on that
> see the post [0] [1], although discussion is mostly on the first patch, the
> patch you want to look at is the second one [1].
> 
> [0] https://lkml.kernel.org/r/20210306022035.11266-2-mcgrof@kernel.org
> [1] https://lkml.kernel.org/r/20210306022035.11266-3-mcgrof@kernel.org
> 
> I considered fixing scsi_debug in light of this, but given that module
> initialization is *also* calling helpers used by syfs attributes, *and* this
> is also true at module removal, I'm afraid much more care is needed here. In
> my patch to zram for the sysfs issue I mention ways to trigger the deadlock,
> if you're up for the task to fix that, it would be wonderful. But hey, these
> are separate issues. just figured you should be aware.

That was a long winded way of saying -- yes stress testing async scan + teardown may be good, but at this point in time *these* other issues I think are of higher priority before one can even consider stress testing async scan + teardown.

Oh and also, someone should probably consider if this is required or not, I have a hunch it may, but not sure:

commit 48f3c4f354ce113f45cb5adbebe0f1f06f1487f7
Author: Luis Chamberlain <mcgrof@kernel.org>
Date:   Thu Mar 18 15:22:34 2021 +0000

    scsi_lib: try module get before running queue
    
    Signed-off-by: Luis Chamberlain <mcgrof@kernel.org>

diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index ffe824782647..0af38f8936e4 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -22,6 +22,7 @@
 #include <linux/scatterlist.h>
 #include <linux/blk-mq.h>
 #include <linux/ratelimit.h>
+#include <linux/module.h>
 #include <asm/unaligned.h>
 
 #include <scsi/scsi.h>
@@ -1527,6 +1528,12 @@ static int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
 
 	}
 
+	if (!try_module_get(host->hostt->module)) {
+		cmd->result = (DID_NO_CONNECT << 16);
+		goto done;
+
+	}
+
 	trace_scsi_dispatch_cmd_start(cmd);
 	rtn = host->hostt->queuecommand(host, cmd);
 	if (rtn) {
@@ -1538,6 +1545,7 @@ static int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
 		SCSI_LOG_MLQUEUE(3, scmd_printk(KERN_INFO, cmd,
 			"queuecommand : request rejected\n"));
 	}
+	module_put(host->hostt->module);
 
 	return rtn;
  done:

Comment 6 Luis Chamberlain 2021-03-18 19:22:26 UTC

(In reply to Luis Chamberlain from comment #5)
> (In reply to Luis Chamberlain from comment #4)
> > (In reply to d gilbert from comment #3)
> > > Of course, commencing device teardown during an async scan is stress
> > testing
> > > that code.
> > 
> > I'm afraid scsi_debug is filled with bug bombs bound to happen, because it
> > was written without certain consideration of races now coming up as
> tangible
> > with syfs / driver load. Namely, if you hold a lock at init and also use it
> > on sysfs attributes you can easily deadlock. I discovered this issue first
> > with the zram driver, and fixed the issue with try_module_get()'s on each
> > driver sysfs attribute, I posted patches for that, for discussion on that
> > see the post [0] [1], although discussion is mostly on the first patch, the
> > patch you want to look at is the second one [1].
> > 
> > [0] https://lkml.kernel.org/r/20210306022035.11266-2-mcgrof@kernel.org
> > [1] https://lkml.kernel.org/r/20210306022035.11266-3-mcgrof@kernel.org
> > 
> > I considered fixing scsi_debug in light of this, but given that module
> > initialization is *also* calling helpers used by syfs attributes, *and*
> this
> > is also true at module removal, I'm afraid much more care is needed here.
> In
> > my patch to zram for the sysfs issue I mention ways to trigger the
> deadlock,
> > if you're up for the task to fix that, it would be wonderful. But hey,
> these
> > are separate issues. just figured you should be aware.
> 
> That was a long winded way of saying -- yes stress testing async scan +
> teardown may be good, but at this point in time *these* other issues I think
> are of higher priority before one can even consider stress testing async
> scan + teardown.
> 
> Oh and also, someone should probably consider if this is required or not, I
> have a hunch it may, but not sure:
> 
> commit 48f3c4f354ce113f45cb5adbebe0f1f06f1487f7
> Author: Luis Chamberlain <mcgrof@kernel.org>
> Date:   Thu Mar 18 15:22:34 2021 +0000
> 
>     scsi_lib: try module get before running queue
>     
>     Signed-off-by: Luis Chamberlain <mcgrof@kernel.org>
> 
> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> index ffe824782647..0af38f8936e4 100644
> --- a/drivers/scsi/scsi_lib.c
> +++ b/drivers/scsi/scsi_lib.c
> @@ -22,6 +22,7 @@
>  #include <linux/scatterlist.h>
>  #include <linux/blk-mq.h>
>  #include <linux/ratelimit.h>
> +#include <linux/module.h>
>  #include <asm/unaligned.h>
>  
>  #include <scsi/scsi.h>
> @@ -1527,6 +1528,12 @@ static int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
>  
>       }
>  
> +     if (!try_module_get(host->hostt->module)) {
> +             cmd->result = (DID_NO_CONNECT << 16);
> +             goto done;
> +
> +     }
> +
>       trace_scsi_dispatch_cmd_start(cmd);
>       rtn = host->hostt->queuecommand(host, cmd);
>       if (rtn) {
> @@ -1538,6 +1545,7 @@ static int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
>               SCSI_LOG_MLQUEUE(3, scmd_printk(KERN_INFO, cmd,
>                       "queuecommand : request rejected\n"));
>       }
> +     module_put(host->hostt->module);
>  
>       return rtn;
>   done:

I should explain a bit more here. Refcounting on the driver's queuecommand() is possible for sure, *but* in scsi_debug's case its quite complex given we have 3 ways to queue commands:

  * right away
  * work queue
  * hrtimer

Yes, you can refcount at the top, but the code is easier to manage / if the library does it. And if its indeed correct, better it goes there.

Comment 7 Luis Chamberlain 2021-03-18 19:57:21 UTC

(In reply to d gilbert from comment #3)
> To stop any higher levels setting up SCSI devices before the async scans
> are complete, the scsi_debug can set TEST UNIT READY to return an error
> along the lines of: not ready, device in process of becoming ready
> BTW that is what real devices do, but scsi_debug does not do that by default.

I looked but it was not clear how to do this exactly.

Comment 8 d gilbert 2021-03-18 21:00:10 UTC

On 2021-03-18 3:14 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=212337
> 
> --- Comment #4 from Luis Chamberlain (mcgrof@kernel.org) ---
> (In reply to d gilbert from comment #3)
>> On 2021-03-18 1:38 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
>>> https://bugzilla.kernel.org/show_bug.cgi?id=212337
>>>
>>> Luis Chamberlain (mcgrof@kernel.org) changed:
>>>
>>>              What    |Removed                     |Added
>>>
>> ----------------------------------------------------------------------------
>>>                Status|NEW                         |RESOLVED
>>>            Resolution|---                         |WILL_NOT_FIX
>>>
>>> --- Comment #1 from Luis Chamberlain (mcgrof@kernel.org) ---
>>>
>>> At first glance this might seem like a problem with scsi's async probe, and
>>> so
>>> one might believe disabling CONFIG_SCSI_SCAN_ASYNC could help, however it
>>> does
>>> not. Linux scsi doesn't have semantics to allow only one driver to prefer
>> to
>>> probe asynchronously, but we can shoe-horn this in as follows:
>>>
>>> diff --git a/drivers/scsi/scsi_debug.c b/drivers/scsi/scsi_debug.c
>>> index 3cdeaeb92933..d970050ae866 100644
>>> --- a/drivers/scsi/scsi_debug.c
>>> +++ b/drivers/scsi/scsi_debug.c
>>> @@ -857,6 +857,8 @@ static const int device_qfull_result =
>>>
>>>    static const int condition_met_result = SAM_STAT_CONDITION_MET;
>>>
>>> +MODULE_IMPORT_NS(SCSI_PRIVATE);
>>> +int scsi_complete_async_scans(void);
>>>
>>>    /* Only do the extra work involved in logical block provisioning if one
>> or
>>>     * more of the lbpu, lbpws or lbpws10 parameters are given and we are
>> doing
>>> @@ -6851,6 +6853,7 @@ static int __init scsi_debug_init(void)
>>>                           }
>>>                   }
>>>           }
>>> +       scsi_complete_async_scans();
>>>           if (sdebug_verbose)
>>>                   pr_info("built %d host(s)\n", sdebug_num_hosts);
>>>
>>> Even with this present though we still have he refcnt issue. A better way
>> to
>>> see what is going on is to trace the kernel module calls after boot and see
>>> why
>>> perhaps certain refcounts for the module are high at times and why they are
>>> not
>>> in most other cases.
>>
>> Hi,
>> Interesting analysis. There have been many changes to the scsi_debug driver
>> during the last 6 months, but none that I can remember in module
>> initialization area. Do you think this is a problem introduced by those
>> changes or may it have been there for a longer period?\
> 
> This problem has existed since it was decided to do loading of things at
> init.
> Its a terribly bad idea t do a lot work at init.

Hi,
Addressing this issue first (i.e. loading things in scsi_debug_init() ). The
bulk of the work is done in that function's final for loop. Would putting
that in its own thread started by a workqueue help? If so, then
scsi_debug_init() could complete reasonably quickly. That thread
(called sdeb_add_hosts_thr, say) might still be running when a rmmod is
attempted. How to handle that?

>> Could it be that
>> the scsi_debug driver is exposing the async nature of the scanning code.
> 
> Nope. That's not it. I tried by disabling async scan and also forcing it as I
> mentioned by exporting the function to wait.

For some other testing, I was loading up 10,000 scsi_debug LUNs and found that
life was too short for ptype=0 (i.e. disks (and the default). When I set
ptype=21 (Reserved according to T10) things went impressively quickly. By
randomly killing threads, I suspect udev daemons are (a large) part of the cause.

>> Of course, commencing device teardown during an async scan is stress testing
>> that code.
> 
> I'm afraid scsi_debug is filled with bug bombs bound to happen, because it
> was
> written without certain consideration of races now coming up as tangible with
> syfs / driver load. Namely, if you hold a lock at init and also use it on
> sysfs
> attributes you can easily deadlock. I discovered this issue first with the
> zram
> driver, and fixed the issue with try_module_get()'s on each driver sysfs
> attribute, I posted patches for that, for discussion on that see the post [0]
> [1], although discussion is mostly on the first patch, the patch you want to
> look at is the second one [1].
> 
> [0] https://lkml.kernel.org/r/20210306022035.11266-2-mcgrof@kernel.org
> [1] https://lkml.kernel.org/r/20210306022035.11266-3-mcgrof@kernel.org
> 
> I considered fixing scsi_debug in light of this, but given that module
> initialization is *also* calling helpers used by syfs attributes, *and* this
> is
> also true at module removal, I'm afraid much more care is needed here. In my
> patch to zram for the sysfs issue I mention ways to trigger the deadlock, if
> you're up for the task to fix that, it would be wonderful. But hey, these are
> separate issues. just figured you should be aware.

In the hack proposed above, not much would appear in sysfs until that thread
finished adding at least adding its first host by which time scsi_debug_init()
should have long since finished.

>> It would be an improvement IMO, if rmmod alerted the module
>> in question when it rejects a removal attempt with "device busy".
> 
> rmmod does just that when it can find that. In this case it can just provide
> a
> refcount.

I'm looking for some callback that scsi_debug wires up in its init function
that when called will try and stop things, or at least stop adding new things.

>> To stop any higher levels setting up SCSI devices before the async scans
>> are complete, the scsi_debug can set TEST UNIT READY to return an error
>> along the lines of: not ready, device in process of becoming ready
> 
> OK cool, we could try this, but I'm afraid it would not fix the issue, given
> that you may have userspace applications such as multipath mucking with the
> device on init, and you won't know when its done. So I still think that the
> onus is on userspace here.
> 
> Ideally I'd actually just remove the damn setup stuff on init, but since we
> have old users, I'm afraid that's not possible now. Granted, scsi_debug is a
> developer tool, so perhaps its OK to deprecate that. But still, you end up
> with
> the same requirements to verify the refcnt is 1 before trying to remove it.
> 
>> BTW that is what real devices do, but scsi_debug does not do that by
>> default.
> 
> Why not?

Backward compatibility :-)

>> The scsi_debug module option that is already in place is:
>>     tur_ms_to_ready: TEST UNIT READY millisecs before initial good status
>> (def=0)

You asked how it works, try:
     modprobe scsi_debug tur_ms_to_ready=20000

Doug Gilbert

>> So it's just a fixed delay at the moment. Perhaps you could experiment with
>> that
>> option to see if it improves things.
> 
> fstests / blktests relies on scsi_debug for a few tests, we need a solution
> documented / in palce for both upstream / older kernels. If setting the
> not-ready thing on init works, we would still need to verify a solution for
> older kernels.
>

Comment 9 Luis Chamberlain 2021-03-22 16:23:06 UTC

(In reply to d gilbert from comment #8)

> >> The scsi_debug module option that is already in place is:
> >>     tur_ms_to_ready: TEST UNIT READY millisecs before initial good status
> >> (def=0)
> 
> You asked how it works, try:
>      modprobe scsi_debug tur_ms_to_ready=20000
> 

That does not resolve the rmmod race against insmod:

scsi host2: scsi_debug: version 0190 [20200710]
[   42.213400]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
[   42.217527] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug       0190 PQ: 0 ANSI: 7
[   42.223346] scsi 2:0:0:0: Attached scsi generic sg0 type 0
[   42.282195] scsi host2: scsi_debug: version 0190 [20200710]
[   42.282195]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
[   42.288169] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug       0190 PQ: 0 ANSI: 7
[   42.292122] sd 2:0:0:0: Attached scsi generic sg0 type 0
[   42.292244] sd 2:0:0:0: Power-on or device reset occurred
[   42.302288] sd 2:0:0:0: [sda] Spinning up disk...

Then we wait...

[   44.308213] ...................ready
[   62.748919] sd 2:0:0:0: [sda] 16384 512-byte logical blocks: (8.39 MB/8.00 MiB)
[   62.754265] sd 2:0:0:0: [sda] Write Protect is off
[   62.763253] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled, supports DPO and FUA
[   62.776965] sd 2:0:0:0: [sda] Optimal transfer size 524288 bytes
[   62.883817] sd 2:0:0:0: [sda] Attached SCSI disk

And then rmmod still fails.

Comment 10 Luis Chamberlain 2021-03-22 18:21:33 UTC

(In reply to Luis Chamberlain from comment #9)
> (In reply to d gilbert from comment #8)
> 
> > >> The scsi_debug module option that is already in place is:
> > >>     tur_ms_to_ready: TEST UNIT READY millisecs before initial good
> status
> > >> (def=0)
> > 
> > You asked how it works, try:
> >      modprobe scsi_debug tur_ms_to_ready=20000
> > 
> 
> That does not resolve the rmmod race against insmod:
> 
> scsi host2: scsi_debug: version 0190 [20200710]
> [   42.213400]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> [   42.217527] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug      
> 0190 PQ: 0 ANSI: 7
> [   42.223346] scsi 2:0:0:0: Attached scsi generic sg0 type 0
> [   42.282195] scsi host2: scsi_debug: version 0190 [20200710]
> [   42.282195]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> [   42.288169] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug      
> 0190 PQ: 0 ANSI: 7
> [   42.292122] sd 2:0:0:0: Attached scsi generic sg0 type 0
> [   42.292244] sd 2:0:0:0: Power-on or device reset occurred
> [   42.302288] sd 2:0:0:0: [sda] Spinning up disk...
> 
> Then we wait...
> 
> [   44.308213] ...................ready
> [   62.748919] sd 2:0:0:0: [sda] 16384 512-byte logical blocks: (8.39
> MB/8.00 MiB)
> [   62.754265] sd 2:0:0:0: [sda] Write Protect is off
> [   62.763253] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled,
> supports DPO and FUA
> [   62.776965] sd 2:0:0:0: [sda] Optimal transfer size 524288 bytes
> [   62.883817] sd 2:0:0:0: [sda] Attached SCSI disk
> 
> And then rmmod still fails.

Using udevadm settle (as used in blktests) after modprobe and before rmmod  fixes the issue. I tested modprobe udevadm settle; rmmod scsi_debug loop 5000 so far without issue.

I however note that we send uevents via kobject_uevent_net_broadcast() and that's a no-op for kernels without CONFIG_NET, and so this is not a true global solution either. Udev events are sent via netlink to userspace, and udev in userspace is in charge of handling the events. The command udevadm settle just checks if /run/udev/queue is 0. There is currently nothing we can do on scsi_debug to do something similar on init.

#!/bin/bash

LOOP=1

while true; do
        modprobe scsi_debug
        if [[ $? -ne 0 ]]; then
                echo "scsi_debug modprobe failed at count $LOOP"
                exit 1
        fi
        udevadm settle
        rmmod scsi_debug
        if [[ $? -ne 0 ]]; then
                echo "scsi_debug rmmod failed at count $LOOP"
                exit 1
        else
                echo "Loop $LOOP: OK!"
        fi
        let LOOP=$LOOP+1
done

I should note that this works even if one either delays async probe on sd.c, and/or also augments the delay and delays scheduling the probe as follows:

diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index 9179825ff646..b9ae63c17cb6 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -1071,6 +1071,7 @@ static int __driver_attach(struct device *dev, void *data)
        } /* ret > 0 means positive match */
 
        if (driver_allows_async_probing(drv)) {
+               ssleep(5);
                /*
                 * Instead of probing the device synchronously we will
                 * probe it asynchronously to allow for more parallelism.
diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index ed0b1bb99f08..79fc834073af 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -3371,6 +3371,7 @@ static int sd_probe(struct device *dev)
        int index;
        int error;
 
+       ssleep(3);
        scsi_autopm_get_device(sdp);
        error = -ENODEV;
        if (sdp->type != TYPE_DISK &&


Using wait_for_device_probe() on scsi_debug's driver init doesn't fix this either. And so I think we're stuck with userspace having to call udevadm settle after modprobe and before rmmod as well.

Comment 11 Luis Chamberlain 2021-03-22 18:31:07 UTC

(In reply to d gilbert from comment #8)
> On 2021-03-18 3:14 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> Addressing this issue first (i.e. loading things in scsi_debug_init() ). The
> bulk of the work is done in that function's final for loop. Would putting
> that in its own thread started by a workqueue help? If so, then
> scsi_debug_init() could complete reasonably quickly. That thread
> (called sdeb_add_hosts_thr, say) might still be running when a rmmod is
> attempted. How to handle that?

I don't think it would given we'd still move the race elsewhere. It would be nice design though to do that in principle though. Then load can be done using new sysfs knobs. But since we want to keep backward compatibility I can't see how this can help.

> >> It would be an improvement IMO, if rmmod alerted the module
> >> in question when it rejects a removal attempt with "device busy".
> > 
> > rmmod does just that when it can find that. In this case it can just
> provide
> > a
> > refcount.
> 
> I'm looking for some callback that scsi_debug wires up in its init function
> that when called will try and stop things, or at least stop adding new
> things.

If try_module_get() fails the module can be in leaving state, that is, its module removal is being called. But rmmod won't bother to call the unload module system call unless the refcount is 1.

So, the way to avoid doing things when the module is leaving is to check for try_module_get(). Other than that, one needs its own state machine. The races I observed however likely could not be fixed with a new state machine though, given the semantics would be the same. I can't see what other information the driver can get to prevent this race at this time.

Comment 12 d gilbert 2021-03-23 00:38:00 UTC

On 2021-03-22 12:23 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=212337
> 
> --- Comment #9 from Luis Chamberlain (mcgrof@kernel.org) ---
> (In reply to d gilbert from comment #8)
> 
>>>> The scsi_debug module option that is already in place is:
>>>>      tur_ms_to_ready: TEST UNIT READY millisecs before initial good status
>>>> (def=0)
>>
>> You asked how it works, try:
>>       modprobe scsi_debug tur_ms_to_ready=20000
>>
> 
> That does not resolve the rmmod race against insmod:
> 
> scsi host2: scsi_debug: version 0190 [20200710]
> [   42.213400]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> [   42.217527] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug       0190
> PQ: 0 ANSI: 7
> [   42.223346] scsi 2:0:0:0: Attached scsi generic sg0 type 0
> [   42.282195] scsi host2: scsi_debug: version 0190 [20200710]
> [   42.282195]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> [   42.288169] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug       0190
> PQ: 0 ANSI: 7
> [   42.292122] sd 2:0:0:0: Attached scsi generic sg0 type 0
> [   42.292244] sd 2:0:0:0: Power-on or device reset occurred
> [   42.302288] sd 2:0:0:0: [sda] Spinning up disk...
> 
> Then we wait...
> 
> [   44.308213] ...................ready
> [   62.748919] sd 2:0:0:0: [sda] 16384 512-byte logical blocks: (8.39 MB/8.00
> MiB)
> [   62.754265] sd 2:0:0:0: [sda] Write Protect is off
> [   62.763253] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled,
> supports DPO and FUA
> [   62.776965] sd 2:0:0:0: [sda] Optimal transfer size 524288 bytes
> [   62.883817] sd 2:0:0:0: [sda] Attached SCSI disk
> 
> And then rmmod still fails.
> 

Just to explain a bit more about tur_ms_to_ready, that does not effect SCSI
commands like REPORT LUNS, INQUIRY and REQUEST SENSE, but does slow down all
"media access" commands including TEST UNIT READY (TUR) and READ CAPACITY. So
if you watch what is happening with 'lsscsi -s' the device (LUN) will appear
almost immediately but its size will be "-" due to the fact that READ
CAPACITY (or TUR before it) is waiting for tur_ms_to_ready to elapse. After
that the size (for disks) will be shown by 'lsscsi -s'.

When you say 'rmmod still fails' do you mean it refuses to remove the module
because the device is busy? It is busy, where is the race?. What precisely
would you like to happen? What does a real SCSI HBA do?

Is there any way that a driver can detect that rmmod has been called and
rejected? If not, we could add  a "shutdown" writable attribute in
/sys/bus/pseudo/drivers/scsi_debug/ . Then if a large number of pseudo
devices is being built due to the modprobe invocation, the driver can go
into reverse by checking that attribute before it adds another host
(target or LUN?). After shutdown, the driver is still active, just with
no hosts, and thus no LUNs. A more accurate name would be rm_all_hosts .

Doug Gilbert

Comment 13 Luis Chamberlain 2021-05-04 21:18:22 UTC

(In reply to d gilbert from comment #12)
> On 2021-03-22 12:23 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> > https://bugzilla.kernel.org/show_bug.cgi?id=212337
> > 
> > --- Comment #9 from Luis Chamberlain (mcgrof@kernel.org) ---
> > (In reply to d gilbert from comment #8)
> > 
> >>>> The scsi_debug module option that is already in place is:
> >>>>      tur_ms_to_ready: TEST UNIT READY millisecs before initial good
> status
> >>>> (def=0)
> >>
> >> You asked how it works, try:
> >>       modprobe scsi_debug tur_ms_to_ready=20000
> >>
> > 
> > That does not resolve the rmmod race against insmod:
> > 
> > scsi host2: scsi_debug: version 0190 [20200710]
> > [   42.213400]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> > [   42.217527] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug      
> 0190
> > PQ: 0 ANSI: 7
> > [   42.223346] scsi 2:0:0:0: Attached scsi generic sg0 type 0
> > [   42.282195] scsi host2: scsi_debug: version 0190 [20200710]
> > [   42.282195]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> > [   42.288169] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug      
> 0190
> > PQ: 0 ANSI: 7
> > [   42.292122] sd 2:0:0:0: Attached scsi generic sg0 type 0
> > [   42.292244] sd 2:0:0:0: Power-on or device reset occurred
> > [   42.302288] sd 2:0:0:0: [sda] Spinning up disk...
> > 
> > Then we wait...
> > 
> > [   44.308213] ...................ready
> > [   62.748919] sd 2:0:0:0: [sda] 16384 512-byte logical blocks: (8.39
> MB/8.00
> > MiB)
> > [   62.754265] sd 2:0:0:0: [sda] Write Protect is off
> > [   62.763253] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled,
> > supports DPO and FUA
> > [   62.776965] sd 2:0:0:0: [sda] Optimal transfer size 524288 bytes
> > [   62.883817] sd 2:0:0:0: [sda] Attached SCSI disk
> > 
> > And then rmmod still fails.
> > 
> 
> Just to explain a bit more about tur_ms_to_ready, that does not effect SCSI
> commands like REPORT LUNS, INQUIRY and REQUEST SENSE, but does slow down all
> "media access" commands including TEST UNIT READY (TUR) and READ CAPACITY. So
> if you watch what is happening with 'lsscsi -s' the device (LUN) will appear
> almost immediately but its size will be "-" due to the fact that READ
> CAPACITY (or TUR before it) is waiting for tur_ms_to_ready to elapse. After
> that the size (for disks) will be shown by 'lsscsi -s'.
> 
> 
> When you say 'rmmod still fails' do you mean it refuses to remove the module
> because the device is busy?

Yes. The refcnt must be 1 for rmmod to work. If it is not it will fail.

> If is busy, where is the race?. What precisely
> would you like to happen? What does a real SCSI HBA do?

That's the thing, the trace on comment #1 does not exactly show who to blame, but there seems to be only two possibilities: systemd and multipath. Regardless what is clearer is that once the device is exposed we *cannot* block userspace from poking at the device. The best we can do, is udevadm settle, however that still does not guarantee userspace things like multipath won't try to poke.
 
> Is there any way that a driver can detect that rmmod has been called and
> rejected?

Yes! try_module_get() would fail if rmmod was kicked off.

> If not, we could add  a "shutdown" writable attribute in
> /sys/bus/pseudo/drivers/scsi_debug/ . Then if a large number of pseudo
> devices is being built due to the modprobe invocation, the driver can go
> into reverse by checking that attribute before it adds another host
> (target or LUN?). After shutdown, the driver is still active, just with
> no hosts, and thus no LUNs. A more accurate name would be rm_all_hosts .

This may work actually, and so new users who would want to avoid this race would have to issue this call prior to rmmod. That would remove the possibility of a race. Let me know if you have a patch I can test. Putting this as re-opened.

Comment 14 Luis Chamberlain 2021-05-04 21:22:51 UTC

(In reply to d gilbert from comment #8)
> On 2021-03-18 3:14 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> > https://bugzilla.kernel.org/show_bug.cgi?id=212337
> > 
> > --- Comment #4 from Luis Chamberlain (mcgrof@kernel.org) ---
> > I'm afraid scsi_debug is filled with bug bombs bound to happen, because it
> > was
> > written without certain consideration of races now coming up as tangible
> with
> > syfs / driver load. Namely, if you hold a lock at init and also use it on
> > sysfs
> > attributes you can easily deadlock. I discovered this issue first with the
> > zram
> > driver, and fixed the issue with try_module_get()'s on each driver sysfs
> > attribute, I posted patches for that, for discussion on that see the post
> [0]
> > [1], although discussion is mostly on the first patch, the patch you want
> to
> > look at is the second one [1].
> > 
> > [0] https://lkml.kernel.org/r/20210306022035.11266-2-mcgrof@kernel.org
> > [1] https://lkml.kernel.org/r/20210306022035.11266-3-mcgrof@kernel.org
> > 
> > I considered fixing scsi_debug in light of this, but given that module
> > initialization is *also* calling helpers used by syfs attributes, *and*
> this
> > is
> > also true at module removal, I'm afraid much more care is needed here. In
> my
> > patch to zram for the sysfs issue I mention ways to trigger the deadlock,
> if
> > you're up for the task to fix that, it would be wonderful. But hey, these
> are
> > separate issues. just figured you should be aware.
> 
> In the hack proposed above, not much would appear in sysfs until that thread
> finished adding at least adding its first host by which time
> scsi_debug_init()
> should have long since finished.

The sysfs races are a bit more complex than what I think is being conveyed. I will Cc you on some fixes for zram which demo what the issues are, which are generic, which I also think we need to fix in this driver. There would be two issues:

 * the syfs deadlock
 * races against the private data which is type specific

Comment 15 d gilbert 2021-05-05 16:06:40 UTC

On 2021-05-04 5:18 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=212337
> 
> Luis Chamberlain (mcgrof@kernel.org) changed:
> 
>             What    |Removed                     |Added
> ----------------------------------------------------------------------------
>               Status|RESOLVED                    |REOPENED
>           Resolution|WILL_NOT_FIX                |---
> 
> --- Comment #13 from Luis Chamberlain (mcgrof@kernel.org) ---
> (In reply to d gilbert from comment #12)
>> On 2021-03-22 12:23 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
>>> https://bugzilla.kernel.org/show_bug.cgi?id=212337
>>>
>>> --- Comment #9 from Luis Chamberlain (mcgrof@kernel.org) ---
>>> (In reply to d gilbert from comment #8)
>>>
>>>>>> The scsi_debug module option that is already in place is:
>>>>>>       tur_ms_to_ready: TEST UNIT READY millisecs before initial good
>> status
>>>>>> (def=0)
>>>>
>>>> You asked how it works, try:
>>>>        modprobe scsi_debug tur_ms_to_ready=20000
>>>>
>>>
>>> That does not resolve the rmmod race against insmod:
>>>
>>> scsi host2: scsi_debug: version 0190 [20200710]
>>> [   42.213400]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
>>> [   42.217527] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug
>> 0190
>>> PQ: 0 ANSI: 7
>>> [   42.223346] scsi 2:0:0:0: Attached scsi generic sg0 type 0
>>> [   42.282195] scsi host2: scsi_debug: version 0190 [20200710]
>>> [   42.282195]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
>>> [   42.288169] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug
>> 0190
>>> PQ: 0 ANSI: 7
>>> [   42.292122] sd 2:0:0:0: Attached scsi generic sg0 type 0
>>> [   42.292244] sd 2:0:0:0: Power-on or device reset occurred
>>> [   42.302288] sd 2:0:0:0: [sda] Spinning up disk...
>>>
>>> Then we wait...
>>>
>>> [   44.308213] ...................ready
>>> [   62.748919] sd 2:0:0:0: [sda] 16384 512-byte logical blocks: (8.39
>> MB/8.00
>>> MiB)
>>> [   62.754265] sd 2:0:0:0: [sda] Write Protect is off
>>> [   62.763253] sd 2:0:0:0: [sda] Write cache: enabled, read cache: enabled,
>>> supports DPO and FUA
>>> [   62.776965] sd 2:0:0:0: [sda] Optimal transfer size 524288 bytes
>>> [   62.883817] sd 2:0:0:0: [sda] Attached SCSI disk
>>>
>>> And then rmmod still fails.
>>>
>>
>> Just to explain a bit more about tur_ms_to_ready, that does not effect SCSI
>> commands like REPORT LUNS, INQUIRY and REQUEST SENSE, but does slow down all
>> "media access" commands including TEST UNIT READY (TUR) and READ CAPACITY.
>> So
>> if you watch what is happening with 'lsscsi -s' the device (LUN) will appear
>> almost immediately but its size will be "-" due to the fact that READ
>> CAPACITY (or TUR before it) is waiting for tur_ms_to_ready to elapse. After
>> that the size (for disks) will be shown by 'lsscsi -s'.
>>
>>
>> When you say 'rmmod still fails' do you mean it refuses to remove the module
>> because the device is busy?
> 
> Yes. The refcnt must be 1 for rmmod to work. If it is not it will fail.
> 
>> If is busy, where is the race?. What precisely
>> would you like to happen? What does a real SCSI HBA do?
> 
> That's the thing, the trace on comment #1 does not exactly show who to blame,
> but there seems to be only two possibilities: systemd and multipath.
> Regardless
> what is clearer is that once the device is exposed we *cannot* block
> userspace
> from poking at the device. The best we can do, is udevadm settle, however
> that
> still does not guarantee userspace things like multipath won't try to poke.
> 
>> Is there any way that a driver can detect that rmmod has been called and
>> rejected?
> 
> Yes! try_module_get() would fail if rmmod was kicked off.

I have tried this:
     if (!try_module_get(THIS_MODULE)) {
          pr_warn("%s: probable rmmod, stop adding\n", __func__);
          break;
     }
     module_put(THIS_MODULE);
     ....

placed inside the loop that adds each host inside scsi_debug_init() and
I can never get try_modules_get() to fail. There is a 'rmmod scsi_debug'
bash script sending a rmmod every 0.3 seconds. To slow scsi_debug down
there is a 0.5 second delay on each media access command. The overall
modprobe takes over 10 seconds but scsi_debug_init() is only about 0.8
seconds of that. The rest of the time is udev and friends piling on,
sending SCSI commands to the newly appearing devices. And whenever the
driver is processing commands then rmmod is going to get EBUSY which is
exactly what is observed.

The kernel try_module_get() documentation is underwhelming. Is there some
kind of synchronization between this call and rmmod? Does a failed rmmod
leave a persistent flag that a following try_module_get() will notice and
return false? If so, what if the user changes their mind? If not, how is
this meant to be useful?

>> If not, we could add  a "shutdown" writable attribute in
>> /sys/bus/pseudo/drivers/scsi_debug/ . Then if a large number of pseudo
>> devices is being built due to the modprobe invocation, the driver can go
>> into reverse by checking that attribute before it adds another host
>> (target or LUN?). After shutdown, the driver is still active, just with
>> no hosts, and thus no LUNs. A more accurate name would be rm_all_hosts .
> 
> This may work actually, and so new users who would want to avoid this race
> would have to issue this call prior to rmmod. That would remove the
> possibility
> of a race. Let me know if you have a patch I can test. Putting this as
> re-opened.

This will depend on how quickly sysfs visibility appears (i.e.
/sys/bus/pseudo/drivers/scsi_debug/* ) after modprobe is started.

Doug Gilbert

Comment 16 Luis Chamberlain 2021-05-07 18:25:17 UTC

(In reply to d gilbert from comment #15)
> On 2021-05-04 5:18 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> > https://bugzilla.kernel.org/show_bug.cgi?id=212337
> > 
> > Luis Chamberlain (mcgrof@kernel.org) changed:
> > 
> >             What    |Removed                     |Added
> >
> ----------------------------------------------------------------------------
> >               Status|RESOLVED                    |REOPENED
> >           Resolution|WILL_NOT_FIX                |---
> > 
> > --- Comment #13 from Luis Chamberlain (mcgrof@kernel.org) ---
> > (In reply to d gilbert from comment #12)
> >> On 2021-03-22 12:23 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> >>> https://bugzilla.kernel.org/show_bug.cgi?id=212337
> >>>
> >>> --- Comment #9 from Luis Chamberlain (mcgrof@kernel.org) ---
> >>> (In reply to d gilbert from comment #8)
> >>>
> >>>>>> The scsi_debug module option that is already in place is:
> >>>>>>       tur_ms_to_ready: TEST UNIT READY millisecs before initial good
> >> status
> >>>>>> (def=0)
> >>>>
> >>>> You asked how it works, try:
> >>>>        modprobe scsi_debug tur_ms_to_ready=20000
> >>>>
> >>>
> >>> That does not resolve the rmmod race against insmod:
> >>>
> >>> scsi host2: scsi_debug: version 0190 [20200710]
> >>> [   42.213400]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> >>> [   42.217527] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug
> >> 0190
> >>> PQ: 0 ANSI: 7
> >>> [   42.223346] scsi 2:0:0:0: Attached scsi generic sg0 type 0
> >>> [   42.282195] scsi host2: scsi_debug: version 0190 [20200710]
> >>> [   42.282195]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
> >>> [   42.288169] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug
> >> 0190
> >>> PQ: 0 ANSI: 7
> >>> [   42.292122] sd 2:0:0:0: Attached scsi generic sg0 type 0
> >>> [   42.292244] sd 2:0:0:0: Power-on or device reset occurred
> >>> [   42.302288] sd 2:0:0:0: [sda] Spinning up disk...
> >>>
> >>> Then we wait...
> >>>
> >>> [   44.308213] ...................ready
> >>> [   62.748919] sd 2:0:0:0: [sda] 16384 512-byte logical blocks: (8.39
> >> MB/8.00
> >>> MiB)
> >>> [   62.754265] sd 2:0:0:0: [sda] Write Protect is off
> >>> [   62.763253] sd 2:0:0:0: [sda] Write cache: enabled, read cache:
> enabled,
> >>> supports DPO and FUA
> >>> [   62.776965] sd 2:0:0:0: [sda] Optimal transfer size 524288 bytes
> >>> [   62.883817] sd 2:0:0:0: [sda] Attached SCSI disk
> >>>
> >>> And then rmmod still fails.
> >>>
> >>
> >> Just to explain a bit more about tur_ms_to_ready, that does not effect
> SCSI
> >> commands like REPORT LUNS, INQUIRY and REQUEST SENSE, but does slow down
> all
> >> "media access" commands including TEST UNIT READY (TUR) and READ CAPACITY.
> >> So
> >> if you watch what is happening with 'lsscsi -s' the device (LUN) will
> appear
> >> almost immediately but its size will be "-" due to the fact that READ
> >> CAPACITY (or TUR before it) is waiting for tur_ms_to_ready to elapse.
> After
> >> that the size (for disks) will be shown by 'lsscsi -s'.
> >>
> >>
> >> When you say 'rmmod still fails' do you mean it refuses to remove the
> module
> >> because the device is busy?
> > 
> > Yes. The refcnt must be 1 for rmmod to work. If it is not it will fail.
> > 
> >> If is busy, where is the race?. What precisely
> >> would you like to happen? What does a real SCSI HBA do?
> > 
> > That's the thing, the trace on comment #1 does not exactly show who to
> blame,
> > but there seems to be only two possibilities: systemd and multipath.
> > Regardless
> > what is clearer is that once the device is exposed we *cannot* block
> > userspace
> > from poking at the device. The best we can do, is udevadm settle, however
> > that
> > still does not guarantee userspace things like multipath won't try to poke.
> > 
> >> Is there any way that a driver can detect that rmmod has been called and
> >> rejected?
> > 
> > Yes! try_module_get() would fail if rmmod was kicked off.
> 
> I have tried this:
>      if (!try_module_get(THIS_MODULE)) {
>           pr_warn("%s: probable rmmod, stop adding\n", __func__);
>           break;
>      }
>      module_put(THIS_MODULE);
>      ....
> 
> placed inside the loop that adds each host inside scsi_debug_init() and
> I can never get try_modules_get() to fail.

You won't race init stuff with rmmod, the issue comes up *after* the device is up, once init completes.

> There is a 'rmmod scsi_debug'
> bash script sending a rmmod every 0.3 seconds. To slow scsi_debug down
> there is a 0.5 second delay on each media access command. The overall
> modprobe takes over 10 seconds but scsi_debug_init() is only about 0.8
> seconds of that. The rest of the time is udev and friends piling on,
> sending SCSI commands to the newly appearing devices. And whenever the
> driver is processing commands then rmmod is going to get EBUSY which is
> exactly what is observed.

Right, try installing multipath too, which is a a busy nosy neighbor who just loves too poke at devices when they pop up as well.

> The kernel try_module_get() documentation is underwhelming. Is there some
> kind of synchronization between this call and rmmod? 

No, the piece of information you are likely missing is that rmmod does a sanity check in userspace on the refcnt before trying to call the system call to try to remove the module. That refcnt is what userspace modprobe is bailing on.

A refcnt is always held on init, and so rmmod cannot possibly done on init. The races we are observing is not something on init and rmmod... its *after* init, and then rmmod not being able to complete. Why? Because we allow for it.

> Does a failed rmmod
> leave a persistent flag that a following try_module_get() will notice and
> return false?

No. try_module_get() is best effort, in the sense that if the module is not being removed yet, and it succeeds in getting a reference, rmmod will be prevented from removing the module unput we put the module later. If try_module_get() failed, we can safely assume the module is gone out fishing.

> If so, what if the user changes their mind? If not, how is
> this meant to be useful?

The idea here is to call a busy syfs file which will not return until all devices are removed *and* it also locks the driver to not allow any new entries, therefore making the driver useful for new additions. That requires adding a small state machine. The reason I am thinking this would be needed, is that as in the patches with zram you'll see there are possible races also with module removal and sysfs files. So if we really want to *quiesce* this driver, for removal, we need to ensure that no new sysfs entries will busy out while rmmod is going on.

> >> If not, we could add  a "shutdown" writable attribute in
> >> /sys/bus/pseudo/drivers/scsi_debug/ . Then if a large number of pseudo
> >> devices is being built due to the modprobe invocation, the driver can go
> >> into reverse by checking that attribute before it adds another host
> >> (target or LUN?). After shutdown, the driver is still active, just with
> >> no hosts, and thus no LUNs. A more accurate name would be rm_all_hosts .
> > 
> > This may work actually, and so new users who would want to avoid this race
> > would have to issue this call prior to rmmod. That would remove the
> > possibility
> > of a race. Let me know if you have a patch I can test. Putting this as
> > re-opened.
> 
> This will depend on how quickly sysfs visibility appears (i.e.
> /sys/bus/pseudo/drivers/scsi_debug/* ) after modprobe is started.

It should appear right away if we attach sysfs stuff prior to the devices which probe asynchronously.

Comment 17 d gilbert 2021-05-07 20:46:07 UTC

On 2021-05-07 2:25 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=212337
> 
> --- Comment #16 from Luis Chamberlain (mcgrof@kernel.org) ---
> (In reply to d gilbert from comment #15)
>> On 2021-05-04 5:18 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
>>> https://bugzilla.kernel.org/show_bug.cgi?id=212337
>>>
>>> Luis Chamberlain (mcgrof@kernel.org) changed:
>>>
>>>              What    |Removed                     |Added
>>>
>> ----------------------------------------------------------------------------
>>>                Status|RESOLVED                    |REOPENED
>>>            Resolution|WILL_NOT_FIX                |---
>>>
>>> --- Comment #13 from Luis Chamberlain (mcgrof@kernel.org) ---
>>> (In reply to d gilbert from comment #12)
>>>> On 2021-03-22 12:23 p.m., bugzilla-daemon@bugzilla.kernel.org wrote:
>>>>> https://bugzilla.kernel.org/show_bug.cgi?id=212337
>>>>>
>>>>> --- Comment #9 from Luis Chamberlain (mcgrof@kernel.org) ---
>>>>> (In reply to d gilbert from comment #8)
>>>>>
>>>>>>>> The scsi_debug module option that is already in place is:
>>>>>>>>        tur_ms_to_ready: TEST UNIT READY millisecs before initial good
>>>> status
>>>>>>>> (def=0)
>>>>>>
>>>>>> You asked how it works, try:
>>>>>>         modprobe scsi_debug tur_ms_to_ready=20000
>>>>>>
>>>>>
>>>>> That does not resolve the rmmod race against insmod:
>>>>>
>>>>> scsi host2: scsi_debug: version 0190 [20200710]
>>>>> [   42.213400]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
>>>>> [   42.217527] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug
>>>> 0190
>>>>> PQ: 0 ANSI: 7
>>>>> [   42.223346] scsi 2:0:0:0: Attached scsi generic sg0 type 0
>>>>> [   42.282195] scsi host2: scsi_debug: version 0190 [20200710]
>>>>> [   42.282195]   dev_size_mb=8, opts=0x0, submit_queues=1, statistics=0
>>>>> [   42.288169] scsi 2:0:0:0: Direct-Access     Linux    scsi_debug
>>>> 0190
>>>>> PQ: 0 ANSI: 7
>>>>> [   42.292122] sd 2:0:0:0: Attached scsi generic sg0 type 0
>>>>> [   42.292244] sd 2:0:0:0: Power-on or device reset occurred
>>>>> [   42.302288] sd 2:0:0:0: [sda] Spinning up disk...
>>>>>
>>>>> Then we wait...
>>>>>
>>>>> [   44.308213] ...................ready
>>>>> [   62.748919] sd 2:0:0:0: [sda] 16384 512-byte logical blocks: (8.39
>>>> MB/8.00
>>>>> MiB)
>>>>> [   62.754265] sd 2:0:0:0: [sda] Write Protect is off
>>>>> [   62.763253] sd 2:0:0:0: [sda] Write cache: enabled, read cache:
>> enabled,
>>>>> supports DPO and FUA
>>>>> [   62.776965] sd 2:0:0:0: [sda] Optimal transfer size 524288 bytes
>>>>> [   62.883817] sd 2:0:0:0: [sda] Attached SCSI disk
>>>>>
>>>>> And then rmmod still fails.
>>>>>
>>>>
>>>> Just to explain a bit more about tur_ms_to_ready, that does not effect
>> SCSI
>>>> commands like REPORT LUNS, INQUIRY and REQUEST SENSE, but does slow down
>> all
>>>> "media access" commands including TEST UNIT READY (TUR) and READ CAPACITY.
>>>> So
>>>> if you watch what is happening with 'lsscsi -s' the device (LUN) will
>> appear
>>>> almost immediately but its size will be "-" due to the fact that READ
>>>> CAPACITY (or TUR before it) is waiting for tur_ms_to_ready to elapse.
>> After
>>>> that the size (for disks) will be shown by 'lsscsi -s'.
>>>>
>>>>
>>>> When you say 'rmmod still fails' do you mean it refuses to remove the
>> module
>>>> because the device is busy?
>>>
>>> Yes. The refcnt must be 1 for rmmod to work. If it is not it will fail.
>>>
>>>> If is busy, where is the race?. What precisely
>>>> would you like to happen? What does a real SCSI HBA do?
>>>
>>> That's the thing, the trace on comment #1 does not exactly show who to
>> blame,
>>> but there seems to be only two possibilities: systemd and multipath.
>>> Regardless
>>> what is clearer is that once the device is exposed we *cannot* block
>>> userspace
>>> from poking at the device. The best we can do, is udevadm settle, however
>>> that
>>> still does not guarantee userspace things like multipath won't try to poke.
>>>
>>>> Is there any way that a driver can detect that rmmod has been called and
>>>> rejected?
>>>
>>> Yes! try_module_get() would fail if rmmod was kicked off.
>>
>> I have tried this:
>>       if (!try_module_get(THIS_MODULE)) {
>>            pr_warn("%s: probable rmmod, stop adding\n", __func__);
>>            break;
>>       }
>>       module_put(THIS_MODULE);
>>       ....
>>
>> placed inside the loop that adds each host inside scsi_debug_init() and
>> I can never get try_modules_get() to fail.
> 
> You won't race init stuff with rmmod, the issue comes up *after* the device
> is
> up, once init completes.
> 
>> There is a 'rmmod scsi_debug'
>> bash script sending a rmmod every 0.3 seconds. To slow scsi_debug down
>> there is a 0.5 second delay on each media access command. The overall
>> modprobe takes over 10 seconds but scsi_debug_init() is only about 0.8
>> seconds of that. The rest of the time is udev and friends piling on,
>> sending SCSI commands to the newly appearing devices. And whenever the
>> driver is processing commands then rmmod is going to get EBUSY which is
>> exactly what is observed.
> 
> Right, try installing multipath too, which is a a busy nosy neighbor who just
> loves too poke at devices when they pop up as well.

I'm working on the rm_all_hosts parameter angle which lets me get in "under"
modprobe, as well as after scsi_debug_init() finishes ... lots of races :-)

If I can solve all of those, the reported problem may disappear.

>> The kernel try_module_get() documentation is underwhelming. Is there some
>> kind of synchronization between this call and rmmod?
> 
> No, the piece of information you are likely missing is that rmmod does a
> sanity
> check in userspace on the refcnt before trying to call the system call to try
> to remove the module. That refcnt is what userspace modprobe is bailing on.
> 
> A refcnt is always held on init, and so rmmod cannot possibly done on init.
> The
> races we are observing is not something on init and rmmod... its *after*
> init,
> and then rmmod not being able to complete. Why? Because we allow for it.
> 
>> Does a failed rmmod
>> leave a persistent flag that a following try_module_get() will notice and
>> return false?
> 
> No. try_module_get() is best effort, in the sense that if the module is not
> being removed yet, and it succeeds in getting a reference, rmmod will be
> prevented from removing the module unput we put the module later. If
> try_module_get() failed, we can safely assume the module is gone out fishing.
> 
>> If so, what if the user changes their mind? If not, how is
>> this meant to be useful?
> 
> The idea here is to call a busy syfs file which will not return until all
> devices are removed *and* it also locks the driver to not allow any new
> entries, therefore making the driver useful for new additions. That requires
> adding a small state machine. The reason I am thinking this would be needed,
> is
> that as in the patches with zram you'll see there are possible races also
> with
> module removal and sysfs files. So if we really want to *quiesce* this
> driver,
> for removal, we need to ensure that no new sysfs entries will busy out while
> rmmod is going on.

The scsi_debug driver, being a low level driver (LLD) doesn't have that sort
of overview. It just sees a thundering heard of SCSI commands (e.g. REPORT LUNS,
INQUIRY, TEST UNIT READY, then READ CAPACITY) followed by READs. It doesn't
know or care where they come from or what they are associated with.

After rm_all_hosts gets set, no further hosts are added, new commands get
rejected with DID_NO_CONNECT and queued commands have their timers cancelled
(if they are using a timer) and DID_NO_CONNECT is sent back to the mid-level
via their 'done' callback.

>>>> If not, we could add  a "shutdown" writable attribute in
>>>> /sys/bus/pseudo/drivers/scsi_debug/ . Then if a large number of pseudo
>>>> devices is being built due to the modprobe invocation, the driver can go
>>>> into reverse by checking that attribute before it adds another host
>>>> (target or LUN?). After shutdown, the driver is still active, just with
>>>> no hosts, and thus no LUNs. A more accurate name would be rm_all_hosts .
>>>
>>> This may work actually, and so new users who would want to avoid this race
>>> would have to issue this call prior to rmmod. That would remove the
>>> possibility
>>> of a race. Let me know if you have a patch I can test. Putting this as
>>> re-opened.
>>
>> This will depend on how quickly sysfs visibility appears (i.e.
>> /sys/bus/pseudo/drivers/scsi_debug/* ) after modprobe is started.
> 
> It should appear right away if we attach sysfs stuff prior to the devices
> which
> probe asynchronously.
> 

Yes, it does appear pretty early, with my script firing every 0.3 second
( 'echo 1 > rm_all_hosts') my modprobe scsi_debug creating 3 hosts gets
reliably hit after it has set up 1 of the 3 hosts.

After the system settles (with no hosts available) I want:
    echo 0 > rm_all_hosts
to recreate the host set up that would have been in place after an
un-interrupted modprobe (with the same parameters).


There is another curious thing that I am seeing when hosts are recreated:
the new devices (disks) have sg nodes but no sd nodes. That is with
lk 5.12.0-rc1 (MKP's 5.13/scsi-queue branch). The sd node resolution seems
to stop after a Power-on or device reset occurred UA. I notice that the sd
driver doesn't accept 0x29,0x1 which is "Power on occurred" in the same way.

I refer the sd maintainer to sam6r07.pdf section 5.14:

Each logical unit shall establish a unit attention condition when an I_T
nexus is established that has not been previously established. The
additional sense code shall be set to:
     a) POWER ON, RESET, OR BUS DEVICE RESET OCCURRED;
     b) DEVICE INTERNAL RESET; or
     c) POWER ON OCCURRED.


I was thinking of changing the scsi_debug driver to give 'c)' in the newly
created device case and 'a)' in the reset case(s).

Doug Gilbert

Comment 18 Luis Chamberlain 2021-05-07 22:37:36 UTC

(In reply to d gilbert from comment #17)
> > It should appear right away if we attach sysfs stuff prior to the devices
> > which probe asynchronously.
> > 
> 
> Yes, it does appear pretty early, 

I thought scsi_debug had generic sysfs files to control adding new scsi devices at run time or removing them, or controlling the scsi_debug driver generically, but correct me if I'm wrong, I don't see them. If so then my statement was incorrect in that "should" is an assumption.

All the sysfs knobs I'm seeing are per scsi device, not generic. And so I take it back. Since scsi probes asynchronously its by chance they appear by the time modprobe completes.

Comment 19 Luis Chamberlain 2021-05-07 22:46:22 UTC

(In reply to d gilbert from comment #17)
> I'm working on the rm_all_hosts parameter angle which lets me get in "under"
> modprobe, as well as after scsi_debug_init() finishes ... lots of races :-)

OK so this would be a new generic sysfs knob, ie, independent of scsi devices it creates? So created and attached synchronously at init.
 
> If I can solve all of those, the reported problem may disappear.

If the solution includes a state machine to prevent *future* additions, *or* it uses try_module_get() before allowing any new possible generic knobs (not sure if you are going to add some) I agree that this should work.

FWIW, just one minor consideration, just recall that distributions are now using scsi_debug to do tons of testing both on fstests and blktests... So... they'd benefit from fixing these races as a backport with the least amount of changes as possible, and so if a fix is possible with the least amount of lines possible they can backport this fix so that tests don't run into so many false positives with tests.

Comment 20 Luis Chamberlain 2021-07-27 19:27:22 UTC

I've narrowed down that using this patch:

http://lkml.kernel.org/r/20210508230745.27923-1-dgilbert@interlog.com

helps on older kernels. In particular, at least with kernel v5.3 one can eventually run into a situation where the recnt can be see in /sys/module/scsi_debug/refcnt as 0 and yet rmmod can fail.

This is not possible with linux-next.

Comment 21 Luis Chamberlain 2021-07-30 20:31:05 UTC

(In reply to Luis Chamberlain from comment #20)
> one can
> eventually run into a situation where the recnt can be see in
> /sys/module/scsi_debug/refcnt as 0 and yet rmmod can fail.
> 
> This is not possible with linux-next.

This is false, the failure rate is just lower with linux-next, I see it around 1/1642 tries. I'll work on a reproducer but that is a separate issue, a generic module issue which I'll address.

Comment 22 Luis Chamberlain 2021-08-10 05:19:20 UTC

(In reply to Luis Chamberlain from comment #21)
> (In reply to Luis Chamberlain from comment #20)
> > one can
> > eventually run into a situation where the recnt can be see in
> > /sys/module/scsi_debug/refcnt as 0 and yet rmmod can fail.
> > 
> > This is not possible with linux-next.
> 
> This is false, the failure rate is just lower with linux-next, I see it
> around 1/1642 tries. I'll work on a reproducer but that is a separate issue,
> a generic module issue which I'll address.

I am tracking those failures and proposed fixes on korg#214015

[0] https://bugzilla.kernel.org/show_bug.cgi?id=214015

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