Re: [RFC PATCH] mtd: rawnand: use mutex to protect access while in suspend

[Boris Brezillon]

On Mon, 4 Oct 2021 12:12:46 +0200
Sean Nyekjaer <sean@xxxxxxxxxx> wrote:

> On Mon, Oct 04, 2021 at 11:58:17AM +0200, Boris Brezillon wrote:
> > On Mon, 4 Oct 2021 10:55:09 +0200
> > Sean Nyekjaer <sean@xxxxxxxxxx> wrote:
> >   
> > > On Mon, Oct 04, 2021 at 10:41:47AM +0200, Boris Brezillon wrote:  
> > > > On Mon,  4 Oct 2021 08:56:09 +0200
> > > > Sean Nyekjaer <sean@xxxxxxxxxx> wrote:
> > > >     
> > > > > This will prevent nand_get_device() from returning -EBUSY.
> > > > > It will force mtd_write()/mtd_read() to wait for the nand_resume() to unlock
> > > > > access to the mtd device.
> > > > > 
> > > > > Then we avoid -EBUSY is returned to ubifsi via mtd_write()/mtd_read(),
> > > > > that will in turn hard error on every error returened.
> > > > > We have seen during ubifs tries to call mtd_write before the mtd device
> > > > > is resumed.    
> > > > 
> > > > I think the problem is here. Why would UBIFS/UBI try to write something
> > > > to a device that's not resumed yet (or has been suspended already, if
> > > > you hit this in the suspend path).
> > > >     
> > > > > 
> > > > > Exec_op[0] speed things up, so we see this race when the device is
> > > > > resuming. But it's actually "mtd: rawnand: Simplify the locking" that
> > > > > allows it to return -EBUSY, before that commit it would have waited for
> > > > > the mtd device to resume.    
> > > > 
> > > > Uh, wait. If nand_resume() was called before any writes/reads this
> > > > wouldn't happen. IMHO, the problem is not that we return -EBUSY without
> > > > blocking, the problem is that someone issues a write/read before calling
> > > > mtd_resume().
> > > >     
> > > 
> > > The commit msg from "mtd: rawnand: Simplify the locking" states this clearly.
> > > 
> > > """
> > > Last important change to mention: we now return -EBUSY when someone
> > > tries to access a device that as been suspended, and propagate this
> > > error to the upper layer.
> > > """
> > > 
> > > IMHO "mtd: rawnand: Simplify the locking" should never had been merged
> > > before the upper layers was fixed to handle -EBUSY. ;)
> > > Which they still not are...  
> > 
> > That's not really the problem here. Upper layers should never get
> > -EBUSY in the first place if the MTD device was resumed before the UBI
> > device. Looks like we have a missing UBI -> MTD parenting link, which
> > would explain why things don't get resumed in the right order. Can you
> > try with the following diff applied?
> > 
> > ---
> > diff --git a/drivers/mtd/ubi/build.c b/drivers/mtd/ubi/build.c
> > index f399edc82191..1981ce8f3a26 100644
> > --- a/drivers/mtd/ubi/build.c
> > +++ b/drivers/mtd/ubi/build.c
> > @@ -905,6 +905,7 @@ int ubi_attach_mtd_dev(struct mtd_info *mtd, int
> > ubi_num, ubi->dev.release = dev_release;
> >         ubi->dev.class = &ubi_class;
> >         ubi->dev.groups = ubi_dev_groups;
> > +       ubi->dev.parent = &mtd->dev;
> >  
> >         ubi->mtd = mtd;
> >         ubi->ubi_num = ubi_num;
> >   
> 
> No change:
> [   71.739193] Filesystems sync: 34.212 seconds
> [   71.755044] Freezing user space processes ... (elapsed 0.004 seconds) done.
> [   71.767289] OOM killer disabled.
> [   71.770552] Freezing remaining freezable tasks ... (elapsed 0.004 seconds) done.
> [   71.782182] printk: Suspending console(s) (use no_console_suspend to debug)
> [   71.824391] nand_suspend
> [   71.825177] gpmi_pm_suspend
> [   71.825676] PM: suspend devices took 0.040 seconds
> [   71.825971] nand_write_oob - nand_get_device() returned -EBUSY
> [   71.825985] ubi0 error: ubi_io_write: error -16 while writing 4096 bytes to PEB 986:65536, written 0 bytes
> [   71.826029] CPU: 0 PID: 7 Comm: kworker/u2:0 Not tainted 5.15.0-rc3-dirty #43
> [   71.826043] Hardware name: Freescale i.MX6 Ultralite (Device Tree)
> [   71.826054] Workqueue: writeback wb_workfn (flush-ubifs_0_8)
> [   71.826094] [<c010da84>] (unwind_backtrace) from [<c010a1b4>] (show_stack+0x10/0x14)
> [   71.826122] [<c010a1b4>] (show_stack) from [<c0989c30>] (dump_stack_lvl+0x40/0x4c)
> [   71.826151] [<c0989c30>] (dump_stack_lvl) from [<c05ed690>] (ubi_io_write+0x510/0x6b0)
> [   71.826178] [<c05ed690>] (ubi_io_write) from [<c05ea2f0>] (ubi_eba_write_leb+0xd0/0x968)
> [   71.826204] [<c05ea2f0>] (ubi_eba_write_leb) from [<c05e8754>] (ubi_leb_write+0xd0/0xe8)
> [   71.826232] [<c05e8754>] (ubi_leb_write) from [<c03d67bc>] (ubifs_leb_write+0x68/0x104)
> [   71.826263] [<c03d67bc>] (ubifs_leb_write) from [<c03d79e8>] (ubifs_wbuf_write_nolock+0x28c/0x74c)
> [   71.826291] [<c03d79e8>] (ubifs_wbuf_write_nolock) from [<c03ca18c>] (ubifs_jnl_write_data+0x1b8/0x2b4)
> [   71.826319] [<c03ca18c>] (ubifs_jnl_write_data) from [<c03cd184>] (do_writepage+0x190/0x284)
> [   71.826342] [<c03cd184>] (do_writepage) from [<c023083c>] (__writepage+0x14/0x68)
> [   71.826367] [<c023083c>] (__writepage) from [<c0231748>] (write_cache_pages+0x1c8/0x3f0)
> [   71.826390] [<c0231748>] (write_cache_pages) from [<c0233854>] (do_writepages+0xcc/0x1f4)
> [   71.826413] [<c0233854>] (do_writepages) from [<c02d03dc>] (__writeback_single_inode+0x2c/0x1b4)
> [   71.826440] [<c02d03dc>] (__writeback_single_inode) from [<c02d0a64>] (writeback_sb_inodes+0x200/0x470)
> [   71.826466] [<c02d0a64>] (writeback_sb_inodes) from [<c02d0d10>] (__writeback_inodes_wb+0x3c/0xf4)
> [   71.826493] [<c02d0d10>] (__writeback_inodes_wb) from [<c02d0f58>] (wb_writeback+0x190/0x1f0)
> [   71.826520] [<c02d0f58>] (wb_writeback) from [<c02d21d8>] (wb_workfn+0x2c0/0x3d4)
> [   71.826545] [<c02d21d8>] (wb_workfn) from [<c013ac04>] (process_one_work+0x1e0/0x440)
> [   71.826574] [<c013ac04>] (process_one_work) from [<c013aeac>] (worker_thread+0x48/0x594)
> [   71.826600] [<c013aeac>] (worker_thread) from [<c0142364>] (kthread+0x134/0x15c)
> [   71.826625] [<c0142364>] (kthread) from [<c0100150>] (ret_from_fork+0x14/0x24)

I'm not entirely sure, but given the timing, it looks like this
actually happens in the suspend path, not it the resume path. What I
don't get is why we still have a kernel thread running at that point.

> 
> [...]
> 
> [   71.921673] gpmi_pm_resume
> [   71.923319] nand_resume
> [   71.936120] PM: resume devices took 0.100 seconds
> [   72.314551] ci_hdrc ci_hdrc.0: freeing queued request
> [   72.521656] IPv6: ADDRCONF(NETDEV_CHANGE): usb0: link becomes ready
> [   75.006404] OOM killer enabled.
> [   75.009562] Restarting tasks ...
> [   75.074123] done.
> [   75.095540] PM: suspend exit
> 
> With the RFC PATCH:
> [ 3702.682122] Filesystems sync: 33.416 seconds
> [ 3702.695350] Freezing user space processes ... (elapsed 0.001 seconds) done.
> [ 3702.704218] OOM killer disabled.
> [ 3702.707559] Freezing remaining freezable tasks ... (elapsed 0.003 seconds) done.
> [ 3702.718696] printk: Suspending console(s) (use no_console_suspend to debug)
> [ 3702.757660] nand_suspend
> [ 3702.758577] gpmi_pm_suspend
> [ 3702.759072] PM: suspend devices took 0.040 seconds
> [ 3702.761618] Disabling non-boot CPUs ...
> [ 3702.854985] gpmi_pm_resume
> [ 3702.856623] nand_resume
> [ 3702.867796] PM: resume devices took 0.110 seconds
> [ 3702.895019] OOM killer enabled.
> [ 3702.898291] Restarting tasks ... done.
> [ 3702.950723] PM: suspend exit