Erase race?

Erase race?

[Jon Ringle]

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.

Jon

Re: Erase race?

[Jon Ringle]

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?

Thanks
Jon

Re: Erase race?

[Jamie Lokier]

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?

I have nothing to offer, but I'm interested in anything more you
discover as I would like to use UBIFS on NOR too.

-- Jamie

Re: Erase race?

[Artem Bityutskiy]

On Tue, 2010-04-13 at 16:15 -0400, Jon Ringle 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'm out of office and have a long queue of unanswered mails, so please,
do not wait for help from me soon, and just debug this.

The erase_worker function writes the EC header after the eraseblock is
erased. IOW, I think erase_worker calls ubi_io_write, which fails with
-EINVAL for some reasons, and you see these prints. So this does not
look like a race, at least not an UBI race. If you had UBI debugging
enabled (which is a good idea), you'd have few more info and a stackdump
printed.

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

Re: Erase race?

[Artem Bityutskiy]

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?

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

Re: Erase race?

[Jon Ringle]

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


>
> --
> Best Regards,
> Artem Bityutskiy (Артём Битюцкий)
>
>
> ______________________________________________________
> Linux MTD discussion mailing list
> http://lists.infradead.org/mailman/listinfo/linux-mtd/
>

Re: Erase race?

[Artem Bityutskiy]

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 (Артём Битюцкий)

Re: Erase race?

[massimo cirillo]

Hi Jon,
I verified some particular error conditions regarding
the erase suspend in some nor flash chip.
Please tell me the part number of the flash you
are using and I will check it.

Max

2010/5/12 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 (Артём Битюцкий)
>
>
> ______________________________________________________
> Linux MTD discussion mailing list
> http://lists.infradead.org/mailman/listinfo/linux-mtd/
>

Re: Erase race?

[Jon Ringle]

On Wed, May 12, 2010 at 4:21 AM, massimo cirillo <maxcir@gmail.com> wrote:
> Hi Jon,
> I verified some particular error conditions regarding
> the erase suspend in some nor flash chip.
> Please tell me the part number of the flash you
> are using and I will check it.

Thanks. The boards that showed this failure have Intel JS28F256P30T95.
However, we are planning on switching to Numonyx JS28F256P30TF due to
upcoming obsolescence of the Intel part.

Jon

Re: Erase race?

[massimo cirillo]

Have you any evidence of erase suspend occurrence ?
Could you try to disable erase suspend from cfi_cmdset_0001.c ?
To this end, uncomment
#define CMDSET0001_DISABLE_ERASE_SUSPEND_ON_WRITE
#define CMDSET0001_DISABLE_WRITE_SUSPEND
(they must be defined) at the beginning of the file and repeat
your test.
Bye

2010/5/12 Jon Ringle <jon@ringle.org>:
> On Wed, May 12, 2010 at 4:21 AM, massimo cirillo <maxcir@gmail.com> wrote:
>> Hi Jon,
>> I verified some particular error conditions regarding
>> the erase suspend in some nor flash chip.
>> Please tell me the part number of the flash you
>> are using and I will check it.
>
> Thanks. The boards that showed this failure have Intel JS28F256P30T95.
> However, we are planning on switching to Numonyx JS28F256P30TF due to
> upcoming obsolescence of the Intel part.
>
> Jon
>

Re: Erase race?

[Jon Ringle]

On Wed, May 12, 2010 at 8:31 AM, massimo cirillo <maxcir@gmail.com> wrote:
> Have you any evidence of erase suspend occurrence ?
How do I know if erase suspend occurs?

> Could you try to disable erase suspend from cfi_cmdset_0001.c ?
> To this end, uncomment
> #define CMDSET0001_DISABLE_ERASE_SUSPEND_ON_WRITE
> #define CMDSET0001_DISABLE_WRITE_SUSPEND
> (they must be defined) at the beginning of the file and repeat
> your test.

Thanks. I will try this, however, since the problem is infrequent and
I don't know how to make the problem happen more reliably, it will
take some time to verify that this fixes the issue.

Jon