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

[Sean Nyekjaer]

On Mon, Oct 04, 2021 at 01:47:00PM +0200, Boris Brezillon wrote:
> 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.

Have you seen the reproducer script?
---
root@iwg26-v1:/data/root# cat /data/crash.sh
#!/bin/sh -x

echo enabled > /sys/devices/platform/soc/2100000.bus/21f4000.serial/tty/ttymxc4/power/wakeup

rm /data/test50M
dd if=/dev/urandom of=/tmp/test50M bs=1M count=50
cp /tmp/test50M /data/ &
sleep 1
echo mem > /sys/power/state
---

As seen in the log above disk is synced before suspend.
cp is continuing to copy data to ubifs.
And then user space processes are frozen.
At this point the kernel thread would have unwritten data.

We tried to solve this with:
https://lkml.org/lkml/2021/9/1/280

/Sean