Re: Erase race?

[Artem Bityutskiy <dedekind1@gmail.com>]

On Tue, 2010-05-11 at 22:30 -0400, Jon Ringle wrote:
> On Tue, Apr 27, 2010 at 8:59 AM, Artem Bityutskiy <dedekind1@gmail.com> wrote:
> > On Tue, 2010-04-20 at 16:24 -0400, Jon Ringle wrote:
> >> On Tue, Apr 13, 2010 at 4:15 PM, Jon Ringle <jon@ringle.org> wrote:
> >> > Hi,
> >> > I have a few machines that have UBI and UBIFS on NOR flash that are
> >> > undergoing continuous reboot testing.
> >> > One of them just caught the following failure:
> >> >
> >> > [   51.250000] IXP4XX-Flash.0: buffer write error (status 0xd0)
> >> > [   51.250000] UBI error: ubi_io_write: error -22 while writing 64
> >> > bytes to PEB 226:0, written 0 bytes
> >> > [   51.270000] UBI error: erase_worker: failed to erase PEB 226, error -22
> >> > [   51.270000] UBI warning: ubi_ro_mode: switch to read-only mode
> >> > [   51.290000] UBI error: do_work: work failed with error code -22
> >> > [   51.290000] UBI error: ubi_thread: ubi_bgt0d: work failed with error code -22
> >> >
> >> > Looking at this it appears that the failure might have been caused due
> >> > to the erase_worker and ubi_io_write occurring out of order... since
> >> > it looks like ubi_io_write was trying to write at offset 0 of the PEB,
> >> > which I imagine would have to be the EC header, which should happen
> >> > after the block is erased. But it doesn't seem to be the case here.
> >>
> >> I had this issue occur again on another system:
> >> [   48.250000] IXP4XX-Flash.0: buffer write error (status 0xd0)
> >> [   48.250000] UBI error: ubi_io_write: error -22 while writing 64
> >> bytes to PEB 111:0, written 0 bytes
> >> [   48.280000] UBI error: erase_worker: failed to erase PEB 111, error -22
> >> [   48.280000] UBI warning: ubi_ro_mode: switch to read-only mode
> >> [   48.310000] UBI error: do_work: work failed with error code -22
> >> [   48.310000] UBI error: ubi_thread: ubi_bgt0d: work failed with error code -22
> >>
> >> Can anyone comment as to my theory that this is a race condition
> >> between ubi_io_write and erase_worker occurring out of order?
> >
> > Did you debug this further? Any new findings?
> 
> I finally got a capture of this with CONFIG_MTD_UBI_DEBUG turned on:
> 
> [   61.710000] IXP4XX-Flash.0: buffer write error (status 0xd0)
> [   61.710000] UBI error: ubi_io_write: error -22 while writing 64
> bytes to PEB 136:0, written 0 bytes
> [   61.740000] [<c011a240>] (unwind_backtrace+0x0/0x170) from
> [<bf0157a8>] (ubi_io_write+0x1ec/0x214 [ubi])
> [   61.770000] [<bf0157a8>] (ubi_io_write+0x1ec/0x214 [ubi]) from
> [<bf01599c>] (ubi_io_write_vid_hdr+0x1cc/0x20c [ubi])
> [   61.800000] [<bf01599c>] (ubi_io_write_vid_hdr+0x1cc/0x20c [ubi])
> from [<bf016c50>] (sync_erase+0xd4/0x128 [ubi])
> [   61.830000] [<bf016c50>] (sync_erase+0xd4/0x128 [ubi]) from
> [<bf017344>] (erase_worker+0x28/0x2d8 [ubi])
> [   61.860000] [<bf017344>] (erase_worker+0x28/0x2d8 [ubi]) from
> [<bf0180e4>] (do_work+0x98/0x13c [ubi])
> [   61.860000] [<bf0180e4>] (do_work+0x98/0x13c [ubi]) from
> [<bf01824c>] (ubi_thread+0xc4/0x158 [ubi])
> [   61.890000] [<bf01824c>] (ubi_thread+0xc4/0x158 [ubi]) from
> [<c0142b84>] (kthread+0x7c/0x84)
> [   61.890000] [<c0142b84>] (kthread+0x7c/0x84) from [<c0115378>]
> (kernel_thread_exit+0x0/0x8)
> [   61.920000] UBI error: erase_worker: failed to erase PEB 136, error -22
> [   61.920000] UBI warning: ubi_ro_mode: switch to read-only mode
> [   61.950000] UBI error: do_work: work failed with error code -22
> [   61.950000] UBI error: ubi_thread: ubi_bgt0d: work failed with error code -22

So it is probably not a kind of race you assumed before. Your flash for
some reasons encounters an error, dunno why.

-- 
Best Regards,
Artem Bityutskiy (Артём Битюцкий)