Re: [PATCH v2 2/2] scsi: sd: Rework asynchronous resume support

[Geert Uytterhoeven <geert@linux-m68k.org>]

Hi Bart,

CC linux-ide

On Fri, Jul 22, 2022 at 7:56 PM Bart Van Assche <bvanassche@acm.org> wrote:
> On 7/22/22 01:53, Geert Uytterhoeven wrote:
> > During s2idle, the following trace data is generated:
> >
> >     kworker/u16:9-325     [000] ...2.   230.478731: block_rq_issue: 8,0
> > N 0 () 0 + 0 [kworker/u16:9]
> >     kworker/u16:9-325     [000] ...2.   230.478745:
> > scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=0
> > prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0
> > cmnd=(SYNCHRONIZE_CACHE - raw=35 00 00 00 00 00 00 00 00 00)
> >            <idle>-0       [007] d.h3.   230.478832:
> > scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=0
> > prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=0
> > cmnd=(SYNCHRONIZE_CACHE - raw=35 00 00 00 00 00 00 00 00 00)
> > result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE
> > status=SAM_STAT_GOOD)
> >            <idle>-0       [000] ..s2.   230.478851: block_rq_complete:
> > 8,0 N () 18446744073709551615 + 0 [0]
> >     kworker/u16:9-325     [000] ...2.   230.483134: block_rq_issue: 8,0
> > N 0 () 0 + 0 [kworker/u16:9]
> >     kworker/u16:9-325     [000] ...2.   230.483136:
> > scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 data_sgl=0
> > prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1
> > cmnd=(START_STOP - raw=1b 00 00 00 00 00)
> >            <idle>-0       [007] d.h3.   230.624530:
> > scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 data_sgl=0
> > prot_sgl=0 prot_op=SCSI_PROT_NORMAL driver_tag=0 scheduler_tag=1
> > cmnd=(START_STOP - raw=1b 00 00 00 00 00) result=(driver=DRIVER_OK
> > host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)
> >            <idle>-0       [000] d.s4.   230.624634: scsi_eh_wakeup: host_no=0
> >            <idle>-0       [000] ..s2.   230.624642: block_rq_complete:
> > 8,0 N () 18446744073709551615 + 0 [0]
> >    kworker/u16:14-1027    [007] d..3.   231.393642: scsi_eh_wakeup: host_no=0
> >
> > When reading from hard drive after s2idle, no more trace data
> > is generated.
>
> I think the above commands come from the suspend sequence. '1b 00 00 00
> 00 00' stops a block device. The lowest bit in byte 4 needs to be set to
> start a block device.
>
> Something that is not yet clear is whether or not sd_submit_start()
> hangs during the resume process. How about verifying whether or not
> sd_submit_start() hangs by either issuing SysRq-t or by adding pr_info()
> statements in that function?

sd_submit_start() is called once during suspend, and once during
resume.  It does not hang.

Reading from /dev/sda hangs after resume (not in sd_submit_start(),
which is never called for reading).

Two tasks are blocked in blk_mq_get_tag() calling io_schedule():

task:kworker/7:1     state:D stack:    0 pid:  122 ppid:     2 flags:0x00000008
Workqueue: events ata_scsi_dev_rescan
Call trace:
 __switch_to+0xbc/0x124
 __schedule+0x540/0x71c
 schedule+0x58/0xa0
 io_schedule+0x18/0x34
 blk_mq_get_tag+0x138/0x244
 __blk_mq_alloc_requests+0x130/0x2f0
 blk_mq_alloc_request+0x74/0xa8
 scsi_alloc_request+0x10/0x30
 __scsi_execute+0x5c/0x18c
 scsi_vpd_inquiry+0x7c/0xdc
 scsi_get_vpd_size+0x34/0xa8
 scsi_get_vpd_buf+0x28/0xf4
 scsi_attach_vpd+0x44/0x170
 scsi_rescan_device+0x30/0x98
 ata_scsi_dev_rescan+0xc8/0xfc
 process_one_work+0x2e0/0x474
 worker_thread+0x1cc/0x270
 kthread+0xd8/0xe8
 ret_from_fork+0x10/0x20


task:hd              state:D stack:    0 pid: 1163 ppid:  1076 flags:0x00000000
Call trace:
 __switch_to+0xbc/0x124
 __schedule+0x540/0x71c
 schedule+0x58/0xa0
 io_schedule+0x18/0x34
 blk_mq_get_tag+0x138/0x244
 __blk_mq_alloc_requests+0x130/0x2f0
 blk_mq_submit_bio+0x44c/0x5b4
 __submit_bio+0x24/0x5c
 submit_bio_noacct_nocheck+0x8c/0x178
 submit_bio_noacct+0x380/0x3b0
 submit_bio+0x34/0x3c
 mpage_bio_submit+0x28/0x38
 mpage_readahead+0xa8/0x178
 blkdev_readahead+0x14/0x1c
 read_pages+0x4c/0x158
 page_cache_ra_unbounded+0xd8/0x174
 do_page_cache_ra+0x40/0x4c
 page_cache_ra_order+0x14/0x1c
 ondemand_readahead+0x124/0x2fc
 page_cache_sync_ra+0x50/0x54
 filemap_read+0x130/0x6e8
 blkdev_read_iter+0xf0/0x164
 new_sync_read+0x74/0xc0
 vfs_read+0xbc/0xd8
 ksys_read+0x6c/0xd4
 __arm64_sys_read+0x14/0x1c
 invoke_syscall+0x70/0xf4
 el0_svc_common.constprop.0+0xbc/0xf0
 do_el0_svc+0x18/0x20
 el0_svc+0x30/0x84
 el0t_64_sync_handler+0x90/0xf8
 el0t_64_sync+0x14c/0x150

I hope this helps.
Thanks!

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds