Re: ufshcd_queuecommand() triggering after ufshcd_suspend()?
On Sun, Jan 13, 2019 at 7:25 PM Zang Leigang wrote: > I think there are two different issues: > > 1. clk_gating's state(including state's trace event) and is_suspended is not > wrapped by ufshcd_is_clkgating_allowed which Hisilicon's kirin platoform > soc does not need but is set and checked in a regular path. > 2. I think SCSI is necessary to block queue to stop sending to ufs after > system suspend or, add a new state for ufs like UFSHCD_STATE_SUSPENDING > or what else. hba->is_sys_suspended is too late to stop > ufshcd_queuecommand > Hey Zang, Thanks for the suggestions. I'm not sure I have enough context to try to come up with a patch. I'll try to take a stab at it, but I'd appreciate it if you have any more specific suggestions or patches for me to try. :) thanks -john
Re: ufshcd_queuecommand() triggering after ufshcd_suspend()?
Hey all, I think there are two different issues: 1. clk_gating's state(including state's trace event) and is_suspended is not wrapped by ufshcd_is_clkgating_allowed which Hisilicon's kirin platoform soc does not need but is set and checked in a regular path. 2. I think SCSI is necessary to block queue to stop sending to ufs after system suspend or, add a new state for ufs like UFSHCD_STATE_SUSPENDING or what else. hba->is_sys_suspended is too late to stop ufshcd_queuecommand On Fri, Jan 11, 2019 at 06:39:56AM +, Avri Altman wrote: > +Zang > > Thanks, > Avri > > > > > From: John Stultz > Sent: Friday, January 11, 2019 1:02:21 AM > To: Sahitya Tummala; Christoph Hellwig; Wei Li; Martin K. Petersen > Cc: Evan Green; Avri Altman; Vijay Viswanath; lkml; linux-s...@vger.kernel.org > Subject: ufshcd_queuecommand() triggering after ufshcd_suspend()? > > Hey all, > Frequently, since support for the HiKey960's UFS code landed in > 4.19, I've noticed the following warning on reboot: > > [ 23.086860] WARNING: CPU: 0 PID: 2507 at > drivers/scsi/ufs/ufshcd.c:2460 ufshcd_queuecommand+0x59c/0x5a8 > [ 23.096256] Modules linked in: > [ 23.099313] CPU: 0 PID: 2507 Comm: kworker/0:1H Tainted: G S > 5.0.0-rc1-00068-g3f81a19 #273 > [ 23.108873] Hardware name: HiKey960 (DT) > [ 23.112802] Workqueue: kblockd blk_mq_requeue_work > [ 23.117591] pstate: 8045 (Nzcv daif +PAN -UAO) > [ 23.122378] pc : ufshcd_queuecommand+0x59c/0x5a8 > [ 23.126990] lr : ufshcd_queuecommand+0x58c/0x5a8 > [ 23.131600] sp : ff8015e1ba80 > [ 23.134907] x29: ff8015e1ba80 x28: ffc217f94048 > [ 23.140214] x27: 0010 x26: ffc217a7c8b8 > [ 23.145520] x25: ffc217a7c000 x24: ffc217a7ceb0 > [ 23.150827] x23: x22: ffc217a7c808 > [ 23.156133] x21: ffc217f94120 x20: 0010 > [ 23.161440] x19: ff801186d000 x18: ff801186db08 > [ 23.166746] x17: x16: > [ 23.172053] x15: ff8095e1b7c7 x14: 692064616574736e > [ 23.177360] x13: 6928204e4f5f534b x12: 4c43203d21206574 > [ 23.182666] x11: 6174732e676e6974 x10: 61675f6b6c633e2d > [ 23.187973] x9 : 61626820646e616d x8 : 6d6f636575657571 > [ 23.193280] x7 : x6 : ff801186e000 > [ 23.198586] x5 : ff801186e270 x4 : ff8010096dc0 > [ 23.203894] x3 : 0001 x2 : 47dd99afde511d00 > [ 23.209201] x1 : x0 : > [ 23.214509] Call trace: > [ 23.216952] ufshcd_queuecommand+0x59c/0x5a8 > [ 23.221220] scsi_queue_rq+0x5b4/0x880 > [ 23.224964] blk_mq_dispatch_rq_list+0xb0/0x510 > [ 23.229492] blk_mq_sched_dispatch_requests+0xf4/0x198 > [ 23.234626] __blk_mq_run_hw_queue+0xb4/0x120 > [ 23.238978] __blk_mq_delay_run_hw_queue+0x110/0x200 > [ 23.243937] blk_mq_run_hw_queue+0xb8/0x118 > [ 23.248114] blk_mq_run_hw_queues+0x58/0x78 > [ 23.252291] blk_mq_requeue_work+0x140/0x168 > [ 23.256560] process_one_work+0x158/0x468 > [ 23.260564] worker_thread+0x50/0x460 > [ 23.264222] kthread+0x104/0x130 > [ 23.267447] ret_from_fork+0x10/0x1c > [ 23.271017] ---[ end trace 45f1ee04059cdf00 ]--- > > Since the warning is triggering from the WARN_ON(hba->clk_gating.state > != CLKS_ON) line, I annotated the clk_gating.state changes, and am > seeing on reboot: > vdc: Waited 0ms for vold > sd 0:0:0:3: [sdd] Synchronizing SCSI cache > sd 0:0:0:2: [sdc] Synchronizing SCSI cache > sd 0:0:0:1: [sdb] Synchronizing SCSI cache > sd 0:0:0:0: [sda] Synchronizing SCSI cache > ufshcd_suspend: setting clk_gating.state CLKS_OFF > ufshcd_queuecommand hba->clk_gating.state != CLKS_ON (instead its 0) > > > So it seems like ufshcd_suspend() is has run, but then the workqueue > (occasionally) fires afterwards triggering the issue. > > Maybe should something in ufshcd_queuecommand be checking the > clk_gating.is_suspended flag before proceeding? > > Other ideas? The logic all seems to be in the generic code, but I'm > not sure if maybe the ufs-hisi.c code is mis-managing something? > > thanks > -john -- Thanks, Zang Leigang
Re: ufshcd_queuecommand() triggering after ufshcd_suspend()?
+Zang Thanks, Avri From: John Stultz Sent: Friday, January 11, 2019 1:02:21 AM To: Sahitya Tummala; Christoph Hellwig; Wei Li; Martin K. Petersen Cc: Evan Green; Avri Altman; Vijay Viswanath; lkml; linux-s...@vger.kernel.org Subject: ufshcd_queuecommand() triggering after ufshcd_suspend()? Hey all, Frequently, since support for the HiKey960's UFS code landed in 4.19, I've noticed the following warning on reboot: [ 23.086860] WARNING: CPU: 0 PID: 2507 at drivers/scsi/ufs/ufshcd.c:2460 ufshcd_queuecommand+0x59c/0x5a8 [ 23.096256] Modules linked in: [ 23.099313] CPU: 0 PID: 2507 Comm: kworker/0:1H Tainted: G S 5.0.0-rc1-00068-g3f81a19 #273 [ 23.108873] Hardware name: HiKey960 (DT) [ 23.112802] Workqueue: kblockd blk_mq_requeue_work [ 23.117591] pstate: 8045 (Nzcv daif +PAN -UAO) [ 23.122378] pc : ufshcd_queuecommand+0x59c/0x5a8 [ 23.126990] lr : ufshcd_queuecommand+0x58c/0x5a8 [ 23.131600] sp : ff8015e1ba80 [ 23.134907] x29: ff8015e1ba80 x28: ffc217f94048 [ 23.140214] x27: 0010 x26: ffc217a7c8b8 [ 23.145520] x25: ffc217a7c000 x24: ffc217a7ceb0 [ 23.150827] x23: x22: ffc217a7c808 [ 23.156133] x21: ffc217f94120 x20: 0010 [ 23.161440] x19: ff801186d000 x18: ff801186db08 [ 23.166746] x17: x16: [ 23.172053] x15: ff8095e1b7c7 x14: 692064616574736e [ 23.177360] x13: 6928204e4f5f534b x12: 4c43203d21206574 [ 23.182666] x11: 6174732e676e6974 x10: 61675f6b6c633e2d [ 23.187973] x9 : 61626820646e616d x8 : 6d6f636575657571 [ 23.193280] x7 : x6 : ff801186e000 [ 23.198586] x5 : ff801186e270 x4 : ff8010096dc0 [ 23.203894] x3 : 0001 x2 : 47dd99afde511d00 [ 23.209201] x1 : x0 : [ 23.214509] Call trace: [ 23.216952] ufshcd_queuecommand+0x59c/0x5a8 [ 23.221220] scsi_queue_rq+0x5b4/0x880 [ 23.224964] blk_mq_dispatch_rq_list+0xb0/0x510 [ 23.229492] blk_mq_sched_dispatch_requests+0xf4/0x198 [ 23.234626] __blk_mq_run_hw_queue+0xb4/0x120 [ 23.238978] __blk_mq_delay_run_hw_queue+0x110/0x200 [ 23.243937] blk_mq_run_hw_queue+0xb8/0x118 [ 23.248114] blk_mq_run_hw_queues+0x58/0x78 [ 23.252291] blk_mq_requeue_work+0x140/0x168 [ 23.256560] process_one_work+0x158/0x468 [ 23.260564] worker_thread+0x50/0x460 [ 23.264222] kthread+0x104/0x130 [ 23.267447] ret_from_fork+0x10/0x1c [ 23.271017] ---[ end trace 45f1ee04059cdf00 ]--- Since the warning is triggering from the WARN_ON(hba->clk_gating.state != CLKS_ON) line, I annotated the clk_gating.state changes, and am seeing on reboot: vdc: Waited 0ms for vold sd 0:0:0:3: [sdd] Synchronizing SCSI cache sd 0:0:0:2: [sdc] Synchronizing SCSI cache sd 0:0:0:1: [sdb] Synchronizing SCSI cache sd 0:0:0:0: [sda] Synchronizing SCSI cache ufshcd_suspend: setting clk_gating.state CLKS_OFF ufshcd_queuecommand hba->clk_gating.state != CLKS_ON (instead its 0) So it seems like ufshcd_suspend() is has run, but then the workqueue (occasionally) fires afterwards triggering the issue. Maybe should something in ufshcd_queuecommand be checking the clk_gating.is_suspended flag before proceeding? Other ideas? The logic all seems to be in the generic code, but I'm not sure if maybe the ufs-hisi.c code is mis-managing something? thanks -john
ufshcd_queuecommand() triggering after ufshcd_suspend()?
Hey all, Frequently, since support for the HiKey960's UFS code landed in 4.19, I've noticed the following warning on reboot: [ 23.086860] WARNING: CPU: 0 PID: 2507 at drivers/scsi/ufs/ufshcd.c:2460 ufshcd_queuecommand+0x59c/0x5a8 [ 23.096256] Modules linked in: [ 23.099313] CPU: 0 PID: 2507 Comm: kworker/0:1H Tainted: G S 5.0.0-rc1-00068-g3f81a19 #273 [ 23.108873] Hardware name: HiKey960 (DT) [ 23.112802] Workqueue: kblockd blk_mq_requeue_work [ 23.117591] pstate: 8045 (Nzcv daif +PAN -UAO) [ 23.122378] pc : ufshcd_queuecommand+0x59c/0x5a8 [ 23.126990] lr : ufshcd_queuecommand+0x58c/0x5a8 [ 23.131600] sp : ff8015e1ba80 [ 23.134907] x29: ff8015e1ba80 x28: ffc217f94048 [ 23.140214] x27: 0010 x26: ffc217a7c8b8 [ 23.145520] x25: ffc217a7c000 x24: ffc217a7ceb0 [ 23.150827] x23: x22: ffc217a7c808 [ 23.156133] x21: ffc217f94120 x20: 0010 [ 23.161440] x19: ff801186d000 x18: ff801186db08 [ 23.166746] x17: x16: [ 23.172053] x15: ff8095e1b7c7 x14: 692064616574736e [ 23.177360] x13: 6928204e4f5f534b x12: 4c43203d21206574 [ 23.182666] x11: 6174732e676e6974 x10: 61675f6b6c633e2d [ 23.187973] x9 : 61626820646e616d x8 : 6d6f636575657571 [ 23.193280] x7 : x6 : ff801186e000 [ 23.198586] x5 : ff801186e270 x4 : ff8010096dc0 [ 23.203894] x3 : 0001 x2 : 47dd99afde511d00 [ 23.209201] x1 : x0 : [ 23.214509] Call trace: [ 23.216952] ufshcd_queuecommand+0x59c/0x5a8 [ 23.221220] scsi_queue_rq+0x5b4/0x880 [ 23.224964] blk_mq_dispatch_rq_list+0xb0/0x510 [ 23.229492] blk_mq_sched_dispatch_requests+0xf4/0x198 [ 23.234626] __blk_mq_run_hw_queue+0xb4/0x120 [ 23.238978] __blk_mq_delay_run_hw_queue+0x110/0x200 [ 23.243937] blk_mq_run_hw_queue+0xb8/0x118 [ 23.248114] blk_mq_run_hw_queues+0x58/0x78 [ 23.252291] blk_mq_requeue_work+0x140/0x168 [ 23.256560] process_one_work+0x158/0x468 [ 23.260564] worker_thread+0x50/0x460 [ 23.264222] kthread+0x104/0x130 [ 23.267447] ret_from_fork+0x10/0x1c [ 23.271017] ---[ end trace 45f1ee04059cdf00 ]--- Since the warning is triggering from the WARN_ON(hba->clk_gating.state != CLKS_ON) line, I annotated the clk_gating.state changes, and am seeing on reboot: vdc: Waited 0ms for vold sd 0:0:0:3: [sdd] Synchronizing SCSI cache sd 0:0:0:2: [sdc] Synchronizing SCSI cache sd 0:0:0:1: [sdb] Synchronizing SCSI cache sd 0:0:0:0: [sda] Synchronizing SCSI cache ufshcd_suspend: setting clk_gating.state CLKS_OFF ufshcd_queuecommand hba->clk_gating.state != CLKS_ON (instead its 0) So it seems like ufshcd_suspend() is has run, but then the workqueue (occasionally) fires afterwards triggering the issue. Maybe should something in ufshcd_queuecommand be checking the clk_gating.is_suspended flag before proceeding? Other ideas? The logic all seems to be in the generic code, but I'm not sure if maybe the ufs-hisi.c code is mis-managing something? thanks -john