Numonyx NOR and chip->mutex bug?

Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

Greetings All.

I've been working on a 2.6.35.7-based ARM kernel for the Gumstix VerdexPro-XL6P hardware. (Our software; their hardware.) Previous boards had a Numonyx 256Mbit NOR flash marked 2003. The latest batch has an F in the part number (indicating a change from 130nm to 65nm) and a 2008 copyright. (The part is a 256PF30TF).

With this new part I'm seeing MTD errors that I think I've traced to cfi_cmdset_0001.c that I'd like to ask about.

The error manifests when I write hard to a UBIFS file system on this NOR flash. What I see is a "NOR Flash: buffer write error" and then either "(block locked)" or "(Bad VPP)"

Through a lot of tracing (which I can describe if anyone cares) I've determined that the problem is that while waiting for the write-completion command to finish the part mysteriously goes back into array mode. (The variations in the error message above stem from array data being seen as status bits.)

But how could that happen given the use of the chip->mutex? I think the answer is that the chip->mutex code is broken.

The (non-XIP) wait function inval_cache_and_wait_for_operation() that waits for completion of the buffer program confirm command has several places where it drops and then retakes the chip->mutex. While dropped it does various cache-flush, msleep(), cond_reshed(), and schedule() calls. Exactly which of these it calls depends on the absolute length of the operation underway.

Interestingly, this new FLASH part has a write buffer of 512 words while the previous part was 32 words. Thus the write times (and time outs) have also increased by a similar x16 factor. I think this is why this has not been seen before.

I also think UBI is important in seeing the problem. If I just flash_erase and dd into an MTD partition it works fine. But those programs are single-threaded where improper mutex use won't matter. By contrast, UBI is heavily multi-threaded.

But my confusion is how can dropping that mutex ever be correct? Isn't its purpose to prevent other threads from calling down into the MTD code for the same devices while a lengthy operation is underway? How can it ever be correct to then allow such concurrency in the middle of the operation?

If I comment out all of those unlock/lock calls on chip->mutex in inval_cache_and_wait_for_operation() all the errors vanish. In fact, everything seems to work fine though I'm not doing suspend/resume.

Am I wildly confused in all this? When is dropping the chip->mutex while waiting for lengthy commands needed? Scheduling while holding a spinlock is bad, but we're not dealing with a spinlock but rather a mutex.

Input welcome.

-Mike Cashwell

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> Greetings All.
>
> I've been working on a 2.6.35.7-based ARM kernel for the Gumstix VerdexPro-XL6P hardware. (Our software; their hardware.) Previous boards had a Numonyx 256Mbit NOR flash marked 2003. The latest batch has an F in the part number (indicating a change from 130nm to 65nm) and a 2008 copyright. (The
part is a 256PF30TF).
>
> With this new part I'm seeing MTD errors that I think I've traced to cfi_cmdset_0001.c that I'd like to ask about.
>
> The error manifests when I write hard to a UBIFS file system on this NOR flash. What I see is a "NOR Flash: buffer write error" and then either "(block locked)" or "(Bad VPP)"

I think chip hw error(s). These chips has some strange chip errors so you better check
the errata for your chip. We have seen similar problems with these newer 65Nm Numonyx chips.

>
> Through a lot of tracing (which I can describe if anyone cares) I've determined that the problem is that while waiting for the write-completion command to finish the part mysteriously goes back into array mode. (The variations in the error message above stem from array data being seen as status
bits.)
>
> But how could that happen given the use of the chip->mutex? I think the answer is that the chip->mutex code is broken.
>
> The (non-XIP) wait function inval_cache_and_wait_for_operation() that waits for completion of the buffer program confirm command has several places where it drops and then retakes the chip->mutex. While dropped it does various cache-flush, msleep(), cond_reshed(), and schedule() calls. Exactly
which of these it calls depends on the absolute length of the operation underway.
>
> Interestingly, this new FLASH part has a write buffer of 512 words while the previous part was 32 words. Thus the write times (and time outs) have also increased by a similar x16 factor. I think this is why this has not been seen before.

Should not the write time be about the same? What is the point with a bigger buffer otherwise?

>
> I also think UBI is important in seeing the problem. If I just flash_erase and dd into an MTD partition it works fine. But those programs are single-threaded where improper mutex use won't matter. By contrast, UBI is heavily multi-threaded.
>
> But my confusion is how can dropping that mutex ever be correct? Isn't its purpose to prevent other threads from calling down into the MTD code for the same devices while a lengthy operation is underway? How can it ever be correct to then allow such concurrency in the middle of the operation?
>
> If I comment out all of those unlock/lock calls on chip->mutex in inval_cache_and_wait_for_operation() all the errors vanish. In fact, everything seems to work fine though I'm not doing suspend/resume.
>
> Am I wildly confused in all this? When is dropping the chip->mutex while waiting for lengthy commands needed? Scheduling

When you want to suspend an erase to do a read for example. You don't want be be without
erase suspend, trust me :)

> while holding a spinlock is bad, but we're not dealing with a spinlock but rather a mutex.
>
> Input welcome.

It is unlikely there is a locking problem I think. You only need to lock when testing/changing the
chip->state.

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Jan 25, 2011, at 1:56 PM, Joakim Tjernlund wrote:

> On Jan 25, 2011, at 1:14 PM, Michael Cashwell wrote:
> 
>> With this new part I'm seeing MTD errors that I think I've traced to cfi_cmdset_0001.c that I'd like to ask about.
>> 
>> The error manifests when I write hard to a UBIFS file system on this NOR flash. What I see is a "NOR Flash: buffer write error" and then either "(block locked)" or "(Bad VPP)"
> 
> I think chip hw error(s). These chips has some strange chip errors so you better check the errata for your chip. We have seen similar problems with these newer 65Nm Numonyx chips.

The latest spec update for these is dated Nov 2009. It lists an issue with block lock/unlock (which I've handled separately) but nothing related to buffered programming.

>> Interestingly, this new FLASH part has a write buffer of 512 words while the previous part was 32 words. Thus the write times (and time outs) have also increased by a similar x16 factor. I think this is why this has not been seen before.
> 
> Should not the write time be about the same? What is the point with a bigger buffer otherwise?

It seems the answer is between "the same" and "linear". The 32-word part had a max buffered write time of 880us. The 512-word part's is 4096us. So the timeout increases by 4.65 not 16. That yields faster writes but also the potential for different code paths in inval_cache_and_wait_for_operation().

>> Am I wildly confused in all this? When is dropping the chip->mutex while waiting for lengthy commands needed?
> 
> When you want to suspend an erase to do a read for example. You don't want be be without erase suspend, trust me :)

I believe that. But in that case there's an active command sent to suspend the in-process erase via writing 0xB0 at line 785.

For non-XIP there is no suspension of buffered writes. Yet somehow, in the middle of one, the part goes back to array mode unexpectedly.

>> Input welcome.
> 
> It is unlikely there is a locking problem I think. You only need to lock when testing/changing the chip->state.

Quite possible. This could just be a hardware bug in the chip. But I'm suspicious of that easy answer. We know these parts have longer write times and we know that makes the wait function more likely to schedule than with the older chips.

The fact that the errors stop if I comment out the chip->mutex calls while waiting suggests to me that there's a reentrancy problem. It doesn't mean the locks are wrong or that doing that is a real fix.

I'm going to explore this on Wed. If I find a problem I'll report back.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> On Jan 25, 2011, at 1:56 PM, Joakim Tjernlund wrote:
>
> > On Jan 25, 2011, at 1:14 PM, Michael Cashwell wrote:
> >
> >> With this new part I'm seeing MTD errors that I think I've traced to cfi_cmdset_0001.c that I'd like to ask about.
> >>
> >> The error manifests when I write hard to a UBIFS file system on this NOR flash. What I see is a "NOR Flash: buffer write error" and then either "(block locked)" or "(Bad VPP)"
> >
> > I think chip hw error(s). These chips has some strange chip errors so you better check the errata for your chip. We have seen similar problems with these newer 65Nm Numonyx chips.
>
> The latest spec update for these is dated Nov 2009. It lists an issue with block lock/unlock (which I've handled separately) but nothing related to buffered programming.

Just check that you didn't get some old samples. We did.

>
> >> Interestingly, this new FLASH part has a write buffer of 512 words while the previous part was 32 words. Thus the write times (and time outs) have also increased by a similar x16 factor. I think this is why this has not been seen before.
> >
> > Should not the write time be about the same? What is the point with a bigger buffer otherwise?
>
> It seems the answer is between "the same" and "linear". The 32-word part had a max buffered write time of 880us. The 512-word part's is 4096us. So the timeout increases by 4.65 not 16. That yields faster writes but also the potential for different code paths in inval_cache_and_wait_for_operation
().

Yes

>
> >> Am I wildly confused in all this? When is dropping the chip->mutex while waiting for lengthy commands needed?
> >
> > When you want to suspend an erase to do a read for example. You don't want be be without erase suspend, trust me :)
>
> I believe that. But in that case there's an active command sent to suspend the in-process erase via writing 0xB0 at line 785.
>
> For non-XIP there is no suspension of buffered writes. Yet somehow, in the middle of one, the part goes back to array mode unexpectedly.
>
> >> Input welcome.
> >
> > It is unlikely there is a locking problem I think. You only need to lock when testing/changing the chip->state.
>
> Quite possible. This could just be a hardware bug in the chip. But I'm suspicious of that easy answer. We know these parts have longer write times and we know that makes the wait function more likely to schedule than with the older chips.

Right.

>
> The fact that the errors stop if I comment out the chip->mutex calls while waiting suggests to me that there's a reentrancy problem. It doesn't mean the locks are wrong or that doing that is a real fix.

Oh, I misread earlier. I figured you held the lock for all ops.

>
> I'm going to explore this on Wed. If I find a problem I'll report back.

Yes, seems like a good idea.

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

[-- Attachment #1: Type: text/plain, Size: 3494 bytes --]

On Jan 25, 2011, at 6:09 PM, Joakim Tjernlund wrote:

> On Jan 25, 2011, at 1:14 PM, Michael Cashwell wrote:
> 
>> With this new part I'm seeing MTD errors that I think I've traced to cfi_cmdset_0001.c that I'd like to ask about.
>> 
>> The error manifests when I write hard to a UBIFS file system on this NOR flash. What I see is a "NOR Flash: buffer write error" and then either "(block locked)" or "(Bad VPP)"
> 
> Just check that you didn't get some old samples. We did.

All I know is that the chips are marked with an '08 copyright. (The previous ones are '03.) So we are dealing with old(er) parts in any event. But from what I can tell, this particular part is the current one Numonyx/Micron are selling.

>> The fact that the errors stop if I comment out the chip->mutex calls while waiting [for command completion] suggests to me that there's a reentrancy problem. It doesn't mean the locks are wrong or that doing that is a real fix.
> 
> Oh, I misread earlier. I figured you held the lock for all ops.

In the end I found a failure in the following scenario. A block erase is underway and a request is made to access the chip in order to write data elsewhere. The erase is suspended and the buffered write is performed. When the chip is released after the write operation the code notices the suspended erase and resumes it. But there seems to be a timing issue where the WSM ready bit SR.7 was checked "too soon" following issuing the resume command and it made the code think the erase was complete when it was not.

The normal code paths that *start* erase or program operations have an inherent delay of several µs between writing the command and the first read of the WSM status. This delay is a side effect of a kernel cache invalidate call. But the key issue is that when resuming an erase no such cache invalidation is done as it was already done when the erase originally began.

That difference means there's very little time between the resume command write and the status read. The apparent result is that the WSM is reported "not busy" when in fact the resumption is still being acted upon. The code misinterprets this to mean the resumed erase is complete when it is not and subsequent commands then go fully off the rails as a result.

I cannot find a corresponding timing constraint in the data sheet. By rights, the bus cycle time alone should be enough between the write and read. But in practice, for these parts, it is not. This may be an undocumented erratum for current parts or just an anomaly for this batch. I have no way to tell.

I found the addition of a 20µs delay immediately after the erase resume command avoids the failure. I also tested 10µs and found it to be insufficient. I did not bisect the time further. I have also not explored any similar issue for resumed write operations because it appears that only kernels doing XIP on MTD parts ever do that. I frankly expect the problem would occur then too but I'm not setup to do XIP and don't want to propose changes I cannot test.

I've included the patch that I am using. It also addresses a few other warts and errata I found while debugging this. If these changes are found to have merit after review I'd be happy for them to be included in mainline. Let me know if I can assist in any way.

Stephan, I hope this helps. Since yours is the only report at all similar to mine I'd be very interested in hearing about your progress.

Best regards,
-Mike Cashwell


[-- Attachment #2: linux-2.6.35.7-001-numonyx-errata.patch --]
[-- Type: application/octet-stream, Size: 2326 bytes --]

diff -Nurp linux-2.6.35.7-arm-gum/drivers/mtd/chips/cfi_cmdset_0001.c linux-2.6.35.7-arm-gum-mod/drivers/mtd/chips/cfi_cmdset_0001.c
--- linux-2.6.35.7-arm-gum/drivers/mtd/chips/cfi_cmdset_0001.c	2010-09-28 21:09:08.000000000 -0400
+++ linux-2.6.35.7-arm-gum-mod/drivers/mtd/chips/cfi_cmdset_0001.c	2011-01-27 16:11:27.000000000 -0500
@@ -1004,7 +1004,19 @@ static void put_chip(struct map_info *ma
 		   sending the 0x70 (Read Status) command to an erasing
 		   chip and expecting it to be ignored, that's what we
 		   do. */
+		/* numonyx data sheet clearly says to always reset the status bits
+		   before resuming a suspended erase. not doing so results in
+		   an ambiguous mixture of status bits once the command ends. */
+		map_write(map, CMD(0x50), adr);
 		map_write(map, CMD(0xd0), adr);
+		/* some numonyx P30 parts have an apparent delay after starting or
+		   resuming some commands. this is normally covered by the cache
+		   invalidation done between the command and the start of reading
+		   for the busy status bit to clear. but no such cache invalidation
+		   is done when resuming and this allows the status-reading thread
+		   awakened below to read the status too soon and think its operation
+		   has finished when it fact its resumption is still underway. */
+		udelay(20);
 		map_write(map, CMD(0x70), adr);
 		chip->oldstate = FL_READY;
 		chip->state = FL_ERASING;
# Numonyx Axcell P33/P30 Spec Update - Nov 2009 - document 509003-04
# Erratum #2 - Flexlock Write Timing for stepping A1
@@ -2045,6 +2057,7 @@ static int __xipram do_xxlock_oneblock(s
 {
 	struct cfi_private *cfi = map->fldrv_priv;
 	struct cfi_pri_intelext *extp = cfi->cmdset_priv;
+	int ofs_factor = cfi->interleave * cfi->device_type;
 	int udelay;
 	int ret;
 
@@ -2060,6 +2073,14 @@ static int __xipram do_xxlock_oneblock(s
 	ENABLE_VPP(map);
 	xip_disable(map, chip, adr);
 
+	/* address numonyx errata regarding Flexlock Write Timing.
+	   before doing a 0x60 lock/unlock sequence on a sector
+	   its current lock state needs to be read and the result
+	   discarded. */
+	map_write(map, CMD(0x90), adr+(2*ofs_factor));
+	chip->state = FL_JEDEC_QUERY;
+	(void) cfi_read_query(map, adr+(2*ofs_factor));
+
 	map_write(map, CMD(0x60), adr);
 	if (thunk == DO_XXLOCK_ONEBLOCK_LOCK) {
 		map_write(map, CMD(0x01), adr);

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi Michael

Thank you for the patch. I applied it, but without success.
I still have the simular situation as before:

here my log

ubimkvol /dev/ubi0 -s 6MiB -N test1
[2299][209] do_erase_oneblock start adr=0x00020000 len=0x20000
[2299][209] map_write 0x50 to 0x00020000
[2299][209] map_write 0x20 to 0x00020000
[2299][209] map_write 0xd0 to 0x00020000
[2299][465] map_write 0xb0 to 0x03fe5000
[2307][465] erase suspend 1         adr=0x03fe5000
[2307][465] map_write 0x70 to 0x03fe5000
[2307][465] map_write 0xe8 to 0x03fe5000
[2307][209] map_write 0x70 to 0x00020000
[2307][209] map_write 0x50 to 0x00020000
[2307][209] map_write 0xd0 to 0x00020000
[2307][209] map_write 0x70 to 0x00020000
[2311][209] erase resumed 2b        adr=0x00020000
[2319][209] do_erase_oneblock end   adr=0x00020000 len=0x20000
[2319][465] map_write 0x1ff to 0x03fe5000
[2319][465] map_write 0xc03c0000 to 0x03fe5000
[2319][465] map_write 0xc03c0000 to 0x03fe5002
...
[2327][465] map_write 0xc03c0000 to 0x03fe53fc
[2327][465] map_write 0xc03c0000 to 0x03fe53fe
[2327][465] map_write 0xd0 to 0x03fe5000
[3387][465] map_write 0x50 to 0x03fe5000
[3387][465] map_write 0x70 to 0x03fe5000
[3395][465] 50000000.flash: buffer write error status 0xb0 
adr=0x03fe5400 len=0x0 (0x400)

I will have a look tomorrow.

Best regards
Stefan


Am 02/02/2011 05:20 PM, schrieb Michael Cashwell:
> On Jan 25, 2011, at 6:09 PM, Joakim Tjernlund wrote:
>
>> On Jan 25, 2011, at 1:14 PM, Michael Cashwell wrote:
>>
>>> With this new part I'm seeing MTD errors that I think I've traced to cfi_cmdset_0001.c that I'd like to ask about.
>>>
>>> The error manifests when I write hard to a UBIFS file system on this NOR flash. What I see is a "NOR Flash: buffer write error" and then either "(block locked)" or "(Bad VPP)"
>> Just check that you didn't get some old samples. We did.
> All I know is that the chips are marked with an '08 copyright. (The previous ones are '03.) So we are dealing with old(er) parts in any event. But from what I can tell, this particular part is the current one Numonyx/Micron are selling.
>
>>> The fact that the errors stop if I comment out the chip->mutex calls while waiting [for command completion] suggests to me that there's a reentrancy problem. It doesn't mean the locks are wrong or that doing that is a real fix.
>> Oh, I misread earlier. I figured you held the lock for all ops.
> In the end I found a failure in the following scenario. A block erase is underway and a request is made to access the chip in order to write data elsewhere. The erase is suspended and the buffered write is performed. When the chip is released after the write operation the code notices the suspended erase and resumes it. But there seems to be a timing issue where the WSM ready bit SR.7 was checked "too soon" following issuing the resume command and it made the code think the erase was complete when it was not.
>
> The normal code paths that *start* erase or program operations have an inherent delay of several µs between writing the command and the first read of the WSM status. This delay is a side effect of a kernel cache invalidate call. But the key issue is that when resuming an erase no such cache invalidation is done as it was already done when the erase originally began.
>
> That difference means there's very little time between the resume command write and the status read. The apparent result is that the WSM is reported "not busy" when in fact the resumption is still being acted upon. The code misinterprets this to mean the resumed erase is complete when it is not and subsequent commands then go fully off the rails as a result.
>
> I cannot find a corresponding timing constraint in the data sheet. By rights, the bus cycle time alone should be enough between the write and read. But in practice, for these parts, it is not. This may be an undocumented erratum for current parts or just an anomaly for this batch. I have no way to tell.
>
> I found the addition of a 20µs delay immediately after the erase resume command avoids the failure. I also tested 10µs and found it to be insufficient. I did not bisect the time further. I have also not explored any similar issue for resumed write operations because it appears that only kernels doing XIP on MTD parts ever do that. I frankly expect the problem would occur then too but I'm not setup to do XIP and don't want to propose changes I cannot test.
>
> I've included the patch that I am using. It also addresses a few other warts and errata I found while debugging this. If these changes are found to have merit after review I'd be happy for them to be included in mainline. Let me know if I can assist in any way.
>
> Stephan, I hope this helps. Since yours is the only report at all similar to mine I'd be very interested in hearing about your progress.
>
> Best regards,
> -Mike Cashwell
>

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/02 17:20:46:

> From: Michael Cashwell <mboards@prograde.net>
> To: linux-mtd@lists.infradead.org
> Cc: Joakim Tjernlund <joakim.tjernlund@transmode.se>, Holger brunck <holger.brunck@keymile.com>, Stefan Bigler <stefan.bigler@keymile.com>
> Date: 2011/02/02 17:20
> Subject: Re: Numonyx NOR and chip->mutex bug?
>
> On Jan 25, 2011, at 6:09 PM, Joakim Tjernlund wrote:
>
> > On Jan 25, 2011, at 1:14 PM, Michael Cashwell wrote:
> >
> >> With this new part I'm seeing MTD errors that I think I've traced to cfi_cmdset_0001.c that I'd like to ask about.
> >>
> >> The error manifests when I write hard to a UBIFS file system on this NOR flash. What I see is a "NOR Flash: buffer write error" and then either "(block locked)" or "(Bad VPP)"
> >
> > Just check that you didn't get some old samples. We did.
>
> All I know is that the chips are marked with an '08 copyright. (The previous ones are '03.) So we are dealing with old(er) parts in any event. But from what I can tell, this particular part is the current one Numonyx/Micron are selling.

Don't think this marking has any meaning, In 03 I don't think these chips were available yet. You will have
to check the shipping slip, hopefully the factory that mounted these chips still has it.

>
> >> The fact that the errors stop if I comment out the chip->mutex calls while waiting [for command completion] suggests to me that there's a reentrancy problem. It doesn't mean the locks are wrong or that doing that is a real fix.
> >
> > Oh, I misread earlier. I figured you held the lock for all ops.
>
> In the end I found a failure in the following scenario. A block erase is underway and a request is made to access the chip in order to write data elsewhere. The erase is suspended and the buffered write is performed. When the chip is released after the write operation the code notices the
suspended erase and resumes it. But there seems to be a timing issue where the WSM ready bit SR.7 was checked "too soon" following issuing the resume command and it made the code think the erase was complete when it was not.
>
> The normal code paths that *start* erase or program operations have an inherent delay of several µs between writing the command and the first read of the WSM status. This delay is a side effect of a kernel cache invalidate call. But the key issue is that when resuming an erase no such cache
invalidation is done as it was already done when the erase originally began.
>
> That difference means there's very little time between the resume command write and the status read. The apparent result is that the WSM is reported "not busy" when in fact the resumption is still being acted upon. The code misinterprets this to mean the resumed erase is complete when it is not
and subsequent commands then go fully off the rails as a result.

Please post patches inline, much easier to comment on them.
Here is the relevant part I am interested in:

+++ linux-2.6.35.7-arm-gum-mod/drivers/mtd/chips/cfi_cmdset_0001.c  2011-01-27 16:11:27.000000000 -0500
@@ -1004,7 +1004,19 @@ static void put_chip(struct map_info *ma
      sending the 0x70 (Read Status) command to an erasing
      chip and expecting it to be ignored, that's what we
      do. */
+    /* numonyx data sheet clearly says to always reset the status bits
+     before resuming a suspended erase. not doing so results in
+     an ambiguous mixture of status bits once the command ends. */
+    map_write(map, CMD(0x50), adr);
hmm, I found this:
8.5
Program Resume
The Resume command instructs the device to continue programming, and
automatically clears Status Register bits SR[7,2]. This command can be written to any
address. If error bits are set, the Status Register should be cleared before issuing the
next instruction. RST# must remain deasserted (see Figure 32, “Buffer Program
Flowchart” on page 74).

Which I think disagrees with your statement. How did you arrive to this conclusion?

     map_write(map, CMD(0xd0), adr);
+    /* some numonyx P30 parts have an apparent delay after starting or
+     resuming some commands. this is normally covered by the cache
+     invalidation done between the command and the start of reading
+     for the busy status bit to clear. but no such cache invalidation
+     is done when resuming and this allows the status-reading thread
+     awakened below to read the status too soon and think its operation
+     has finished when it fact its resumption is still underway. */
+    udelay(20);

I don't follow your reasoning here. This Read Status command isn't
saved anywhere so how can the code get confused later on?
Perhaps the chip gets confused by this command?
Have you tried to remove the Read Status command?
What if you move the udelay after the Read Status?

     map_write(map, CMD(0x70), adr);
     chip->oldstate = FL_READY;
     chip->state = FL_ERASING;

>
> I cannot find a corresponding timing constraint in the data sheet. By rights, the bus cycle time alone should be enough between the write and read. But in practice, for these parts, it is not. This may be an undocumented erratum for current parts or just an anomaly for this batch. I have no way to
tell.
>
> I found the addition of a 20µs delay immediately after the erase resume command avoids the failure. I also tested 10µs and found it to be insufficient. I did not bisect the time further. I have also not explored any similar issue for resumed write operations because it appears that only kernels
doing XIP on MTD parts ever do that. I frankly expect the problem would occur then too but I'm not setup to do XIP and don't want to propose changes I cannot test.
>
> I've included the patch that I am using. It also addresses a few other warts and errata I found while debugging this. If these changes are found to have merit after review I'd be happy for them to be included in mainline. Let me know if I can assist in any way.
>
> Stephan, I hope this helps. Since yours is the only report at all similar to mine I'd be very interested in hearing about your progress.
>
> Best regards,
> -Mike Cashwell
>
> [attachment "linux-2.6.35.7-001-numonyx-errata.patch" deleted by Joakim Tjernlund/Transmode]

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 2, 2011, at 3:12 PM, Joakim Tjernlund wrote:

>> That difference means there's very little time between the resume command write and the status read. The apparent result is that the WSM is reported "not busy" when in fact the resumption is still being acted upon. The code misinterprets this to mean the resumed erase is complete when it is not and subsequent commands then go fully off the rails as a result.
> 
> Please post patches inline, much easier to comment on them.

OK. Sorry about that!

> Here is the relevant part I am interested in:
> 
> +++ linux-2.6.35.7-arm-gum-mod/drivers/mtd/chips/cfi_cmdset_0001.c  2011-01-27 16:11:27.000000000 -0500
> @@ -1004,7 +1004,19 @@ static void put_chip(struct map_info *ma
>       sending the 0x70 (Read Status) command to an erasing
>       chip and expecting it to be ignored, that's what we
>       do. */
> +    /* numonyx data sheet clearly says to always reset the status bits
> +     before resuming a suspended erase. not doing so results in
> +     an ambiguous mixture of status bits once the command ends. */
> +    map_write(map, CMD(0x50), adr);
> hmm, I found this:
> 8.5
> Program Resume
> The Resume command instructs the device to continue programming, and
> automatically clears Status Register bits SR[7,2]. This command can be written to any
> address. If error bits are set, the Status Register should be cleared before issuing the
> next instruction. RST# must remain deasserted (see Figure 32, “Buffer Program
> Flowchart” on page 74).
> 
> Which I think disagrees with your statement. How did you arrive to this conclusion?

There are several statements in flight. If you refer here to my claim that we should clear the status register before resuming then it's "If error bits are set, the Status Register should be cleared before issuing the next instruction." I don't see the point in reading the status and doing that clear conditionally. Clearing them when they are already clear is OK.

My point was just that the code is doing a resume and did not clear the error bits as the data sheet said it should.

Note, the SR[7,2] bits its says are cleared by the command are not the error bits we're talking about. 7 and 2 are WSM-ready and erase-complete. The error bits are different ones. Maybe that's the confusion?

>      map_write(map, CMD(0xd0), adr);
> +    /* some numonyx P30 parts have an apparent delay after starting or
> +     resuming some commands. this is normally covered by the cache
> +     invalidation done between the command and the start of reading
> +     for the busy status bit to clear. but no such cache invalidation
> +     is done when resuming and this allows the status-reading thread
> +     awakened below to read the status too soon and think its operation
> +     has finished when it fact its resumption is still underway. */
> +    udelay(20);
> 
> I don't follow your reasoning here. This Read Status command isn't saved anywhere so how can the code get confused later on?

It's not that the read happens here and is saved. It happens in the thread awakened a few lines later. That thread went to sleep while waiting for its WSM operation to complete so it's in a loop reading and testing that. The first thing it does on wake up is read the WSM status.

My point is that in the case of erase-resume there is much less real time between the write of the resume command and the later read of the status register than there is when starting an erase or program operation anew. This is because the latter perform a cache flush that takes time.

My failures were caused by the erase-resume status read "seeing" a non-busy WSM. Adding a 20µs delay before that read (actually after the command write, but it amounts to the same thing) prevents this from happening. By the time awakened "wait-for-completion" code does its first status read it sees the WSM as busy as it should until the erase actually finishes.

The effect of the added delay is to make the erase-resume path's timing similar to the erase and buffer write paths that take more time because of their cache invalidate call. IOW, it explains why only the resume path has a problem when starting new erase or program commands work OK.

> Perhaps the chip gets confused by this command?
> Have you tried to remove the Read Status command?

I wondered about this too. But I recall seeing comments that said some particular Atmel part needed that command following an erase-resume in order to be in the Read-Status state the rest of the code expects. The comments also said that doing that command amounted to a NOP on other hardware, but maybe not. (!!)

It could be that removing that command instead of adding a delay would make mine work but I'm doubtful. If the 0x70 command is messing things up I don't see how adding a delay would avoid it.

> What if you move the udelay after the Read Status?
> 
>      map_write(map, CMD(0x70), adr);
>      chip->oldstate = FL_READY;
>      chip->state = FL_ERASING;

No, I didn't try that. Since the status read has not actually happened yet it didn't occur to me. If my theory is right, doing the delay after the 0x70 would also work since it still separates in real time the command write and status read.

I'm happy to try both of these and report back if you think it would help.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/02 22:19:58:
>
> On Feb 2, 2011, at 3:12 PM, Joakim Tjernlund wrote:
>
> >> That difference means there's very little time between the resume command write and the status read. The apparent result is that the WSM is reported "not busy" when in fact the resumption is still being acted upon. The code misinterprets this to mean the resumed erase is complete when it is not
and subsequent commands then go fully off the rails as a result.
> >
> > Please post patches inline, much easier to comment on them.
>
> OK. Sorry about that!
>
> > Here is the relevant part I am interested in:
> >
> > +++ linux-2.6.35.7-arm-gum-mod/drivers/mtd/chips/cfi_cmdset_0001.c  2011-01-27 16:11:27.000000000 -0500
> > @@ -1004,7 +1004,19 @@ static void put_chip(struct map_info *ma
> >       sending the 0x70 (Read Status) command to an erasing
> >       chip and expecting it to be ignored, that's what we
> >       do. */
> > +    /* numonyx data sheet clearly says to always reset the status bits
> > +     before resuming a suspended erase. not doing so results in
> > +     an ambiguous mixture of status bits once the command ends. */
> > +    map_write(map, CMD(0x50), adr);
> > hmm, I found this:
> > 8.5
> > Program Resume
> > The Resume command instructs the device to continue programming, and
> > automatically clears Status Register bits SR[7,2]. This command can be written to any
> > address. If error bits are set, the Status Register should be cleared before issuing the
> > next instruction. RST# must remain deasserted (see Figure 32, “Buffer Program
> > Flowchart” on page 74).
> >
> > Which I think disagrees with your statement. How did you arrive to this conclusion?
>
> There are several statements in flight. If you refer here to my claim that we should clear the status register before resuming then it's "If error bits are set, the Status Register should be cleared before issuing the next instruction." I don't see the point in reading the status and doing that
clear conditionally. Clearing them when they are already clear is OK.
>
> My point was just that the code is doing a resume and did not clear the error bits as the data sheet said it should.
>
> Note, the SR[7,2] bits its says are cleared by the command are not the error bits we're talking about. 7 and 2 are WSM-ready and erase-complete. The error bits are different ones. Maybe that's the confusion?

Yeah, didn't read this thoroughly enough, the comment talks about the status bits though.
Seems like the safe thing to do even though I don't recall anyone running into this problem
before. Send it as a separate git patch though.

>
> >      map_write(map, CMD(0xd0), adr);
> > +    /* some numonyx P30 parts have an apparent delay after starting or
> > +     resuming some commands. this is normally covered by the cache
> > +     invalidation done between the command and the start of reading
> > +     for the busy status bit to clear. but no such cache invalidation
> > +     is done when resuming and this allows the status-reading thread
> > +     awakened below to read the status too soon and think its operation
> > +     has finished when it fact its resumption is still underway. */
> > +    udelay(20);
> >
> > I don't follow your reasoning here. This Read Status command isn't saved anywhere so how can the code get confused later on?
>
> It's not that the read happens here and is saved. It happens in the thread awakened a few lines later. That thread went to sleep while waiting for its WSM operation to complete so it's in a loop reading and testing that. The first thing it does on wake up is read the WSM status.
>
> My point is that in the case of erase-resume there is much less real time between the write of the resume command and the later read of the status register than there is when starting an erase or program operation anew. This is because the latter perform a cache flush that takes time.
>
> My failures were caused by the erase-resume status read "seeing" a non-busy WSM. Adding a 20µs delay before that read (actually after the command write, but it amounts to the same thing) prevents this from happening. By the time awakened "wait-for-completion" code does its first status read it
sees the WSM as busy as it should until the erase actually finishes.
>
> The effect of the added delay is to make the erase-resume path's timing similar to the erase and buffer write paths that take more time because of their cache invalidate call. IOW, it explains why only the resume path has a problem when starting new erase or program commands work OK.

Ah, now I get it.

>
> > Perhaps the chip gets confused by this command?
> > Have you tried to remove the Read Status command?
>
> I wondered about this too. But I recall seeing comments that said some particular Atmel part needed that command following an erase-resume in order to be in the Read-Status state the rest of the code expects. The comments also said that doing that command amounted to a NOP on other hardware, but
maybe not. (!!)
>
> It could be that removing that command instead of adding a delay would make mine work but I'm doubtful. If the 0x70 command is messing things up I don't see how adding a delay would avoid it.

Two things here:
1) Those comments about needing Read Status are very old may may not be true anymore.
2) We need to explore the nature of this problem further. Adding a random delay isn't
   very appealing and may not fix the problem properly(it doesn't fix the problem for Stefan)

>
> > What if you move the udelay after the Read Status?
> >
> >      map_write(map, CMD(0x70), adr);
> >      chip->oldstate = FL_READY;
> >      chip->state = FL_ERASING;
>
> No, I didn't try that. Since the status read has not actually happened yet it didn't occur to me. If my theory is right, doing the delay after the 0x70 would also work since it still separates in real time the command write and status read.
>
> I'm happy to try both of these and report back if you think it would help.

Yes, as I am not convinced this is the correct fix and what the problem really is.
I still think it is worthwhile checking with Numonyx as we have seen buggy flashes
from them earlier. Are you sure these flashes was delivered directly from Numonyx?

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/02 22:19:58:
> >
> > On Feb 2, 2011, at 3:12 PM, Joakim Tjernlund wrote:

...

> >
> > >      map_write(map, CMD(0xd0), adr);
> > > +    /* some numonyx P30 parts have an apparent delay after starting or
> > > +     resuming some commands. this is normally covered by the cache
> > > +     invalidation done between the command and the start of reading
> > > +     for the busy status bit to clear. but no such cache invalidation
> > > +     is done when resuming and this allows the status-reading thread
> > > +     awakened below to read the status too soon and think its operation
> > > +     has finished when it fact its resumption is still underway. */
> > > +    udelay(20);
> > >
> > > I don't follow your reasoning here. This Read Status command isn't saved anywhere so how can the code get confused later on?
> >
> > It's not that the read happens here and is saved. It happens in the thread awakened a few lines later. That thread went to sleep while waiting for its WSM operation to complete so it's in a loop reading and testing that. The first thing it does on wake up is read the WSM status.
> >
> > My point is that in the case of erase-resume there is much less real time between the write of the resume command and the later read of the status register than there is when starting an erase or program operation anew. This is because the latter perform a cache flush that takes time.
> >
> > My failures were caused by the erase-resume status read "seeing" a non-busy WSM. Adding a 20µs delay before that read (actually after the command write, but it amounts to the same thing) prevents this from happening. By the time awakened "wait-for-completion" code does its first status read it
> sees the WSM as busy as it should until the erase actually finishes.

Perhaps you can test for ESS(SR.6) too?
something like:
  if DWS && !ESS

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 3, 2011, at 4:50 AM, Joakim Tjernlund wrote:

>>> My failures were caused by the erase-resume status read "seeing" a non-busy WSM. Adding a 20µs delay before that read (actually after the command write, but it amounts to the same thing) prevents this from happening. By the time awakened "wait-for-completion" code does its first status read it sees the WSM as busy as it should until the erase actually finishes.
> 
> Perhaps you can test for ESS(SR.6) too?
> something like:
>  if DWS && !ESS

Hmmm. So instead of a blind delay it would loop (with a timeout) while DWS && ESS are both set (meaning the erase resume command just written hasn't yet taken effect). It does make sense that if the resume takes time to drop SR.7 (ready) that it would also take time to drop SR.6 (ESS).

I like that. I'll add that to the set of tests today and report back.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi

I did some more anaysis of the write probem when creating a ubivolume.
I come to the conclusion that there must be a problem in the fuction
inval_cache_and_wait_for_operation().

Why I think this. In the log below you see that in the first part the
do_erase_oneblock() start the erasing. In the function
inval_cache_and_wait_for_operation() this thread is interrupted.

A do_write_buffer() suspends the erase by chip_ready() and runs until
cmd 0xe8 and waits for completion in WAIT_TIMEOUT.

Here again the do_erase_oneblock() continues to run and runs a
erase resume sequence to the end of erase the block.
--> THIS IS WRONG.

Now the do_write_buffer() continue but it ends in a write error.


When reading the inval_cache_and_wait_for_operation() there are 2
places were the mutex is unlocked

1) while INVALIDATE_CACHED_RANGE()
2) if status is not status_OK

My measurement shows that the mutex is taken in the first place.

Now I do expect that this method should make sure that the erasing
thread get "suspended" and the writing task can continue.
But this is not the case.
There is code were we compare the chip_state and chip->state.
But we are not hitting this code.

This is the summary of my analysis for today.
I was asking me why this code is working on other chips?

Regards
Stefan


do_erase_oneblock() begin
[1507][0209] do_erase_oneblock start adr=0x00000000 len=0x20000
[1507][0209] map_write 0x50 to 0x00000000
[1507][0209] map_write 0x20 to 0x00000000
[1507][0209] map_write 0xd0 to 0x00000000
[1507][0209] do_erase_oneblock before INVAL_CACHE_AND_WAIT 
adr=0x00000000 len=0x20000
[1507][0209] inval_cache_and_wait_for_operation short unlock

do_write_buffer() begin
[1507][0465] map_write 0xb0 to 0x03fe4c00
[1515][0465] erase suspend 1         adr=0x03fe4c00
[1515][0465] map_write 0x70 to 0x03fe4c00
[1515][0465] map_write 0xe8 to 0x03fe4c00
[1515][0465] buffer write before 0xe8 WAIT_TIMEOUT
[1515][0465] inval_cache_and_wait_for_operation short unlock

do_erase_oneblock() continue & finish
[1515][0209] inval_cache_and_wait_for_operation short lock
[1515][0209] do_erase_oneblock after  INVAL_CACHE_AND_WAIT 
adr=0x00000000 len=0x20000
[1515][0209] map_write 0x70 to 0x00000000
[1515][0209] map_write 0x50 to 0x00000000
[1515][0209] map_write 0xd0 to 0x00000000
[1515][0209] map_write 0x70 to 0x00000000
[1523][0209] erase resumed 2b        adr=0x00000000
[1527][0209] do_erase_oneblock end   adr=0x00000000 len=0x20000

do_write_buffer() continue & error
[1527][0465] inval_cache_and_wait_for_operation short lock
[1531][0465] buffer write after  0xe8 WAIT_TIMEOUT
[1531][0465] buffer write data to buf words=511
[1531][0465] buffer write data buf done
[1531][0465] map_write 0xd0 to 0x03fe4c00
[1531][0465] 50000000.flash: buffer write before INVAL_CACHE_AND_WAIT 
adr=0x03fe5000 len=0x400
[1531][0465] inval_cache_and_wait_for_operation short unlock
[1531][0465] inval_cache_and_wait_for_operation short lock
[1531][0465] inval_cache_and_wait_for_operation long unlock
[1543][0465] inval_cache_and_wait_for_operation long lock

[2503][0465] inval_cache_and_wait_for_operation long unlock
[2511][0465] inval_cache_and_wait_for_operation long lock
[2511][0465] 50000000.flash: buffer write after  INVAL_CACHE_AND_WAIT 
adr=0x03fe5000 len=0x400
[2511][0465] map_write 0x50 to 0x03fe4c00
[2511][0465] map_write 0x70 to 0x03fe4c00
[2519][0465] 50000000.flash: buffer write error status 0xb0 
adr=0x03fe5000 len=0x400

Am 02/03/2011 04:24 PM, schrieb Michael Cashwell:
> On Feb 3, 2011, at 4:50 AM, Joakim Tjernlund wrote:
>
>>>> My failures were caused by the erase-resume status read "seeing" a non-busy WSM. Adding a 20µs delay before that read (actually after the command write, but it amounts to the same thing) prevents this from happening. By the time awakened "wait-for-completion" code does its first status read it sees the WSM as busy as it should until the erase actually finishes.
>> Perhaps you can test for ESS(SR.6) too?
>> something like:
>>   if DWS&&  !ESS
> Hmmm. So instead of a blind delay it would loop (with a timeout) while DWS&&  ESS are both set (meaning the erase resume command just written hasn't yet taken effect). It does make sense that if the resume takes time to drop SR.7 (ready) that it would also take time to drop SR.6 (ESS).
>
> I like that. I'll add that to the set of tests today and report back.
>
> -Mike
>

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi

Now I have a patch that fix my problem. I did not yet do a lot of tests 
and I did
not yet analyzed correctness in all cases.
I check in the inval_cache_and_wait_for_operation() of the status is 
status_OK
the if the chip->state and the chip_state (the current chip state and 
the chip state
when the function is called) are equal or not. If equal break and exit 
(set the
chip->state= FL_STATUS) and if not equal add the thread in the wait queue.

I think we are not finished when not equal so we have do not have to 
take the mutex.

Now why this code worked with the older Flash chips. I don't know, but 
eventually
they are slower after the write buffer command 0xe8 and they are still 
busy when
inval_cache_and_wait_for_operation() checks if status_OK.
Tomorrow I'll check if this is the case. Now I do not have access to the HW.

Regards Stefan


diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c 
b/drivers/mtd/chips/cfi_cmdset_0001.c
index 28fc5c2..723985c 100644
--- a/drivers/mtd/chips/cfi_cmdset_0001.c
+++ b/drivers/mtd/chips/cfi_cmdset_0001.c

@@ static int inval_cache_and_wait_for_operation(
      for (;;) {
          status = map_read(map, cmd_adr);
-        if (map_word_andequal(map, status, status_OK, status_OK))
+        if (map_word_andequal(map, status, status_OK, status_OK)) {
+            if (chip->state != chip_state) {
+                goto unequal_states;
+            }
              break;
+        }

          if (!timeo) {

@@  static int inval_cache_and_wait_for_operation(
              cond_resched();
              timeo--;
          }
          mutex_lock(&chip->mutex);

+unequal_states:
          while (chip->state != chip_state) {


Am 02/03/2011 05:38 PM, schrieb Stefan Bigler:
> Hi
>
> I did some more anaysis of the write probem when creating a ubivolume.
> I come to the conclusion that there must be a problem in the fuction
> inval_cache_and_wait_for_operation().
>
> Why I think this. In the log below you see that in the first part the
> do_erase_oneblock() start the erasing. In the function
> inval_cache_and_wait_for_operation() this thread is interrupted.
>
> A do_write_buffer() suspends the erase by chip_ready() and runs until
> cmd 0xe8 and waits for completion in WAIT_TIMEOUT.
>
> Here again the do_erase_oneblock() continues to run and runs a
> erase resume sequence to the end of erase the block.
> --> THIS IS WRONG.
>
> Now the do_write_buffer() continue but it ends in a write error.
>
>
> When reading the inval_cache_and_wait_for_operation() there are 2
> places were the mutex is unlocked
>
> 1) while INVALIDATE_CACHED_RANGE()
> 2) if status is not status_OK
>
> My measurement shows that the mutex is taken in the first place.
>
> Now I do expect that this method should make sure that the erasing
> thread get "suspended" and the writing task can continue.
> But this is not the case.
> There is code were we compare the chip_state and chip->state.
> But we are not hitting this code.
>
> This is the summary of my analysis for today.
> I was asking me why this code is working on other chips?
>
> Regards
> Stefan
>
>
> do_erase_oneblock() begin
> [1507][0209] do_erase_oneblock start adr=0x00000000 len=0x20000
> [1507][0209] map_write 0x50 to 0x00000000
> [1507][0209] map_write 0x20 to 0x00000000
> [1507][0209] map_write 0xd0 to 0x00000000
> [1507][0209] do_erase_oneblock before INVAL_CACHE_AND_WAIT 
> adr=0x00000000 len=0x20000
> [1507][0209] inval_cache_and_wait_for_operation short unlock
>
> do_write_buffer() begin
> [1507][0465] map_write 0xb0 to 0x03fe4c00
> [1515][0465] erase suspend 1         adr=0x03fe4c00
> [1515][0465] map_write 0x70 to 0x03fe4c00
> [1515][0465] map_write 0xe8 to 0x03fe4c00
> [1515][0465] buffer write before 0xe8 WAIT_TIMEOUT
> [1515][0465] inval_cache_and_wait_for_operation short unlock
>
> do_erase_oneblock() continue & finish
> [1515][0209] inval_cache_and_wait_for_operation short lock
> [1515][0209] do_erase_oneblock after  INVAL_CACHE_AND_WAIT 
> adr=0x00000000 len=0x20000
> [1515][0209] map_write 0x70 to 0x00000000
> [1515][0209] map_write 0x50 to 0x00000000
> [1515][0209] map_write 0xd0 to 0x00000000
> [1515][0209] map_write 0x70 to 0x00000000
> [1523][0209] erase resumed 2b        adr=0x00000000
> [1527][0209] do_erase_oneblock end   adr=0x00000000 len=0x20000
>
> do_write_buffer() continue & error
> [1527][0465] inval_cache_and_wait_for_operation short lock
> [1531][0465] buffer write after  0xe8 WAIT_TIMEOUT
> [1531][0465] buffer write data to buf words=511
> [1531][0465] buffer write data buf done
> [1531][0465] map_write 0xd0 to 0x03fe4c00
> [1531][0465] 50000000.flash: buffer write before INVAL_CACHE_AND_WAIT 
> adr=0x03fe5000 len=0x400
> [1531][0465] inval_cache_and_wait_for_operation short unlock
> [1531][0465] inval_cache_and_wait_for_operation short lock
> [1531][0465] inval_cache_and_wait_for_operation long unlock
> [1543][0465] inval_cache_and_wait_for_operation long lock
>
> [2503][0465] inval_cache_and_wait_for_operation long unlock
> [2511][0465] inval_cache_and_wait_for_operation long lock
> [2511][0465] 50000000.flash: buffer write after  INVAL_CACHE_AND_WAIT 
> adr=0x03fe5000 len=0x400
> [2511][0465] map_write 0x50 to 0x03fe4c00
> [2511][0465] map_write 0x70 to 0x03fe4c00
> [2519][0465] 50000000.flash: buffer write error status 0xb0 
> adr=0x03fe5000 len=0x400
>
> Am 02/03/2011 04:24 PM, schrieb Michael Cashwell:
>> On Feb 3, 2011, at 4:50 AM, Joakim Tjernlund wrote:
>>
>>>>> My failures were caused by the erase-resume status read "seeing" a 
>>>>> non-busy WSM. Adding a 20µs delay before that read (actually after 
>>>>> the command write, but it amounts to the same thing) prevents this 
>>>>> from happening. By the time awakened "wait-for-completion" code 
>>>>> does its first status read it sees the WSM as busy as it should 
>>>>> until the erase actually finishes.
>>> Perhaps you can test for ESS(SR.6) too?
>>> something like:
>>>   if DWS&&  !ESS
>> Hmmm. So instead of a blind delay it would loop (with a timeout) 
>> while DWS&&  ESS are both set (meaning the erase resume command just 
>> written hasn't yet taken effect). It does make sense that if the 
>> resume takes time to drop SR.7 (ready) that it would also take time 
>> to drop SR.6 (ESS).
>>
>> I like that. I'll add that to the set of tests today and report back.
>>
>> -Mike
>>
>

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/04 00:18:44:
>
> Hi
>
> Now I have a patch that fix my problem. I did not yet do a lot of tests
> and I did
> not yet analyzed correctness in all cases.
> I check in the inval_cache_and_wait_for_operation() of the status is
> status_OK
> the if the chip->state and the chip_state (the current chip state and
> the chip state
> when the function is called) are equal or not. If equal break and exit
> (set the
> chip->state= FL_STATUS) and if not equal add the thread in the wait queue.
>
> I think we are not finished when not equal so we have do not have to
> take the mutex.
>
> Now why this code worked with the older Flash chips. I don't know, but
> eventually
> they are slower after the write buffer command 0xe8 and they are still
> busy when
> inval_cache_and_wait_for_operation() checks if status_OK.
> Tomorrow I'll check if this is the case. Now I do not have access to the HW.
>
> Regards Stefan

I havn't looked into this but I think I would rather see something like:
-        if (map_word_andequal(map, status, status_OK, status_OK))
+        if (map_word_andequal(map, status, status_OK, status_OK) &&
+           (chip->state == chip_state))

Does this work for you too?

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi Jocke

The code does the same, but is much nicer :-)
My test is also working again.

Im on the way to find out why our old P30 (130nm) Flash worked
without the fix.

Regards Stefan


Am 02/04/2011 11:47 AM, schrieb Joakim Tjernlund:
> Stefan Bigler<stefan.bigler@keymile.com>  wrote on 2011/02/04 00:18:44:
>> Hi
>>
>> Now I have a patch that fix my problem. I did not yet do a lot of tests
>> and I did
>> not yet analyzed correctness in all cases.
>> I check in the inval_cache_and_wait_for_operation() of the status is
>> status_OK
>> the if the chip->state and the chip_state (the current chip state and
>> the chip state
>> when the function is called) are equal or not. If equal break and exit
>> (set the
>> chip->state= FL_STATUS) and if not equal add the thread in the wait queue.
>>
>> I think we are not finished when not equal so we have do not have to
>> take the mutex.
>>
>> Now why this code worked with the older Flash chips. I don't know, but
>> eventually
>> they are slower after the write buffer command 0xe8 and they are still
>> busy when
>> inval_cache_and_wait_for_operation() checks if status_OK.
>> Tomorrow I'll check if this is the case. Now I do not have access to the HW.
>>
>> Regards Stefan
> I havn't looked into this but I think I would rather see something like:
> -        if (map_word_andequal(map, status, status_OK, status_OK))
> +        if (map_word_andequal(map, status, status_OK, status_OK)&&
> +           (chip->state == chip_state))
>
> Does this work for you too?
>
>   Jocke
>
>

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/04 12:04:40:
>
> Hi Jocke
>
> The code does the same, but is much nicer :-)
> My test is also working again.

Thinking a little more one could do:
if (chip->state == chip_state) {
	status = map_read(map, cmd_adr);
		if (map_word_andequal(map, status, status_OK, status_OK))
			break;
}
>
> Im on the way to find out why our old P30 (130nm) Flash worked
> without the fix.

Good.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/04 12:04:40:
> >
> > Hi Jocke
> >
> > The code does the same, but is much nicer :-)
> > My test is also working again.
>
> Thinking a little more one could do:
> if (chip->state == chip_state) {
>    status = map_read(map, cmd_adr);
>       if (map_word_andequal(map, status, status_OK, status_OK))
>          break;
> }

This is a bit unoptimal too:
#define XIP_INVAL_CACHED_RANGE(x...)
#define INVAL_CACHE_AND_WAIT inval_cache_and_wait_for_operation

....

	mutex_unlock(&chip->mutex);
	if (inval_len)
		INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
	mutex_lock(&chip->mutex);

XIP_INVAL_CACHED_RANGE is always a nop but still we drop and take the lock.
Just a waste of CPU.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

> >
> > Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/04 12:04:40:
> > >
> > > Hi Jocke
> > >
> > > The code does the same, but is much nicer :-)
> > > My test is also working again.
> >
> > Thinking a little more one could do:
> > if (chip->state == chip_state) {
> >    status = map_read(map, cmd_adr);
> >       if (map_word_andequal(map, status, status_OK, status_OK))
> >          break;
> > }
>
> This is a bit unoptimal too:
> #define XIP_INVAL_CACHED_RANGE(x...)
> #define INVAL_CACHE_AND_WAIT inval_cache_and_wait_for_operation
>
> ....
>
>    mutex_unlock(&chip->mutex);
>    if (inval_len)
>       INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
>    mutex_lock(&chip->mutex);
>
> XIP_INVAL_CACHED_RANGE is always a nop but still we drop and take the lock.
> Just a waste of CPU.

Duuh, disregard

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/04 12:04:40:
>
> Hi Jocke
>
> The code does the same, but is much nicer :-)
> My test is also working again.
>
> Im on the way to find out why our old P30 (130nm) Flash worked
> without the fix.

Stefan,

I think the bug lies in
static int inval_cache_and_wait_for_operation(
		struct map_info *map, struct flchip *chip,
		unsigned long cmd_adr, unsigned long inval_adr, int inval_len,
		unsigned int chip_op_time, unsigned int chip_op_time_max)
{
	struct cfi_private *cfi = map->fldrv_priv;
	map_word status, status_OK = CMD(0x80);
	int chip_state = chip->state;
	unsigned int timeo, sleep_time, reset_timeo;

	mutex_unlock(&chip->mutex);
	if (inval_len)
		INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
	mutex_lock(&chip->mutex);

Here we drop the lock and take it again. Someone may suspend the
erase and do a read/write instead and put the chip some other state.
Later we blindly do:
	for (;;) {
		status = map_read(map, cmd_adr);
		if (map_word_andequal(map, status, status_OK, status_OK))
			break;
But we don't know what we are reading really.

To test my theory, just remove the
	mutex_unlock(&chip->mutex);
	if (inval_len)
		INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
	mutex_lock(&chip->mutex);
and see what happens. This assumes that INVALIDATE_CACHED_RANGE is a NOP
in your setup though.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/04 12:04:40:
> >
> > Hi Jocke
> >
> > The code does the same, but is much nicer :-)
> > My test is also working again.
> >
> > Im on the way to find out why our old P30 (130nm) Flash worked
> > without the fix.
>
> Stefan,
>
> I think the bug lies in
> static int inval_cache_and_wait_for_operation(
>       struct map_info *map, struct flchip *chip,
>       unsigned long cmd_adr, unsigned long inval_adr, int inval_len,
>       unsigned int chip_op_time, unsigned int chip_op_time_max)
> {
>    struct cfi_private *cfi = map->fldrv_priv;
>    map_word status, status_OK = CMD(0x80);
>    int chip_state = chip->state;
>    unsigned int timeo, sleep_time, reset_timeo;
>
>    mutex_unlock(&chip->mutex);
>    if (inval_len)
>       INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
>    mutex_lock(&chip->mutex);
>
> Here we drop the lock and take it again. Someone may suspend the
> erase and do a read/write instead and put the chip some other state.
> Later we blindly do:
>    for (;;) {
>       status = map_read(map, cmd_adr);
>       if (map_word_andequal(map, status, status_OK, status_OK))
>          break;
> But we don't know what we are reading really.
>
> To test my theory, just remove the
>    mutex_unlock(&chip->mutex);
>    if (inval_len)
>       INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
>    mutex_lock(&chip->mutex);
> and see what happens. This assumes that INVALIDATE_CACHED_RANGE is a NOP
> in your setup though.
>
>  Jocke

Noticed this too:
	if (sleep_time >= 1000000/HZ) {
			/*
			 * Half of the normal delay still remaining
			 * can be performed with a sleeping delay instead
			 * of busy waiting.
			 */
			msleep(sleep_time/1000);
			timeo -= sleep_time;
			sleep_time = 1000000/HZ;
	} ...

This is broken and may cause needless delays, possibly underflow timeo
too.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi Jocke

I tested your proposal to remove the unlock/lock for the
INVALIDATE_CACHED_RANGE() and without the addtional test
for unequal states, it worked in my environment.

Regards
Stefan

Am 02/04/2011 02:05 PM, schrieb Joakim Tjernlund:
> Stefan Bigler<stefan.bigler@keymile.com>  wrote on 2011/02/04 12:04:40:
>> Hi Jocke
>>
>> The code does the same, but is much nicer :-)
>> My test is also working again.
>>
>> Im on the way to find out why our old P30 (130nm) Flash worked
>> without the fix.
> Stefan,
>
> I think the bug lies in
> static int inval_cache_and_wait_for_operation(
> 		struct map_info *map, struct flchip *chip,
> 		unsigned long cmd_adr, unsigned long inval_adr, int inval_len,
> 		unsigned int chip_op_time, unsigned int chip_op_time_max)
> {
> 	struct cfi_private *cfi = map->fldrv_priv;
> 	map_word status, status_OK = CMD(0x80);
> 	int chip_state = chip->state;
> 	unsigned int timeo, sleep_time, reset_timeo;
>
> 	mutex_unlock(&chip->mutex);
> 	if (inval_len)
> 		INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
> 	mutex_lock(&chip->mutex);
>
> Here we drop the lock and take it again. Someone may suspend the
> erase and do a read/write instead and put the chip some other state.
> Later we blindly do:
> 	for (;;) {
> 		status = map_read(map, cmd_adr);
> 		if (map_word_andequal(map, status, status_OK, status_OK))
> 			break;
> But we don't know what we are reading really.
>
> To test my theory, just remove the
> 	mutex_unlock(&chip->mutex);
> 	if (inval_len)
> 		INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
> 	mutex_lock(&chip->mutex);
> and see what happens. This assumes that INVALIDATE_CACHED_RANGE is a NOP
> in your setup though.
>
>   Jocke
>

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/04 17:45:17:
>
> Hi Jocke
>
> I tested your proposal to remove the unlock/lock for the
> INVALIDATE_CACHED_RANGE() and without the addtional test
> for unequal states, it worked in my environment.

Great, I have this patch now. Perhaps the both of you can test this
over the weekend?

diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
index e89f2d0..b2665ad 100644
--- a/drivers/mtd/chips/cfi_cmdset_0001.c
+++ b/drivers/mtd/chips/cfi_cmdset_0001.c
@@ -1245,6 +1245,17 @@ static int inval_cache_and_wait_for_operation(
 	sleep_time = chip_op_time / 2;

 	for (;;) {
+		while (chip->state != chip_state) {
+			/* Someone's suspended the operation: sleep */
+			DECLARE_WAITQUEUE(wait, current);
+			set_current_state(TASK_UNINTERRUPTIBLE);
+			add_wait_queue(&chip->wq, &wait);
+			mutex_unlock(&chip->mutex);
+			schedule();
+			remove_wait_queue(&chip->wq, &wait);
+			mutex_lock(&chip->mutex);
+		}
+
 		status = map_read(map, cmd_adr);
 		if (map_word_andequal(map, status, status_OK, status_OK))
 			break;
@@ -1273,16 +1284,6 @@ static int inval_cache_and_wait_for_operation(
 		}
 		mutex_lock(&chip->mutex);

-		while (chip->state != chip_state) {
-			/* Someone's suspended the operation: sleep */
-			DECLARE_WAITQUEUE(wait, current);
-			set_current_state(TASK_UNINTERRUPTIBLE);
-			add_wait_queue(&chip->wq, &wait);
-			mutex_unlock(&chip->mutex);
-			schedule();
-			remove_wait_queue(&chip->wq, &wait);
-			mutex_lock(&chip->mutex);
-		}
 		if (chip->erase_suspended && chip_state == FL_ERASING)  {
 			/* Erase suspend occured while sleep: reset timeout */
 			timeo = reset_timeo;

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 4, 2011, at 8:05 AM, Joakim Tjernlund wrote:

> Stefan,
> 
> I think the bug lies in
> static int inval_cache_and_wait_for_operation(
> 		struct map_info *map, struct flchip *chip,
> 		unsigned long cmd_adr, unsigned long inval_adr, int inval_len,
> 		unsigned int chip_op_time, unsigned int chip_op_time_max)
> {
> 	struct cfi_private *cfi = map->fldrv_priv;
> 	map_word status, status_OK = CMD(0x80);
> 	int chip_state = chip->state;
> 	unsigned int timeo, sleep_time, reset_timeo;
> 
> 	mutex_unlock(&chip->mutex);
> 	if (inval_len)
> 		INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
> 	mutex_lock(&chip->mutex);
> 
> Here we drop the lock and take it again. Someone may suspend the
> erase and do a read/write instead and put the chip some other state.

That's where I get confused. It's true that another thread could do that but wouldn't it have to bracket its operation with calls to get_chip() and put_chip()? Those actually do the suspend and resume. I'm certainly seeing erases being suspended to do a buffered write and then being resumed.

A properly done suspend/resume should leave the hardware is the same state it was in before hand. So if get_chip/put_chip are not doing that then that's where the problem is.

Originally I thought a udelay(20) was needed after the resume command was sent. What I've most recently seen is that just doing one map_read() of status (and discarding the result) is enough to avoid my error:

	switch(chip->oldstate) {
	case FL_ERASING:
		chip->state = chip->oldstate;
		/* What if one interleaved chip has finished and the
		   other hasn't? The old code would leave the finished
		   one in READY mode. That's bad, and caused -EROFS
		   errors to be returned from do_erase_oneblock because
		   that's the only bit it checked for at the time.
		   As the state machine appears to explicitly allow
		   sending the 0x70 (Read Status) command to an erasing
		   chip and expecting it to be ignored, that's what we
		   do. */
		map_write(map, CMD(0xd0), adr);
		map_write(map, CMD(0x70), adr);
		(void) map_read(map, adr);	// <<<<----- added
		chip->oldstate = FL_READY;
		chip->state = FL_ERASING;
		break;

I'm still not sure why. My guess is that it's timing (since udelay(20) in the same spot also works for me) but being timing-sensitive is making it hard to pin down. Adding printk()s also often makes it not happen.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/04 18:09:01:
>
> On Feb 4, 2011, at 8:05 AM, Joakim Tjernlund wrote:
>
> > Stefan,
> >
> > I think the bug lies in
> > static int inval_cache_and_wait_for_operation(
> >       struct map_info *map, struct flchip *chip,
> >       unsigned long cmd_adr, unsigned long inval_adr, int inval_len,
> >       unsigned int chip_op_time, unsigned int chip_op_time_max)
> > {
> >    struct cfi_private *cfi = map->fldrv_priv;
> >    map_word status, status_OK = CMD(0x80);
> >    int chip_state = chip->state;
> >    unsigned int timeo, sleep_time, reset_timeo;
> >
> >    mutex_unlock(&chip->mutex);
> >    if (inval_len)
> >       INVALIDATE_CACHED_RANGE(map, inval_adr, inval_len);
> >    mutex_lock(&chip->mutex);
> >
> > Here we drop the lock and take it again. Someone may suspend the
> > erase and do a read/write instead and put the chip some other state.
>
> That's where I get confused. It's true that another thread could do that but wouldn't it have to bracket its operation with calls to get_chip() and put_chip()? Those actually do the suspend and resume. I'm certainly seeing erases being suspended to do a buffered write and then being resumed.

buffered write do get_chip that suspends the erase, then a WAIT_TIMEOUT which drops the locks and
gives the suspended erase a chance to wakeup and run but now SR is holding the status
for the write so the suspended erase are testing the wrong status, do you agree?

>
> A properly done suspend/resume should leave the hardware is the same state it was in before hand. So if get_chip/put_chip are not doing that then that's where the problem is.

See my comment above, I don't think inval_cache_and_wait_for_operation is doing the right thing.

>
> Originally I thought a udelay(20) was needed after the resume command was sent. What I've most recently seen is that just doing one map_read() of status (and discarding the result) is enough to avoid my error:
>
>    switch(chip->oldstate) {
>    case FL_ERASING:
>       chip->state = chip->oldstate;
>       /* What if one interleaved chip has finished and the
>          other hasn't? The old code would leave the finished
>          one in READY mode. That's bad, and caused -EROFS
>          errors to be returned from do_erase_oneblock because
>          that's the only bit it checked for at the time.
>          As the state machine appears to explicitly allow
>          sending the 0x70 (Read Status) command to an erasing
>          chip and expecting it to be ignored, that's what we
>          do. */
>       map_write(map, CMD(0xd0), adr);
>       map_write(map, CMD(0x70), adr);
>       (void) map_read(map, adr);   // <<<<----- added
>       chip->oldstate = FL_READY;
>       chip->state = FL_ERASING;
>       break;
>
> I'm still not sure why. My guess is that it's timing (since udelay(20) in the same spot also works for me) but being timing-sensitive is making it hard to pin down. Adding printk()s also often makes it not happen.

I won't worry about this until you test my patch and still have a problem :)
Please test it.

   Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 5, 2011, at 5:29 AM, Joakim Tjernlund wrote:

> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/04 18:09:01:
>> 
>> That's where I get confused. It's true that another thread could do that but wouldn't it have to bracket its operation with calls to get_chip() and put_chip()? Those actually do the suspend and resume. I'm certainly seeing erases being suspended to do a buffered write and then being resumed.
> 
> buffered write do get_chip that suspends the erase, then a WAIT_TIMEOUT which drops the locks and gives the suspended erase a chance to wakeup and run but now SR is holding the status for the write so the suspended erase are testing the wrong status, do you agree?

It's not that simple. Just waking the suspended erase thread should not cause it to "run" the way you are saying.

That thread *should* wake up in inval_cache_and_wait_for_operation() inside its while (chip->state != chip_state) loop. The purpose of that loop is to see if something else is going on with the chip and if so just go back to sleep. That should prevent what you are saying is happening and if it is not then we need to figure out why.

In the case of a buffered write the erase thread should see chip->state as either FL_WRITING_TO_BUFFER (if after the 0xE8) or FL_WRITING (if after the 0xD0). Since those don't match the expected FL_ERASING state the thread should stay in the while loop and go back to sleep on the wait queue. It should keep doing that until the chip->state has come back to FL_ERASING. That should not happen until the write function is finished and does its put_chip and erase resume.

So what I'm saying is that just dropping the locks and letting other threads run is not, by itself itself, wrong. The code's supposed to do that. It's just that the other threads are supposed check the conditions when they wake up and only proceed if the conditions are correct.

But I do see something suspicious. I think it can be argued that all CFI thread wake-ups need to do the while (chip->state != chip_state) dance and go back to sleep if not.

That seems to be the case for inval_cache_and_wait_for_operation() but what about the other places where threads can be scheduled out? Won't they just wake up where they are or am I missing some wait queue magic?

IOW: We should look for other places outside of inval_cache_and_wait_for_operation() that call things like msleep, schedule, and cond_resched. (One sneaky one is cfi_udelay as it may call cond_resched.)

If any of those fail to do the chip->state != chip_state sleep loop when they awaken then we have have found our problem.

One last idea is to add more info in your logging code:

ubimkvol /dev/ubi0 -s 6MiB -N test1
[2299][209] do_erase_oneblock start adr=0x00020000 len=0x20000
[2299][209] map_write 0x50 to 0x00020000
[2299][209] map_write 0x20 to 0x00020000
[2299][209] map_write 0xd0 to 0x00020000
[2299][465] map_write 0xb0 to 0x03fe5000
[2307][465] erase suspend 1         adr=0x03fe5000
[2307][465] map_write 0x70 to 0x03fe5000
[2307][465] map_write 0xe8 to 0x03fe5000
[2307][209] map_write 0x70 to 0x00020000
[2307][209] map_write 0x50 to 0x00020000
[2307][209] map_write 0xd0 to 0x00020000
[2307][209] map_write 0x70 to 0x00020000
[2311][209] erase resumed 2b        adr=0x00020000
[2319][209] do_erase_oneblock end   adr=0x00020000 len=0x20000
[2319][465] map_write 0x1ff to 0x03fe5000
[2319][465] map_write 0xc03c0000 to 0x03fe5000
[2319][465] map_write 0xc03c0000 to 0x03fe5002
...
[2327][465] map_write 0xc03c0000 to 0x03fe53fc
[2327][465] map_write 0xc03c0000 to 0x03fe53fe
[2327][465] map_write 0xd0 to 0x03fe5000
[3387][465] map_write 0x50 to 0x03fe5000
[3387][465] map_write 0x70 to 0x03fe5000
[3395][465] 50000000.flash: buffer write error status 0xb0 adr=0x03fe5400 len=0x0 (0x400)

when "erase resumed" happens, it should be inside the put_chip() done when the write command is finished. Something to confirm.

It would be helpful if the log also showed start/end for do_buffer_write() and would print chip->state at various points since that value controls what threads do when they wake up.

> I won't worry about this until you test my patch and still have a problem :)
> Please test it.

I tested it quickly on Friday and it didn't fix my problem, but we may be fighting different problems.

I also can't be sure the .c file didn't have other changes. I was really pressed for time that day.

My plan is to retest your patch against a pristine copy of the file and report back. Unfortunately this has to wait until Monday as I don't have access to the hardware over the weekend.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

Sorry, I misattributed these log entries. That's Stefan's info, not Joakim's.

But still interesting...

On Feb 2, 2011, at 12:37 PM, Stefan Bigler wrote:

> [2307][465] erase suspend 1         adr=0x03fe5000
> [2307][465] map_write 0x70 to 0x03fe5000
> [2307][465] map_write 0xe8 to 0x03fe5000
> [2307][209] map_write 0x70 to 0x00020000
> [2307][209] map_write 0x50 to 0x00020000
> [2307][209] map_write 0xd0 to 0x00020000
> [2307][209] map_write 0x70 to 0x00020000
> [2311][209] erase resumed 2b        adr=0x00020000
> [2319][209] do_erase_oneblock end   adr=0x00020000 len=0x20000
> [2319][465] map_write 0x1ff to 0x03fe5000
> [2319][465] map_write 0xc03c0000 to 0x03fe5000
> [2319][465] map_write 0xc03c0000 to 0x03fe5002

Focusing even more on this... The last 3 lines are telling. That looks very much like a word count for the buffered write followed by data.

So I think we're on the right track overall. Between the 0xe8 and the word count 0x1ff a suspended erase thread is jumping in and disturbing things.

It's not that doing that causes incorrect bits in the SR but that it disrupts up the 0xe8/count/data... sequence that must happen atomically. That later causes a command sequence error, which is what the status 0xb0 means.

So how is an erase thread waking up and not seeing the chip->state to be something other than the FL_ERASING and going back to sleep?

More Monday.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/05 22:47:33:
>
> Sorry, I misattributed these log entries. That's Stefan's info, not Joakim's.
>
> But still interesting...
>
> On Feb 2, 2011, at 12:37 PM, Stefan Bigler wrote:
>
> > [2307][465] erase suspend 1         adr=0x03fe5000
> > [2307][465] map_write 0x70 to 0x03fe5000
> > [2307][465] map_write 0xe8 to 0x03fe5000
> > [2307][209] map_write 0x70 to 0x00020000
> > [2307][209] map_write 0x50 to 0x00020000
> > [2307][209] map_write 0xd0 to 0x00020000
> > [2307][209] map_write 0x70 to 0x00020000
> > [2311][209] erase resumed 2b        adr=0x00020000
> > [2319][209] do_erase_oneblock end   adr=0x00020000 len=0x20000
> > [2319][465] map_write 0x1ff to 0x03fe5000
> > [2319][465] map_write 0xc03c0000 to 0x03fe5000
> > [2319][465] map_write 0xc03c0000 to 0x03fe5002
>
> Focusing even more on this... The last 3 lines are telling. That looks very much like a word count for the buffered write followed by data.
>
> So I think we're on the right track overall. Between the 0xe8 and the word count 0x1ff a suspended erase thread is jumping in and disturbing things.
>
> It's not that doing that causes incorrect bits in the SR but that it disrupts up the 0xe8/count/data... sequence that must happen atomically. That later causes a command sequence error, which is what the status 0xb0 means.
>
> So how is an erase thread waking up and not seeing the chip->state to be something other than the FL_ERASING and going back to sleep?

The only thing I can think of the the earlier discussion about dropping the lock.

Oh, one more thing, possibly one needs to add cpu_relax() or similar
to force gcc to reload chip->state in the while loop?

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 6, 2011, at 4:46 AM, Joakim Tjernlund wrote:

>> It's not that doing that causes incorrect bits in the SR but that it disrupts up the 0xe8/count/data... sequence that must happen atomically. That later causes a command sequence error, which is what the status 0xb0 means.
>> 
>> So how is an erase thread waking up and not seeing the chip->state to be something other than the FL_ERASING and going back to sleep?
> 
> The only thing I can think of the the earlier discussion about dropping the lock.

Right. Specifically about why an awakened erase thread that should not proceed (because the chip->state is wrong) is doing so anyway.

That's clearly what's happening in Stefan's trace when thread 465 writes 0xe8 and the next write is 0x70 by thread 209. Such a sequence is absolutely illegal (for the flash) and the latter thread is the problem. If we could get a stack trace for that map_write 0x70 I think we'd find the thread awoke and touched the chip without verifying the state first. The question is why.

One last idea.

The whole for(;;) loop in inval_cache_and_wait_for_operation() looks odd to me. Continuing with your idea of moving the chip->state while loop first, I see other problems. It seems to me that anywhere we drop and retake the chip mutex the very next thing needs to be the state check loop. Any break in holding that mutex means we must go back to the top and check state again.

I don't think the code as written does that. I have a completely reordered version of this function. (It didn't fix my issue but I think mine is something else.) On Monday I'll send that to you so you can consider it.

> Oh, one more thing, possibly one needs to add cpu_relax() or similar to force gcc to reload chip->state in the while loop?

I was also wondering about possible gcc optimization issues. I'm on 4.5.2 and that worked for me with the 2003 flash part. The same binaries fail with the 2008 parts, so, I don't know.

Keep in mind that chip->state is not a hardware access. It's just another struct member. And I think that the rules are that any function call counts as a sequence point and gcc isn't allowed to think it knows what the result is and must reload it.

Lastly, consider the direction of the behavior. If we're in the state-check while loop then we got there because the two things were NOT equal. If an optimization error is causing a stale value to be compared wouldn't the observed behavior be that it remains not equal? (If it's not reloaded then how could it change?)

I'd expect an optimization error like that to get us stuck in the while loop, not exit from it prematurely.

Makes me head hurt!

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/06 16:49:53:
>
> On Feb 6, 2011, at 4:46 AM, Joakim Tjernlund wrote:
>
> >> It's not that doing that causes incorrect bits in the SR but that it disrupts up the 0xe8/count/data... sequence that must happen atomically. That later causes a command sequence error, which is what the status 0xb0 means.
> >>
> >> So how is an erase thread waking up and not seeing the chip->state to be something other than the FL_ERASING and going back to sleep?
> >
> > The only thing I can think of the the earlier discussion about dropping the lock.
>
> Right. Specifically about why an awakened erase thread that should not proceed (because the chip->state is wrong) is doing so anyway.
>
> That's clearly what's happening in Stefan's trace when thread 465 writes 0xe8 and the next write is 0x70 by thread 209. Such a sequence is absolutely illegal (for the flash) and the latter thread is the problem. If we could get a stack trace for that map_write 0x70 I think we'd find the thread
awoke and touched the chip without verifying the state first. The question is why.

Without my patch it is clear that you do end up with this problem. The first time one enter the for(;;) loop the
driver reads out status from the chip before checking chip->state. This of course assumes that dropping the
lock earlier may cause a schedule. So far Stefans tests indicates this to be true.

>
> One last idea.
>
> The whole for(;;) loop in inval_cache_and_wait_for_operation() looks odd to me. Continuing with your idea of moving the chip->state while loop first, I see other problems. It seems to me that anywhere we drop and retake the chip mutex the very next thing needs to be the state check loop. Any break
in holding that mutex means we must go back to the top and check state again.
>
> I don't think the code as written does that. I have a completely reordered version of this function. (It didn't fix my issue but I think mine is something else.) On Monday I'll send that to you so you can consider it.

Yes, it is a bit odd. In addition to my patch one could move the erase suspend tests before
the if(!timeo) test.

>
> > Oh, one more thing, possibly one needs to add cpu_relax() or similar to force gcc to reload chip->state in the while loop?
>
> I was also wondering about possible gcc optimization issues. I'm on 4.5.2 and that worked for me with the 2003 flash part. The same binaries fail with the 2008 parts, so, I don't know.

Very recent gcc, I am 3.4.6 but recently I began testing a little with 4.5.2. I do think I will
wait for 4.5.3

>
> Keep in mind that chip->state is not a hardware access. It's just another struct member. And I think that the rules are that any function call counts as a sequence point and gcc isn't allowed to think it knows what the result is and must reload it.
>
> Lastly, consider the direction of the behavior. If we're in the state-check while loop then we got there because the two things were NOT equal. If an optimization error is causing a stale value to be compared wouldn't the observed behavior be that it remains not equal? (If it's not reloaded then
how could it change?)
>
> I'd expect an optimization error like that to get us stuck in the while loop, not exit from it prematurely.

Yes, all true. I wonder though if the mutex lock/unlock counts as a reload point? These are
usually some inline asm. If not one could possibly argue that the first chip->state access,
before entering the while body is using an old value.

>
> Makes me head hurt!

You are not alone :)

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 6, 2011, at 12:29 PM, Joakim Tjernlund wrote:

> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/06 16:49:53:
> 
>> That's clearly what's happening in Stefan's trace when thread 465 writes 0xe8 and the next write is 0x70 by thread 209. Such a sequence is absolutely illegal (for the flash) and the latter thread is the problem. If we could get a stack trace for that map_write 0x70 I think we'd find the thread awoke and touched the chip without verifying the state first. The question is why.
> 
> Without my patch it is clear that you do end up with this problem. The first time one enter the for(;;) loop the driver reads out status from the chip before checking chip->state. This of course assumes that dropping the lock earlier may cause a schedule. So far Stefans tests indicates this to be true.

Yes, it was your patch and his log that lead me down that path!

>> One last idea.
>> 
>> The whole for(;;) loop in inval_cache_and_wait_for_operation() looks odd to me. Continuing with your idea of moving the chip->state while loop first, I see other problems. It seems to me that anywhere we drop and retake the chip mutex the very next thing needs to be the state check loop. Any break in holding that mutex means we must go back to the top and check state again.
>> 
>> I don't think the code as written does that. I have a completely reordered version of this function. (It didn't fix my issue but I think mine is something else.) On Monday I'll send that to you so you can consider it.
> 
> Yes, it is a bit odd. In addition to my patch one could move the erase suspend tests before the if(!timeo) test.

Precisely. I suspect you may well already have my reordered version. :-)

>>> Oh, one more thing, possibly one needs to add cpu_relax() or similar to force gcc to reload chip->state in the while loop?
>> 
>> I was also wondering about possible gcc optimization issues. I'm on 4.5.2 and that worked for me with the 2003 flash part. The same binaries fail with the 2008 parts, so, I don't know.
> 
> Very recent gcc, I am 3.4.6 but recently I began testing a little with 4.5.2. I do think I will wait for 4.5.3

I tried 4.5.1 but it failed for other reasons. I submitted bug reports to gnu and a fix appeared (finally) in 4.5.2. It's been good so far but I'm always mindful of that issue.

Staying current is a two edge sword. In general, later gccs have better code analysis and warnings which are valuable even if we ship using an older version.

>> Keep in mind that chip->state is not a hardware access. It's just another struct member. And I think that the rules are that any function call counts as a sequence point and gcc isn't allowed to think it knows what the result is and must reload it.
>> 
>> Lastly, consider the direction of the behavior. If we're in the state-check while loop then we got there because the two things were NOT equal. If an optimization error is causing a stale value to be compared wouldn't the observed behavior be that it remains not equal? (If it's not reloaded then how could it change?)
>> 
>> I'd expect an optimization error like that to get us stuck in the while loop, not exit from it prematurely.
> 
> Yes, all true. I wonder though if the mutex lock/unlock counts as a reload point? These are usually some inline asm. If not one could possibly argue that the first chip->state access, before entering the while body is using an old value.

Yes, how inlines interact with sequence points has never been entirely clear to me. Especially since the compiler is free to inline something I didn't tell it to and to ignore me telling to inline if it wants to.

I *think* the rules are semantic. If it's written (preprocessor aside) to look like a function call then it counts as a sequence point even if it ends up being inlined. But that's all quite beyond anything I can say for sure!

>> Makes me head hurt!
> 
> You are not alone :)

So collectively maybe we can make it hurt less. That's my theory, anyway, and I'm sticking to it.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/06 22:13:40:
>
> On Feb 6, 2011, at 12:29 PM, Joakim Tjernlund wrote:
>
> > Michael Cashwell <mboards@prograde.net> wrote on 2011/02/06 16:49:53:
> >
> >> That's clearly what's happening in Stefan's trace when thread 465 writes 0xe8 and the next write is 0x70 by thread 209. Such a sequence is absolutely illegal (for the flash) and the latter thread is the problem. If we could get a stack trace for that map_write 0x70 I think we'd find the thread
awoke and touched the chip without verifying the state first. The question is why.
> >
> > Without my patch it is clear that you do end up with this problem. The first time one enter the for(;;) loop the driver reads out status from the chip before checking chip->state. This of course assumes that dropping the lock earlier may cause a schedule. So far Stefans tests indicates this to
be true.
>
> Yes, it was your patch and his log that lead me down that path!
>
> >> One last idea.
> >>
> >> The whole for(;;) loop in inval_cache_and_wait_for_operation() looks odd to me. Continuing with your idea of moving the chip->state while loop first, I see other problems. It seems to me that anywhere we drop and retake the chip mutex the very next thing needs to be the state check loop. Any
break in holding that mutex means we must go back to the top and check state again.
> >>
> >> I don't think the code as written does that. I have a completely reordered version of this function. (It didn't fix my issue but I think mine is something else.) On Monday I'll send that to you so you can consider it.
> >
> > Yes, it is a bit odd. In addition to my patch one could move the erase suspend tests before the if(!timeo) test.
>
> Precisely. I suspect you may well already have my reordered version. :-)

hehe, lets se(the barrier() is probably useless):

diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
index e89f2d0..73e29a3 100644
--- a/drivers/mtd/chips/cfi_cmdset_0001.c
+++ b/drivers/mtd/chips/cfi_cmdset_0001.c
@@ -1243,12 +1243,34 @@ static int inval_cache_and_wait_for_operation(
 		timeo = 500000;
 	reset_timeo = timeo;
 	sleep_time = chip_op_time / 2;
-
+	barrier(); /* make sure chip->state gets reloaded */
 	for (;;) {
+		if (chip->state != chip_state) {
+			/* Someone's suspended the operation: sleep */
+			DECLARE_WAITQUEUE(wait, current);
+			set_current_state(TASK_UNINTERRUPTIBLE);
+			add_wait_queue(&chip->wq, &wait);
+			mutex_unlock(&chip->mutex);
+			schedule();
+			remove_wait_queue(&chip->wq, &wait);
+			mutex_lock(&chip->mutex);
+			continue;
+		}
+
 		status = map_read(map, cmd_adr);
 		if (map_word_andequal(map, status, status_OK, status_OK))
 			break;

+		if (chip->erase_suspended && chip_state == FL_ERASING)  {
+			/* Erase suspend occured while sleep: reset timeout */
+			timeo = reset_timeo;
+			chip->erase_suspended = 0;
+		}
+		if (chip->write_suspended && chip_state == FL_WRITING)  {
+			/* Write suspend occured while sleep: reset timeout */
+			timeo = reset_timeo;
+			chip->write_suspended = 0;
+		}
 		if (!timeo) {
 			map_write(map, CMD(0x70), cmd_adr);
 			chip->state = FL_STATUS;
@@ -1272,27 +1294,6 @@ static int inval_cache_and_wait_for_operation(
 			timeo--;
 		}
 		mutex_lock(&chip->mutex);
-
-		while (chip->state != chip_state) {
-			/* Someone's suspended the operation: sleep */
-			DECLARE_WAITQUEUE(wait, current);
-			set_current_state(TASK_UNINTERRUPTIBLE);
-			add_wait_queue(&chip->wq, &wait);
-			mutex_unlock(&chip->mutex);
-			schedule();
-			remove_wait_queue(&chip->wq, &wait);
-			mutex_lock(&chip->mutex);
-		}
-		if (chip->erase_suspended && chip_state == FL_ERASING)  {
-			/* Erase suspend occured while sleep: reset timeout */
-			timeo = reset_timeo;
-			chip->erase_suspended = 0;
-		}
-		if (chip->write_suspended && chip_state == FL_WRITING)  {
-			/* Write suspend occured while sleep: reset timeout */
-			timeo = reset_timeo;
-			chip->write_suspended = 0;
-		}
 	}

 	/* Done and happy. */

>
> >>> Oh, one more thing, possibly one needs to add cpu_relax() or similar to force gcc to reload chip->state in the while loop?
> >>
> >> I was also wondering about possible gcc optimization issues. I'm on 4.5.2 and that worked for me with the 2003 flash part. The same binaries fail with the 2008 parts, so, I don't know.
> >
> > Very recent gcc, I am 3.4.6 but recently I began testing a little with 4.5.2. I do think I will wait for 4.5.3
>
> I tried 4.5.1 but it failed for other reasons. I submitted bug reports to gnu and a fix appeared (finally) in 4.5.2. It's been good so far but I'm always mindful of that issue.
>
> Staying current is a two edge sword. In general, later gccs have better code analysis and warnings which are valuable even if we ship using an older version.

Precisely, but later gcc is worse optimizing trivial code.

>
> >> Keep in mind that chip->state is not a hardware access. It's just another struct member. And I think that the rules are that any function call counts as a sequence point and gcc isn't allowed to think it knows what the result is and must reload it.
> >>
> >> Lastly, consider the direction of the behavior. If we're in the state-check while loop then we got there because the two things were NOT equal. If an optimization error is causing a stale value to be compared wouldn't the observed behavior be that it remains not equal? (If it's not reloaded
then how could it change?)
> >>
> >> I'd expect an optimization error like that to get us stuck in the while loop, not exit from it prematurely.
> >
> > Yes, all true. I wonder though if the mutex lock/unlock counts as a reload point? These are usually some inline asm. If not one could possibly argue that the first chip->state access, before entering the while body is using an old value.
>
> Yes, how inlines interact with sequence points has never been entirely clear to me. Especially since the compiler is free to inline something I didn't tell it to and to ignore me telling to inline if it wants to.
>
> I *think* the rules are semantic. If it's written (preprocessor aside) to look like a function call then it counts as a sequence point even if it ends up being inlined. But that's all quite beyond anything I can say for sure!

That makes sense too.

>
> >> Makes me head hurt!
> >
> > You are not alone :)
>
> So collectively maybe we can make it hurt less. That's my theory, anyway, and I'm sticking to it.

:)

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi

I run the test on my side with the patches proposed with and without 
barrier().
Both worked without problems.

My workspace has now the following patches:

1) clear status before suspend
------------------------------
+    /* numonyx data sheet clearly says to always reset the status bits
+       before resuming a suspended erase. not doing so results in
+       an ambiguous mixture of status bits once the command ends. */
+    debug_map_write(map, CMD(0x50), adr);
+    debug_map_write(map, CMD(0xd0), adr);


2) compare chip>state and chip_state before touching the chip
------------------------------------------------------------

diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
index e89f2d0..73e29a3 100644
--- a/drivers/mtd/chips/cfi_cmdset_0001.c
+++ b/drivers/mtd/chips/cfi_cmdset_0001.c
@@ -1243,12 +1243,34 @@ static int inval_cache_and_wait_for_operation(
  		timeo = 500000;
  	reset_timeo = timeo;
  	sleep_time = chip_op_time / 2;
-
+	barrier(); /* make sure chip->state gets reloaded */
  	for (;;) {
+		if (chip->state != chip_state) {
+			/* Someone's suspended the operation: sleep */
+			DECLARE_WAITQUEUE(wait, current);
+			set_current_state(TASK_UNINTERRUPTIBLE);
+			add_wait_queue(&chip->wq,&wait);
+			mutex_unlock(&chip->mutex);
+			schedule();
+			remove_wait_queue(&chip->wq,&wait);
+			mutex_lock(&chip->mutex);
+			continue;
+		}
+
  		status = map_read(map, cmd_adr);
  		if (map_word_andequal(map, status, status_OK, status_OK))
  			break;

+		if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
+			/* Erase suspend occured while sleep: reset timeout */
+			timeo = reset_timeo;
+			chip->erase_suspended = 0;
+		}
+		if (chip->write_suspended&&  chip_state == FL_WRITING)  {
+			/* Write suspend occured while sleep: reset timeout */
+			timeo = reset_timeo;
+			chip->write_suspended = 0;
+		}
  		if (!timeo) {
  			map_write(map, CMD(0x70), cmd_adr);
  			chip->state = FL_STATUS;
@@ -1272,27 +1294,6 @@ static int inval_cache_and_wait_for_operation(
  			timeo--;
  		}
  		mutex_lock(&chip->mutex);
-
-		while (chip->state != chip_state) {
-			/* Someone's suspended the operation: sleep */
-			DECLARE_WAITQUEUE(wait, current);
-			set_current_state(TASK_UNINTERRUPTIBLE);
-			add_wait_queue(&chip->wq,&wait);
-			mutex_unlock(&chip->mutex);
-			schedule();
-			remove_wait_queue(&chip->wq,&wait);
-			mutex_lock(&chip->mutex);
-		}
-		if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
-			/* Erase suspend occured while sleep: reset timeout */
-			timeo = reset_timeo;
-			chip->erase_suspended = 0;
-		}
-		if (chip->write_suspended&&  chip_state == FL_WRITING)  {
-			/* Write suspend occured while sleep: reset timeout */
-			timeo = reset_timeo;
-			chip->write_suspended = 0;
-		}
  	}

3) Fix for errata regarding Flexlock Write Timing
-------------------------------------------------
This patch is not tested because the code is not called in my
test cases.

+       int ofs_factor = cfi->interleave * cfi->device_type;


+	/* address numonyx errata regarding Flexlock Write Timing.
+	   before doing a 0x60 lock/unlock sequence on a sector
+	   its current lock state needs to be read and the result
+          discarded. */
+       debug_map_write(map, CMD(0x90), adr+(2*ofs_factor));
+	chip->state = FL_JEDEC_QUERY;
+	(void) cfi_read_query(map, adr+(2*ofs_factor));


What are your plans?
Can I do some more tests?


Regards Stefan

Attached you find the small script creating a ubivolume write to it and delete it afterwards.

dd if=foofoo of=testfile bs=1024 count=1024
date
echo time ubimkvol /dev/ubi0 -s 6MiB -N test1
time ubimkvol /dev/ubi0 -s 6MiB -N test1
date
echo time cp testfile /dev/`cat /proc/mtd | grep test1 | sed 's/: .*//' | sed 's/mtd/mtdblock/'`
time cp testfile /dev/`cat /proc/mtd | grep test1 | sed 's/: .*//' | sed 's/mtd/mtdblock/'`
date
echo time ubirmvol /dev/ubi0 -N test1
time ubirmvol /dev/ubi0 -N test1


Am 02/06/2011 10:20 PM, schrieb Joakim Tjernlund:
> Michael Cashwell<mboards@prograde.net>  wrote on 2011/02/06 22:13:40:
>> On Feb 6, 2011, at 12:29 PM, Joakim Tjernlund wrote:
>>
>>> Michael Cashwell<mboards@prograde.net>  wrote on 2011/02/06 16:49:53:
>>>
>>>> That's clearly what's happening in Stefan's trace when thread 465 writes 0xe8 and the next write is 0x70 by thread 209. Such a sequence is absolutely illegal (for the flash) and the latter thread is the problem. If we could get a stack trace for that map_write 0x70 I think we'd find the thread
> awoke and touched the chip without verifying the state first. The question is why.
>>> Without my patch it is clear that you do end up with this problem. The first time one enter the for(;;) loop the driver reads out status from the chip before checking chip->state. This of course assumes that dropping the lock earlier may cause a schedule. So far Stefans tests indicates this to
> be true.
>> Yes, it was your patch and his log that lead me down that path!
>>
>>>> One last idea.
>>>>
>>>> The whole for(;;) loop in inval_cache_and_wait_for_operation() looks odd to me. Continuing with your idea of moving the chip->state while loop first, I see other problems. It seems to me that anywhere we drop and retake the chip mutex the very next thing needs to be the state check loop. Any
> break in holding that mutex means we must go back to the top and check state again.
>>>> I don't think the code as written does that. I have a completely reordered version of this function. (It didn't fix my issue but I think mine is something else.) On Monday I'll send that to you so you can consider it.
>>> Yes, it is a bit odd. In addition to my patch one could move the erase suspend tests before the if(!timeo) test.
>> Precisely. I suspect you may well already have my reordered version. :-)
> hehe, lets se(the barrier() is probably useless):
>
> diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
> index e89f2d0..73e29a3 100644
> --- a/drivers/mtd/chips/cfi_cmdset_0001.c
> +++ b/drivers/mtd/chips/cfi_cmdset_0001.c
> @@ -1243,12 +1243,34 @@ static int inval_cache_and_wait_for_operation(
>   		timeo = 500000;
>   	reset_timeo = timeo;
>   	sleep_time = chip_op_time / 2;
> -
> +	barrier(); /* make sure chip->state gets reloaded */
>   	for (;;) {
> +		if (chip->state != chip_state) {
> +			/* Someone's suspended the operation: sleep */
> +			DECLARE_WAITQUEUE(wait, current);
> +			set_current_state(TASK_UNINTERRUPTIBLE);
> +			add_wait_queue(&chip->wq,&wait);
> +			mutex_unlock(&chip->mutex);
> +			schedule();
> +			remove_wait_queue(&chip->wq,&wait);
> +			mutex_lock(&chip->mutex);
> +			continue;
> +		}
> +
>   		status = map_read(map, cmd_adr);
>   		if (map_word_andequal(map, status, status_OK, status_OK))
>   			break;
>
> +		if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
> +			/* Erase suspend occured while sleep: reset timeout */
> +			timeo = reset_timeo;
> +			chip->erase_suspended = 0;
> +		}
> +		if (chip->write_suspended&&  chip_state == FL_WRITING)  {
> +			/* Write suspend occured while sleep: reset timeout */
> +			timeo = reset_timeo;
> +			chip->write_suspended = 0;
> +		}
>   		if (!timeo) {
>   			map_write(map, CMD(0x70), cmd_adr);
>   			chip->state = FL_STATUS;
> @@ -1272,27 +1294,6 @@ static int inval_cache_and_wait_for_operation(
>   			timeo--;
>   		}
>   		mutex_lock(&chip->mutex);
> -
> -		while (chip->state != chip_state) {
> -			/* Someone's suspended the operation: sleep */
> -			DECLARE_WAITQUEUE(wait, current);
> -			set_current_state(TASK_UNINTERRUPTIBLE);
> -			add_wait_queue(&chip->wq,&wait);
> -			mutex_unlock(&chip->mutex);
> -			schedule();
> -			remove_wait_queue(&chip->wq,&wait);
> -			mutex_lock(&chip->mutex);
> -		}
> -		if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
> -			/* Erase suspend occured while sleep: reset timeout */
> -			timeo = reset_timeo;
> -			chip->erase_suspended = 0;
> -		}
> -		if (chip->write_suspended&&  chip_state == FL_WRITING)  {
> -			/* Write suspend occured while sleep: reset timeout */
> -			timeo = reset_timeo;
> -			chip->write_suspended = 0;
> -		}
>   	}
>
>   	/* Done and happy. */
>
>>>>> Oh, one more thing, possibly one needs to add cpu_relax() or similar to force gcc to reload chip->state in the while loop?
>>>> I was also wondering about possible gcc optimization issues. I'm on 4.5.2 and that worked for me with the 2003 flash part. The same binaries fail with the 2008 parts, so, I don't know.
>>> Very recent gcc, I am 3.4.6 but recently I began testing a little with 4.5.2. I do think I will wait for 4.5.3
>> I tried 4.5.1 but it failed for other reasons. I submitted bug reports to gnu and a fix appeared (finally) in 4.5.2. It's been good so far but I'm always mindful of that issue.
>>
>> Staying current is a two edge sword. In general, later gccs have better code analysis and warnings which are valuable even if we ship using an older version.
> Precisely, but later gcc is worse optimizing trivial code.
>
>>>> Keep in mind that chip->state is not a hardware access. It's just another struct member. And I think that the rules are that any function call counts as a sequence point and gcc isn't allowed to think it knows what the result is and must reload it.
>>>>
>>>> Lastly, consider the direction of the behavior. If we're in the state-check while loop then we got there because the two things were NOT equal. If an optimization error is causing a stale value to be compared wouldn't the observed behavior be that it remains not equal? (If it's not reloaded
> then how could it change?)
>>>> I'd expect an optimization error like that to get us stuck in the while loop, not exit from it prematurely.
>>> Yes, all true. I wonder though if the mutex lock/unlock counts as a reload point? These are usually some inline asm. If not one could possibly argue that the first chip->state access, before entering the while body is using an old value.
>> Yes, how inlines interact with sequence points has never been entirely clear to me. Especially since the compiler is free to inline something I didn't tell it to and to ignore me telling to inline if it wants to.
>>
>> I *think* the rules are semantic. If it's written (preprocessor aside) to look like a function call then it counts as a sequence point even if it ends up being inlined. But that's all quite beyond anything I can say for sure!
> That makes sense too.
>
>>>> Makes me head hurt!
>>> You are not alone :)
>> So collectively maybe we can make it hurt less. That's my theory, anyway, and I'm sticking to it.
> :)
>

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/07 15:47:00:
>
> Hi
>
> I run the test on my side with the patches proposed with and without
> barrier().
> Both worked without problems.

Thanks for testing.

>
> My workspace has now the following patches:
>
> 1) clear status before suspend
> ------------------------------
> +    /* numonyx data sheet clearly says to always reset the status bits
> +       before resuming a suspended erase. not doing so results in
> +       an ambiguous mixture of status bits once the command ends. */
> +    debug_map_write(map, CMD(0x50), adr);
> +    debug_map_write(map, CMD(0xd0), adr);

The 0xd0 seems should not be there, its already in place?
it does seem like a good idea to add a Clear Status to be sure you
won't end up with error bits set just before resume.
This is a separate patch though. Does your test case work without this patch
and only my patch applied?

>
>
> 2) compare chip>state and chip_state before touching the chip
> ------------------------------------------------------------

I plan to submit this one shortly, if you and Michael could Ack.
it when I do, that would be great.

>
> diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
> index e89f2d0..73e29a3 100644
> --- a/drivers/mtd/chips/cfi_cmdset_0001.c
> +++ b/drivers/mtd/chips/cfi_cmdset_0001.c
> @@ -1243,12 +1243,34 @@ static int inval_cache_and_wait_for_operation(
>         timeo = 500000;
>      reset_timeo = timeo;
>      sleep_time = chip_op_time / 2;
> -
> +   barrier(); /* make sure chip->state gets reloaded */
>      for (;;) {
> +      if (chip->state != chip_state) {
> +         /* Someone's suspended the operation: sleep */
> +         DECLARE_WAITQUEUE(wait, current);
> +         set_current_state(TASK_UNINTERRUPTIBLE);
> +         add_wait_queue(&chip->wq,&wait);
> +         mutex_unlock(&chip->mutex);
> +         schedule();
> +         remove_wait_queue(&chip->wq,&wait);
> +         mutex_lock(&chip->mutex);
> +         continue;
> +      }
> +
>         status = map_read(map, cmd_adr);
>         if (map_word_andequal(map, status, status_OK, status_OK))
>            break;
>
> +      if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
> +         /* Erase suspend occured while sleep: reset timeout */
> +         timeo = reset_timeo;
> +         chip->erase_suspended = 0;
> +      }
> +      if (chip->write_suspended&&  chip_state == FL_WRITING)  {
> +         /* Write suspend occured while sleep: reset timeout */
> +         timeo = reset_timeo;
> +         chip->write_suspended = 0;
> +      }
>         if (!timeo) {
>            map_write(map, CMD(0x70), cmd_adr);
>            chip->state = FL_STATUS;
> @@ -1272,27 +1294,6 @@ static int inval_cache_and_wait_for_operation(
>            timeo--;
>         }
>         mutex_lock(&chip->mutex);
> -
> -      while (chip->state != chip_state) {
> -         /* Someone's suspended the operation: sleep */
> -         DECLARE_WAITQUEUE(wait, current);
> -         set_current_state(TASK_UNINTERRUPTIBLE);
> -         add_wait_queue(&chip->wq,&wait);
> -         mutex_unlock(&chip->mutex);
> -         schedule();
> -         remove_wait_queue(&chip->wq,&wait);
> -         mutex_lock(&chip->mutex);
> -      }
> -      if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
> -         /* Erase suspend occured while sleep: reset timeout */
> -         timeo = reset_timeo;
> -         chip->erase_suspended = 0;
> -      }
> -      if (chip->write_suspended&&  chip_state == FL_WRITING)  {
> -         /* Write suspend occured while sleep: reset timeout */
> -         timeo = reset_timeo;
> -         chip->write_suspended = 0;
> -      }
>      }
>
> 3) Fix for errata regarding Flexlock Write Timing
> -------------------------------------------------
> This patch is not tested because the code is not called in my
> test cases.

Same here.

>
> +       int ofs_factor = cfi->interleave * cfi->device_type;
>
>
> +   /* address numonyx errata regarding Flexlock Write Timing.
> +      before doing a 0x60 lock/unlock sequence on a sector
> +      its current lock state needs to be read and the result
> +          discarded. */
> +       debug_map_write(map, CMD(0x90), adr+(2*ofs_factor));
> +   chip->state = FL_JEDEC_QUERY;
> +   (void) cfi_read_query(map, adr+(2*ofs_factor));
>
>
> What are your plans?
> Can I do some more tests?
>
>
> Regards Stefan
>
> Attached you find the small script creating a ubivolume write to it and delete it afterwards.
>
> dd if=foofoo of=testfile bs=1024 count=1024
> date
> echo time ubimkvol /dev/ubi0 -s 6MiB -N test1
> time ubimkvol /dev/ubi0 -s 6MiB -N test1
> date
> echo time cp testfile /dev/`cat /proc/mtd | grep test1 | sed 's/: .*//' | sed 's/mtd/mtdblock/'`
> time cp testfile /dev/`cat /proc/mtd | grep test1 | sed 's/: .*//' | sed 's/mtd/mtdblock/'`
> date
> echo time ubirmvol /dev/ubi0 -N test1
> time ubirmvol /dev/ubi0 -N test1
>
>
> Am 02/06/2011 10:20 PM, schrieb Joakim Tjernlund:
> > Michael Cashwell<mboards@prograde.net>  wrote on 2011/02/06 22:13:40:
> >> On Feb 6, 2011, at 12:29 PM, Joakim Tjernlund wrote:
> >>
> >>> Michael Cashwell<mboards@prograde.net>  wrote on 2011/02/06 16:49:53:
> >>>
> >>>> That's clearly what's happening in Stefan's trace when thread 465 writes 0xe8 and the next write is 0x70 by thread 209. Such a sequence is absolutely illegal (for the flash) and the latter thread is the problem. If we could get a stack trace for that map_write 0x70 I think we'd find the
thread
> > awoke and touched the chip without verifying the state first. The question is why.
> >>> Without my patch it is clear that you do end up with this problem. The first time one enter the for(;;) loop the driver reads out status from the chip before checking chip->state. This of course assumes that dropping the lock earlier may cause a schedule. So far Stefans tests indicates this to
> > be true.
> >> Yes, it was your patch and his log that lead me down that path!
> >>
> >>>> One last idea.
> >>>>
> >>>> The whole for(;;) loop in inval_cache_and_wait_for_operation() looks odd to me. Continuing with your idea of moving the chip->state while loop first, I see other problems. It seems to me that anywhere we drop and retake the chip mutex the very next thing needs to be the state check loop. Any
> > break in holding that mutex means we must go back to the top and check state again.
> >>>> I don't think the code as written does that. I have a completely reordered version of this function. (It didn't fix my issue but I think mine is something else.) On Monday I'll send that to you so you can consider it.
> >>> Yes, it is a bit odd. In addition to my patch one could move the erase suspend tests before the if(!timeo) test.
> >> Precisely. I suspect you may well already have my reordered version. :-)
> > hehe, lets se(the barrier() is probably useless):
> >
> > diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
> > index e89f2d0..73e29a3 100644
> > --- a/drivers/mtd/chips/cfi_cmdset_0001.c
> > +++ b/drivers/mtd/chips/cfi_cmdset_0001.c
> > @@ -1243,12 +1243,34 @@ static int inval_cache_and_wait_for_operation(
> >         timeo = 500000;
> >      reset_timeo = timeo;
> >      sleep_time = chip_op_time / 2;
> > -
> > +   barrier(); /* make sure chip->state gets reloaded */
> >      for (;;) {
> > +      if (chip->state != chip_state) {
> > +         /* Someone's suspended the operation: sleep */
> > +         DECLARE_WAITQUEUE(wait, current);
> > +         set_current_state(TASK_UNINTERRUPTIBLE);
> > +         add_wait_queue(&chip->wq,&wait);
> > +         mutex_unlock(&chip->mutex);
> > +         schedule();
> > +         remove_wait_queue(&chip->wq,&wait);
> > +         mutex_lock(&chip->mutex);
> > +         continue;
> > +      }
> > +
> >         status = map_read(map, cmd_adr);
> >         if (map_word_andequal(map, status, status_OK, status_OK))
> >            break;
> >
> > +      if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
> > +         /* Erase suspend occured while sleep: reset timeout */
> > +         timeo = reset_timeo;
> > +         chip->erase_suspended = 0;
> > +      }
> > +      if (chip->write_suspended&&  chip_state == FL_WRITING)  {
> > +         /* Write suspend occured while sleep: reset timeout */
> > +         timeo = reset_timeo;
> > +         chip->write_suspended = 0;
> > +      }
> >         if (!timeo) {
> >            map_write(map, CMD(0x70), cmd_adr);
> >            chip->state = FL_STATUS;
> > @@ -1272,27 +1294,6 @@ static int inval_cache_and_wait_for_operation(
> >            timeo--;
> >         }
> >         mutex_lock(&chip->mutex);
> > -
> > -      while (chip->state != chip_state) {
> > -         /* Someone's suspended the operation: sleep */
> > -         DECLARE_WAITQUEUE(wait, current);
> > -         set_current_state(TASK_UNINTERRUPTIBLE);
> > -         add_wait_queue(&chip->wq,&wait);
> > -         mutex_unlock(&chip->mutex);
> > -         schedule();
> > -         remove_wait_queue(&chip->wq,&wait);
> > -         mutex_lock(&chip->mutex);
> > -      }
> > -      if (chip->erase_suspended&&  chip_state == FL_ERASING)  {
> > -         /* Erase suspend occured while sleep: reset timeout */
> > -         timeo = reset_timeo;
> > -         chip->erase_suspended = 0;
> > -      }
> > -      if (chip->write_suspended&&  chip_state == FL_WRITING)  {
> > -         /* Write suspend occured while sleep: reset timeout */
> > -         timeo = reset_timeo;
> > -         chip->write_suspended = 0;
> > -      }
> >      }
> >
> >      /* Done and happy. */
> >
> >>>>> Oh, one more thing, possibly one needs to add cpu_relax() or similar to force gcc to reload chip->state in the while loop?
> >>>> I was also wondering about possible gcc optimization issues. I'm on 4.5.2 and that worked for me with the 2003 flash part. The same binaries fail with the 2008 parts, so, I don't know.
> >>> Very recent gcc, I am 3.4.6 but recently I began testing a little with 4.5.2. I do think I will wait for 4.5.3
> >> I tried 4.5.1 but it failed for other reasons. I submitted bug reports to gnu and a fix appeared (finally) in 4.5.2. It's been good so far but I'm always mindful of that issue.
> >>
> >> Staying current is a two edge sword. In general, later gccs have better code analysis and warnings which are valuable even if we ship using an older version.
> > Precisely, but later gcc is worse optimizing trivial code.
> >
> >>>> Keep in mind that chip->state is not a hardware access. It's just another struct member. And I think that the rules are that any function call counts as a sequence point and gcc isn't allowed to think it knows what the result is and must reload it.
> >>>>
> >>>> Lastly, consider the direction of the behavior. If we're in the state-check while loop then we got there because the two things were NOT equal. If an optimization error is causing a stale value to be compared wouldn't the observed behavior be that it remains not equal? (If it's not reloaded
> > then how could it change?)
> >>>> I'd expect an optimization error like that to get us stuck in the while loop, not exit from it prematurely.
> >>> Yes, all true. I wonder though if the mutex lock/unlock counts as a reload point? These are usually some inline asm. If not one could possibly argue that the first chip->state access, before entering the while body is using an old value.
> >> Yes, how inlines interact with sequence points has never been entirely clear to me. Especially since the compiler is free to inline something I didn't tell it to and to ignore me telling to inline if it wants to.
> >>
> >> I *think* the rules are semantic. If it's written (preprocessor aside) to look like a function call then it counts as a sequence point even if it ends up being inlined. But that's all quite beyond anything I can say for sure!
> > That makes sense too.
> >
> >>>> Makes me head hurt!
> >>> You are not alone :)
> >> So collectively maybe we can make it hurt less. That's my theory, anyway, and I'm sticking to it.
> > :)
> >
>

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 7, 2011, at 10:01 AM, Joakim Tjernlund wrote:

> Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/07 15:47:00:
>> 
> 
>> I run the test on my side with the patches proposed with and without barrier().
>> Both worked without problems.
> 
> Thanks for testing.

So that means moving the chip state while loop first solves the problem for both of you. That's good news and makes it more likely that you are seeing the same issue. I'm OK that it doesn't fix my issue. It's seemed different from the beginning.

>> My workspace has now the following patches:
>> 
>> 1) clear status before suspend

No, before erase resume.

>> ------------------------------
>> +    /* numonyx data sheet clearly says to always reset the status bits
>> +       before resuming a suspended erase. not doing so results in
>> +       an ambiguous mixture of status bits once the command ends. */
>> +    debug_map_write(map, CMD(0x50), adr);
>> +    debug_map_write(map, CMD(0xd0), adr);
> 
> The 0xd0 seems should not be there, its already in place?

I think he meant the 0xd0 line to be context, not added. So maybe the + was wrong?

My current workaround from my problem is to do a throw-away status read "(void) map_read(map, addr);" after that 0x50, 0xd0, 0x70 sequence.

Since no one else is seeing my problem I expect it's some issue with my specific batch of chips. Ugh.

> it does seem like a good idea to add a Clear Status to be sure you won't end up with error bits set just before resume.
> This is a separate patch though. Does your test case work without this patch and only my patch applied?
> 
>> 2) compare chip>state and chip_state before touching the chip
>> ------------------------------------------------------------
> 
> I plan to submit this one shortly, if you and Michael could Ack. it when I do, that would be great.

Happy to test and ack when it arrives.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi

Am 02/07/2011 04:46 PM, schrieb Michael Cashwell:
>>> ------------------------------
>>> +    /* numonyx data sheet clearly says to always reset the status bits
>>> +       before resuming a suspended erase. not doing so results in
>>> +       an ambiguous mixture of status bits once the command ends. */
>>> +    debug_map_write(map, CMD(0x50), adr);
>>> +    debug_map_write(map, CMD(0xd0), adr);
>> The 0xd0 seems should not be there, its already in place?

Sorry the 0x0d was already there.

>> I plan to submit this one shortly, if you and Michael could Ack. it when I do, that would be great.
> Happy to test and ack when it arrives.
>
> -Mike
>
Looking forward to do so.

Stefan

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/07 16:46:22:
>
> On Feb 7, 2011, at 10:01 AM, Joakim Tjernlund wrote:
>
> > Stefan Bigler <stefan.bigler@keymile.com> wrote on 2011/02/07 15:47:00:

>
> My current workaround from my problem is to do a throw-away status read "(void) map_read(map, addr);" after that 0x50, 0xd0, 0x70 sequence.
>
> Since no one else is seeing my problem I expect it's some issue with my specific batch of chips. Ugh.

Possibly, or an accident waiting to happen to the rest of us.
The map_read will probably force some HW completion. Perhaps some sync() op. will do the same? Just to nail it down.

BTW, do you have CONFIG_MTD_COMPLEX_MAPPINGS=y ? I do

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 7, 2011, at 11:22 AM, Joakim Tjernlund wrote:

> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/07 16:46:22:
> 
>> My current workaround from my problem is to do a throw-away status read "(void) map_read(map, addr);" after that 0x50, 0xd0, 0x70 sequence. Since no one else is seeing my problem I expect it's some issue with my specific batch of chips. Ugh.
> 
> Possibly, or an accident waiting to happen to the rest of us.

That does worry me too.

> The map_read will probably force some HW completion. Perhaps some sync() op. will do the same? Just to nail it down.

Once your patch is handled I will continue to try to fully explain my issue. I'm not giving up yet.

> BTW, do you have CONFIG_MTD_COMPLEX_MAPPINGS=y ? I do

Interesting. I have used that on a different platform where some of the high-order address lines were GPIOs.

But no, I'm not using that in this case. Just a simple linear mapping of the whole part.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Stefan Bigler]

Hi Mike

I attached a patch for you adding some printk, with those already the 
creation of the first ubivolume goes wrong.
Is this also the case in your setup?

Regards Stefan

Subject: [PATCH 2/2] MTD: cfi_cmdset_0001 driver add tracing

This tracing force in my case a race condition. When I create
a ubivolume.

Signed-off-by: Stefan Bigler <stefan.bigler@keymile.com>
---
  drivers/mtd/chips/cfi_cmdset_0001.c |   15 +++++++++++++++
  1 files changed, 15 insertions(+), 0 deletions(-)

diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c 
b/drivers/mtd/chips/cfi_cmdset_0001.c
index d3b2cd3..ea59726 100644
--- a/drivers/mtd/chips/cfi_cmdset_0001.c
+++ b/drivers/mtd/chips/cfi_cmdset_0001.c
@@ -37,6 +37,8 @@
  #include <linux/mtd/compatmac.h>
  #include <linux/mtd/cfi.h>

+#include <linux/syscalls.h>
+
  /* #define CMDSET0001_DISABLE_ERASE_SUSPEND_ON_WRITE */
  /* #define CMDSET0001_DISABLE_WRITE_SUSPEND */

@@ -799,6 +801,8 @@ static int chip_ready (struct map_info *map, struct 
flchip *chip, unsigned long

          /* Erase suspend */
          map_write(map, CMD(0xB0), adr);
+        printk("[%10u][%04ld] erase suspend 1         adr=0x%08lx\n",
+               jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr);

          /* If the flash has finished erasing, then 'erase suspend'
           * appears to make some (28F320) flash devices switch to
@@ -1012,6 +1016,10 @@ static void put_chip(struct map_info *map, struct 
flchip *chip, unsigned long ad
             do. */
          map_write(map, CMD(0xd0), adr);
          map_write(map, CMD(0x70), adr);
+
+        printk("[%10u][%04ld] erase resumed 2b        adr=0x%08lx\n",
+               jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr);
+
          chip->oldstate = FL_READY;
          chip->state = FL_ERASING;
          break;
@@ -1884,6 +1892,10 @@ static int __xipram do_erase_oneblock(struct 
map_info *map, struct flchip *chip,
   retry:
      mutex_lock(&chip->mutex);
      ret = get_chip(map, chip, adr, FL_ERASING);
+
+    printk("[%10u][%04ld] do_erase_oneblock start adr=0x%08lx len=0x%x\n",
+           jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr, len);
+
      if (ret) {
          mutex_unlock(&chip->mutex);
          return ret;
@@ -1953,6 +1965,9 @@ static int __xipram do_erase_oneblock(struct 
map_info *map, struct flchip *chip,

      xip_enable(map, chip, adr);
   out:    put_chip(map, chip, adr);
+    printk("[%10u][%04ld] do_erase_oneblock end   adr=0x%08lx len=0x%x 
\n",
+        jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr, len);
+
      mutex_unlock(&chip->mutex);
      return ret;
  }
-- 
1.7.0.5

Am 02/07/2011 05:46 PM, schrieb Michael Cashwell:
> On Feb 7, 2011, at 11:22 AM, Joakim Tjernlund wrote:
>
>> Michael Cashwell<mboards@prograde.net>  wrote on 2011/02/07 16:46:22:
>>
>>> My current workaround from my problem is to do a throw-away status read "(void) map_read(map, addr);" after that 0x50, 0xd0, 0x70 sequence. Since no one else is seeing my problem I expect it's some issue with my specific batch of chips. Ugh.
>>
>> Possibly, or an accident waiting to happen to the rest of us.
>
> That does worry me too.
>
>> The map_read will probably force some HW completion. Perhaps some sync() op. will do the same? Just to nail it down.
>
> Once your patch is handled I will continue to try to fully explain my issue. I'm not giving up yet.
>
>> BTW, do you have CONFIG_MTD_COMPLEX_MAPPINGS=y ? I do
>
> Interesting. I have used that on a different platform where some of the high-order address lines were GPIOs.
>
> But no, I'm not using that in this case. Just a simple linear mapping of the whole part.
>
> -Mike
>

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 7, 2011, at 12:08 PM, Stefan Bigler wrote:

> Hi Mike
> 
> I attached a patch for you adding some printk, with those already the creation of the first ubivolume goes wrong.
> Is this also the case in your setup?

Greetings and thanks,

Unfortunately, as I've seen before, adding printks tends to make my problem go away, particularly right after the 0xd0 erase resume command. That's the same place that I also found calls like udelay(20) and (void) map_read() of status also hide the failure. (On a lark, I just tried doing that print just before the resume command but it made no difference.)

To avoid masking the failure I think I need to collect information into a static buffer and printk the buffered data only on the error path. That way, the timing of the code hopefully won't change enough to hide the problem. That's more complicated to do, of course.

More as I find it.

-Mike

> Subject: [PATCH 2/2] MTD: cfi_cmdset_0001 driver add tracing
> 
> This tracing force in my case a race condition. When I create
> a ubivolume.
> 
> Signed-off-by: Stefan Bigler <stefan.bigler@keymile.com>
> ---
> drivers/mtd/chips/cfi_cmdset_0001.c |   15 +++++++++++++++
> 1 files changed, 15 insertions(+), 0 deletions(-)
> 
> diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
> index d3b2cd3..ea59726 100644
> --- a/drivers/mtd/chips/cfi_cmdset_0001.c
> +++ b/drivers/mtd/chips/cfi_cmdset_0001.c
> @@ -37,6 +37,8 @@
> #include <linux/mtd/compatmac.h>
> #include <linux/mtd/cfi.h>
> 
> +#include <linux/syscalls.h>
> +
> /* #define CMDSET0001_DISABLE_ERASE_SUSPEND_ON_WRITE */
> /* #define CMDSET0001_DISABLE_WRITE_SUSPEND */
> 
> @@ -799,6 +801,8 @@ static int chip_ready (struct map_info *map, struct flchip *chip, unsigned long
> 
>         /* Erase suspend */
>         map_write(map, CMD(0xB0), adr);
> +        printk("[%10u][%04ld] erase suspend 1         adr=0x%08lx\n",
> +               jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr);
> 
>         /* If the flash has finished erasing, then 'erase suspend'
>          * appears to make some (28F320) flash devices switch to
> @@ -1012,6 +1016,10 @@ static void put_chip(struct map_info *map, struct flchip *chip, unsigned long ad
>            do. */
>         map_write(map, CMD(0xd0), adr);
>         map_write(map, CMD(0x70), adr);
> +
> +        printk("[%10u][%04ld] erase resumed 2b        adr=0x%08lx\n",
> +               jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr);
> +
>         chip->oldstate = FL_READY;
>         chip->state = FL_ERASING;
>         break;
> @@ -1884,6 +1892,10 @@ static int __xipram do_erase_oneblock(struct map_info *map, struct flchip *chip,
>  retry:
>     mutex_lock(&chip->mutex);
>     ret = get_chip(map, chip, adr, FL_ERASING);
> +
> +    printk("[%10u][%04ld] do_erase_oneblock start adr=0x%08lx len=0x%x\n",
> +           jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr, len);
> +
>     if (ret) {
>         mutex_unlock(&chip->mutex);
>         return ret;
> @@ -1953,6 +1965,9 @@ static int __xipram do_erase_oneblock(struct map_info *map, struct flchip *chip,
> 
>     xip_enable(map, chip, adr);
>  out:    put_chip(map, chip, adr);
> +    printk("[%10u][%04ld] do_erase_oneblock end   adr=0x%08lx len=0x%x \n",
> +        jiffies_to_usecs(jiffies)/1000, sys_gettid(), adr, len);
> +
>     mutex_unlock(&chip->mutex);
>     return ret;
> }
> -- 
> 1.7.0.5
> 
> Am 02/07/2011 05:46 PM, schrieb Michael Cashwell:
>> On Feb 7, 2011, at 11:22 AM, Joakim Tjernlund wrote:
>> 
>>> Michael Cashwell<mboards@prograde.net>  wrote on 2011/02/07 16:46:22:
>>> 
>>>> My current workaround from my problem is to do a throw-away status read "(void) map_read(map, addr);" after that 0x50, 0xd0, 0x70 sequence. Since no one else is seeing my problem I expect it's some issue with my specific batch of chips. Ugh.
>>> 
>>> Possibly, or an accident waiting to happen to the rest of us.
>> 
>> That does worry me too.
>> 
>>> The map_read will probably force some HW completion. Perhaps some sync() op. will do the same? Just to nail it down.
>> 
>> Once your patch is handled I will continue to try to fully explain my issue. I'm not giving up yet.
>> 
>>> BTW, do you have CONFIG_MTD_COMPLEX_MAPPINGS=y ? I do
>> 
>> Interesting. I have used that on a different platform where some of the high-order address lines were GPIOs.
>> 
>> But no, I'm not using that in this case. Just a simple linear mapping of the whole part.
>> 
>> -Mike
>> 
> ______________________________________________________
> Linux MTD discussion mailing list
> http://lists.infradead.org/mailman/listinfo/linux-mtd/

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 7, 2011, at 2:04 PM, Michael Cashwell wrote:

> To avoid masking the failure I think I need to collect information into a static buffer and printk the buffered data only on the error path. That way, the timing of the code hopefully won't change enough to hide the problem. That's more complicated to do, of course.
> 
> More as I find it.

I added a simple buffer to log the last N map_writes() in cfi_cmdset_0001.c. As expected, I had to be very selective about what and how much to log and the logging code itself could take enough on the hot path to make my failure vanish. But I have been able to distill down the results.

It doesn't look like a threading/locking/mutex problem after all. It looks like a straight timing issue on these chips. Here's my reduced log:

Dumping flash write history:
... ongoing write buffer data ...
...cfi_cmdset_0001.c line 1793 writes 216c  <     last data word
...cfi_cmdset_0001.c line 1808 writes 00d0  <---  write confirm
...cfi_cmdset_0001.c line 1051 writes 0050  +	  presumably the buffer write finished and called put_chip.
...cfi_cmdset_0001.c line 1052 writes 00d0  + <-- put_chip(), oldstate FL_ERASING -> erase resume.
...cfi_cmdset_0001.c line 1053 writes 0070  +     == 20µs delay or discard-read of status register here hides problem ===
...cfi_cmdset_0001.c line 832 writes 00b0   <---| erase suspend.
...cfi_cmdset_0001.c line 839 writes 0070   <---| presumably in get_chip/chip_ready for FL_WRITING at start of
...cfi_cmdset_0001.c line 1743 writes 00e8  <---  buffer write
...cfi_cmdset_0001.c line 1771 writes 01ff  <---  number of words
...cfi_cmdset_0001.c line 1793 writes 0001  <     data word 1
... 510 words of data ...
...cfi_cmdset_0001.c line 1793 writes 5c0c  <     data word 512
...cfi_cmdset_0001.c line 1808 writes 00d0  <---  write confirm
...cfi_cmdset_0001.c line 1829 writes 0050  +     write error path
...cfi_cmdset_0001.c line 1830 writes 0070  +     write error has been sensed
NOR Flash: buffer write error (block locked) status 0xffff (priv = (null), chip = c7cf2ef8)
UBI error: ubi_io_write: error -30 while writing 1960 bytes to PEB 30:57800, written 568 bytes
UBI warning: ubi_eba_write_leb: failed to write data to PEB 30
UBI warning: ubi_ro_mode: switch to read-only mode
UBIFS error (pid 404): ubifs_wbuf_write_nolock: cannot write 1956 bytes to LEB 17:57664, error -30
UBIFS warning (pid 404): ubifs_ro_mode: switched to read-only mode, error -30

So when a buffered write fails, it's when the previous write suspended an erase. But more specifically, it seems that if the suspended erase is resumed and then immediately suspended again things go off the rails. This is between entries for lines 1053 and 832 above.

The chip seems to malfunction if an erase-resume is followed "too soon" by an erase-suspend.

I'd like to do things like sys_gettid() or perhaps get_timeofday() but I find that if I log more than 2 words per map_write() the failure is masked. Still working on that.

The only other thing I've done is ensure that following an erase-suspend for (;;) loop that map_word_bitset(map, status, CMD(0x40)) is true. If not then the erase that was being suspended completed instead (which can happen according to the data sheet). That assertion has not failed in my testing so that's not my problem.

I'm still digging but it's really looking like a straight timing problem with this batch of chips. At what point should I declare defeat and propose my simple fix even though it's just for these chips? The file has several instances of similar "Parts XYZ act funny without this even though it should be unnecessary" workarounds.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

linux-mtd-bounces@lists.infradead.org wrote on 2011/02/09 20:52:23:

> From: Michael Cashwell <mboards@prograde.net>
> To: Michael Cashwell <mboards@prograde.net>
> Cc: linux-mtd@lists.infradead.org, Holger brunck <holger.brunck@keymile.com>, stefan.bigler@keymile.com, Joakim Tjernlund <joakim.tjernlund@transmode.se>
> Date: 2011/02/09 20:56
> Subject: Re: Numonyx NOR and chip->mutex bug?
> Sent by: linux-mtd-bounces@lists.infradead.org
>
> On Feb 7, 2011, at 2:04 PM, Michael Cashwell wrote:
>
> > To avoid masking the failure I think I need to collect information into a static buffer and printk the buffered data only on the error path. That way, the timing of the code hopefully won't change enough to hide the problem. That's more complicated to do, of course.
> >
> > More as I find it.
>
> I added a simple buffer to log the last N map_writes() in cfi_cmdset_0001.c. As expected, I had to be very selective about what and how much to log and the logging code itself could take enough on the hot path to make my failure vanish. But I have been able to distill down the results.
>
> It doesn't look like a threading/locking/mutex problem after all. It looks like a straight timing issue on these chips. Here's my reduced log:
>
> Dumping flash write history:
> ... ongoing write buffer data ...
> ...cfi_cmdset_0001.c line 1793 writes 216c  <     last data word
> ...cfi_cmdset_0001.c line 1808 writes 00d0  <---  write confirm
> ...cfi_cmdset_0001.c line 1051 writes 0050  +     presumably the buffer write finished and called put_chip.
> ...cfi_cmdset_0001.c line 1052 writes 00d0  + <-- put_chip(), oldstate FL_ERASING -> erase resume.
> ...cfi_cmdset_0001.c line 1053 writes 0070  +     == 20µs delay or discard-read of status register here hides problem ===
> ...cfi_cmdset_0001.c line 832 writes 00b0   <---| erase suspend.
> ...cfi_cmdset_0001.c line 839 writes 0070   <---| presumably in get_chip/chip_ready for FL_WRITING at start of
> ...cfi_cmdset_0001.c line 1743 writes 00e8  <---  buffer write
> ...cfi_cmdset_0001.c line 1771 writes 01ff  <---  number of words
> ...cfi_cmdset_0001.c line 1793 writes 0001  <     data word 1
> ... 510 words of data ...
> ...cfi_cmdset_0001.c line 1793 writes 5c0c  <     data word 512
> ...cfi_cmdset_0001.c line 1808 writes 00d0  <---  write confirm
> ...cfi_cmdset_0001.c line 1829 writes 0050  +     write error path
> ...cfi_cmdset_0001.c line 1830 writes 0070  +     write error has been sensed
> NOR Flash: buffer write error (block locked) status 0xffff (priv = (null), chip = c7cf2ef8)
> UBI error: ubi_io_write: error -30 while writing 1960 bytes to PEB 30:57800, written 568 bytes
> UBI warning: ubi_eba_write_leb: failed to write data to PEB 30
> UBI warning: ubi_ro_mode: switch to read-only mode
> UBIFS error (pid 404): ubifs_wbuf_write_nolock: cannot write 1956 bytes to LEB 17:57664, error -30
> UBIFS warning (pid 404): ubifs_ro_mode: switched to read-only mode, error -30
>
> So when a buffered write fails, it's when the previous write suspended an erase. But more specifically, it seems that if the suspended erase is resumed and then immediately suspended again things go off the rails. This is between entries for lines 1053 and 832 above.
>
> The chip seems to malfunction if an erase-resume is followed "too soon" by an erase-suspend.
>
> I'd like to do things like sys_gettid() or perhaps get_timeofday() but I find that if I log more than 2 words per map_write() the failure is masked. Still working on that.
>
> The only other thing I've done is ensure that following an erase-suspend for (;;) loop that map_word_bitset(map, status, CMD(0x40)) is true. If not then the erase that was being suspended completed instead (which can happen according to the data sheet). That assertion has not failed in my testing
so that's not my problem.
>
> I'm still digging but it's really looking like a straight timing problem with this batch of chips. At what point should I declare defeat and propose my simple fix even though it's just for these chips? The file has several instances of similar "Parts XYZ act funny without this even though it
should be unnecessary" workarounds.
>
> -Mike

hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)

5. W602: erase suspend resume operation
Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
        due to an internal firmware issue that is exhibited in certain applications that require at
       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
                does not damage the device in any way, but data in the block may be disturbed from its
               original state.
Workaround: If such an erase failure occurs, customer should retry the erase with an increase to the
Tres (W602) spec from 500uS to 1mS. If the device still fails, continue to increase Tres
in increments of 500uS up to a maximum Tres of 2.5mS. Once the failing block passes,
subsequent blocks should revert back to original erase algorithm and timing for Tres
(500uS typical).
Status:
June 2008
309045-09
This erratum does not apply to material marked with an FPO code dated x806xxxx or
later.

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 9, 2011, at 3:13 PM, Joakim Tjernlund wrote:

> hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)
> 
> 5. W602: erase suspend resume operation
> Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
>        due to an internal firmware issue that is exhibited in certain applications that require at
>       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
> Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
>                does not damage the device in any way, but data in the block may be disturbed from its
>               original state.
> Workaround: If such an erase failure occurs, customer should retry the erase with an increase to the
> Tres (W602) spec from 500uS to 1mS. If the device still fails, continue to increase Tres
> in increments of 500uS up to a maximum Tres of 2.5mS. Once the failing block passes,
> subsequent blocks should revert back to original erase algorithm and timing for Tres
> (500uS typical).
> Status:
> June 2008
> 309045-09
> This erratum does not apply to material marked with an FPO code dated x806xxxx or
> later.

Interesting. Thanks for the URL. I'll explore it. I have a 2009 errata sheet but had not seen the 2008 one. (I'm wondering if that's because your's is for a batch of the older 130nm parts which are no longer made. Just guessing.)

It doesn't match exactly, since I'm not seeing erase failures. I'm seeing buffered write failures where, after the 0xd0 Write Confirm command I get back nonsense status. (See the 0xffff reported in my log. I've also seen many values other than 0xffff.)

So the the program operation (0xe8) begins OK, the count and data are written, the confirm command is written but then the status read reads as junk. I'm thinking about adding status-read logs to my buffer if I can do it without disturbing the timing.

The reason that status is nonsense in the status register is only in the lower 8 bits. If it's in read-status mode (which it should be) we should never see any set bits in the upper byte. Because I do see such bits I've suspected from the start that somehow the part is exiting the status-read mode and returning array-read mode when it should not. (My very first post mentions this suspicion.)

One more log point I think I may check is to count and report the number of suspend/resumes for each erase. It would be interesting to see if some sort of spike in that count correlates with my failures.

More as I find it.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Anders Grafström]

On 2011-02-09 22:59, Michael Cashwell wrote:
> On Feb 9, 2011, at 3:13 PM, Joakim Tjernlund wrote:
> 
>> hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)
>>
>> 5. W602: erase suspend resume operation
>> Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
>>        due to an internal firmware issue that is exhibited in certain applications that require at
>>       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
>> Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
>>                does not damage the device in any way, but data in the block may be disturbed from its
>>               original state.

I've seen this issue with Intel 28F640J5 chips as well.

There's an old thread on it.
http://lists.infradead.org/pipermail/linux-mtd/2008-April/021266.html

A delay was suggested similar to the one you're experimenting with I think.
http://lists.infradead.org/pipermail/linux-mtd/2008-April/021436.html

/Anders

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 14:21:36:
>
> On 2011-02-09 22:59, Michael Cashwell wrote:
> > On Feb 9, 2011, at 3:13 PM, Joakim Tjernlund wrote:
> >
> >> hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)
> >>
> >> 5. W602: erase suspend resume operation
> >> Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
> >>        due to an internal firmware issue that is exhibited in certain applications that require at
> >>       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
> >> Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
> >>                does not damage the device in any way, but data in the block may be disturbed from its
> >>               original state.
>
> I've seen this issue with Intel 28F640J5 chips as well.
>
> There's an old thread on it.
> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021266.html
>
> A delay was suggested similar to the one you're experimenting with I think.
> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021436.html

Oh, I had forgotten about this thread :)

I agree with the latency theory, for Numonyx there is this:

W602 is the typical time between an initial block erase or erase resume command and the a subsequent erase suspend
command. Violating the specification repeatedly during any particular block erase may cause erase failures.

W602 is defined to 500us

Adding a delay after resume will do it but is a bit crude. Possibly one
could add a timestamp at resume/initial erase and a check in suspend that enough time has passed
before suspending again.

How does that sound?

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 14:21:36:
> >
> > On 2011-02-09 22:59, Michael Cashwell wrote:
> > > On Feb 9, 2011, at 3:13 PM, Joakim Tjernlund wrote:
> > >
> > >> hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)
> > >>
> > >> 5. W602: erase suspend resume operation
> > >> Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
> > >>        due to an internal firmware issue that is exhibited in certain applications that require at
> > >>       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
> > >> Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
> > >>                does not damage the device in any way, but data in the block may be disturbed from its
> > >>               original state.
> >
> > I've seen this issue with Intel 28F640J5 chips as well.
> >
> > There's an old thread on it.
> > http://lists.infradead.org/pipermail/linux-mtd/2008-April/021266.html
> >
> > A delay was suggested similar to the one you're experimenting with I think.
> > http://lists.infradead.org/pipermail/linux-mtd/2008-April/021436.html
>
> Oh, I had forgotten about this thread :)
>
> I agree with the latency theory, for Numonyx there is this:
>
> W602 is the typical time between an initial block erase or erase resume command and the a subsequent erase suspend
> command. Violating the specification repeatedly during any particular block erase may cause erase failures.
>
> W602 is defined to 500us
>
> Adding a delay after resume will do it but is a bit crude. Possibly one
> could add a timestamp at resume/initial erase and a check in suspend that enough time has passed
> before suspending again.
>
> How does that sound?

A simpler impl. would be a suspend counter. When no. of suspends > 1000, do usleep(500)
or usleep(500) every 100-500 suspends.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 10:04 AM, Joakim Tjernlund wrote:

> A simpler impl. would be a suspend counter. When no. of suspends > 1000, do usleep(500) or usleep(500) every 100-500 suspends.

Our messages crossed each other. I just saw this problem with 29 suspends.

I wonder if THAT is what's different between these chips and the older 130nm parts. And none of that addresses whether or not this change is just an anomaly in this batch or if we would continue to get them.

I'm going to run my test on the older 130nm (2003 vintage) parts just for grins.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 16:59:50:
>
> > A simpler impl. would be a suspend counter. When no. of suspends > 1000, do usleep(500) or usleep(500) every 100-500 suspends.
>
> Our messages crossed each other. I just saw this problem with 29 suspends.
>
> I wonder if THAT is what's different between these chips and the older 130nm parts. And none of that addresses whether or not this change is just an anomaly in this batch or if we would continue to get them.
>
> I'm going to run my test on the older 130nm (2003 vintage) parts just for grins.

Here is another idea, don't resume between every write_buffer etc. If less
than 500 us has passed, just continue with the next write_buffer. That
would be much more efficient.

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 11:05 AM, Joakim Tjernlund wrote:

> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 16:59:50:
>> 
>>> A simpler impl. would be a suspend counter. When no. of suspends > 1000, do usleep(500) or usleep(500) every 100-500 suspends.
>> 
>> Our messages crossed each other. I just saw this problem with 29 suspends.
>> 
>> I wonder if THAT is what's different between these chips and the older 130nm parts. And none of that addresses whether or not this change is just an anomaly in this batch or if we would continue to get them.
>> 
>> I'm going to run my test on the older 130nm (2003 vintage) parts just for grins.
> 
> Here is another idea, don't resume between every write_buffer etc. If less than 500 us has passed, just continue with the next write_buffer. That would be much more efficient.

Wouldn't that extend the wrong time. That would ensure the erase stays *suspended* for at least 500us. But doesn't W602 specify that an erase should be allowed *to run* for 500us before suspension?

It seems the other way around.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 17:41:23:
>
>
> On Feb 10, 2011, at 11:05 AM, Joakim Tjernlund wrote:
>
> > Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 16:59:50:
> >>
> >>> A simpler impl. would be a suspend counter. When no. of suspends > 1000, do usleep(500) or usleep(500) every 100-500 suspends.
> >>
> >> Our messages crossed each other. I just saw this problem with 29 suspends.
> >>
> >> I wonder if THAT is what's different between these chips and the older 130nm parts. And none of that addresses whether or not this change is just an anomaly in this batch or if we would continue to get them.
> >>
> >> I'm going to run my test on the older 130nm (2003 vintage) parts just for grins.
> >
> > Here is another idea, don't resume between every write_buffer etc. If less than 500 us has passed, just continue with the next write_buffer. That would be much more efficient.
>
> Wouldn't that extend the wrong time. That would ensure the erase stays *suspended* for at least 500us. But doesn't W602 specify that an erase should be allowed *to run* for 500us before suspension?
>
> It seems the other way around.

eeh, yes :(

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

> > > Here is another idea, don't resume between every write_buffer etc. If less than 500 us has passed, just continue with the next write_buffer. That would be much more efficient.
> >
> > Wouldn't that extend the wrong time. That would ensure the erase stays *suspended* for at least 500us. But doesn't W602 specify that an erase should be allowed *to run* for 500us before suspension?
> >
> > It seems the other way around.
>
> eeh, yes :(

And this reminds me that if the spec is to be trusted, the delay should be just before
erase suspend, otherwise you miss the time between the initial erase and the first suspend.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 12:02 PM, Joakim Tjernlund wrote:

> And this reminds me that if the spec is to be trusted, the delay should be just before erase suspend, otherwise you miss the time between the initial erase and the first suspend.

Probably true to be completely sure. I bet the need for "repeated violations" is why I've been able to make it work by delaying after. But I agree.

I have an idea for an efficient fix. But it's tricky to not impact writing speed. Once it get the idea worked out I'll post for comment. I have some other commitments today, so honestly it'll likely be next week at this point.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 18:10:18:
>
> On Feb 10, 2011, at 12:02 PM, Joakim Tjernlund wrote:
>
> > And this reminds me that if the spec is to be trusted, the delay should be just before erase suspend, otherwise you miss the time between the initial erase and the first suspend.
>
> Probably true to be completely sure. I bet the need for "repeated violations" is why I've been able to make it work by delaying after. But I agree.

Yes, but you also indicated that a throw away status read made the problem go away?
Can you move that status read to just before suspend and get the same results?

>
> I have an idea for an efficient fix. But it's tricky to not impact writing speed. Once it get the idea worked out I'll post for comment. I have some other commitments today, so honestly it'll likely be next week at this point.
>

Nice, looking forward to that.

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 18:10:18:
> >
> > On Feb 10, 2011, at 12:02 PM, Joakim Tjernlund wrote:
> >
> > > And this reminds me that if the spec is to be trusted, the delay should be just before erase suspend, otherwise you miss the time between the initial erase and the first suspend.
> >
> > Probably true to be completely sure. I bet the need for "repeated violations" is why I've been able to make it work by delaying after. But I agree.
>
> Yes, but you also indicated that a throw away status read made the problem go away?
> Can you move that status read to just before suspend and get the same results?

hmm, Figure 31: Program Suspend/Resume Flowchart and
Figure 36: Erase Suspend/Resume Flowchart actually specifies
a read status(0x70) before suspend(0xb0)

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> >
> > Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 18:10:18:
> > >
> > > On Feb 10, 2011, at 12:02 PM, Joakim Tjernlund wrote:
> > >
> > > > And this reminds me that if the spec is to be trusted, the delay should be just before erase suspend, otherwise you miss the time between the initial erase and the first suspend.
> > >
> > > Probably true to be completely sure. I bet the need for "repeated violations" is why I've been able to make it work by delaying after. But I agree.
> >
> > Yes, but you also indicated that a throw away status read made the problem go away?
> > Can you move that status read to just before suspend and get the same results?
>
> hmm, Figure 31: Program Suspend/Resume Flowchart and
> Figure 36: Erase Suspend/Resume Flowchart actually specifies
> a read status(0x70) before suspend(0xb0)

Furthermore, the read status has to be to the same "partition" and you have
to end the resume with a read status too
 "If the suspended partition was placed in Read Array mode or a Program Loop"

Mike, I think some of this supports your findings.
I guess we need to save the block address which are being erased
to fulfil "same partition"

         Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 1:26 PM, Joakim Tjernlund wrote:

>> hmm, Figure 31: Program Suspend/Resume Flowchart and
>> Figure 36: Erase Suspend/Resume Flowchart actually specifies a read status(0x70) before suspend(0xb0)

I see the Erase Suspend/Resume Flowchart as figure 40, not 36. The sheet info is: 320002-10 Mar 2010. What's yours?

> Furthermore, the read status has to be to the same "partition" and you have to end the resume with a read status too "If the suspended partition was placed in Read Array mode or a Program Loop"

Mine says NOT to do that. You can program or read from any OTHER partition, but trying to do that to the same one that was being erased is not valid.

My Erase Suspend/Resume Flowchart says to do a read-status (0x70) before the 0xb0 suspend. (Interesting that we weren't doing that!) The the address for both must be the same, but can be "any device address."

I don't see where they say the resume address must match the address of the erase.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/11 19:03:00:
>
> On Feb 10, 2011, at 1:26 PM, Joakim Tjernlund wrote:
>
> >> hmm, Figure 31: Program Suspend/Resume Flowchart and
> >> Figure 36: Erase Suspend/Resume Flowchart actually specifies a read status(0x70) before suspend(0xb0)
>
> I see the Erase Suspend/Resume Flowchart as figure 40, not 36. The sheet info is: 320002-10 Mar 2010. What's yours?

  Apr 2010
  Order Number: 208042-05
from
  http://www.numonyx.com/en-US/MemoryProducts/NOR/Pages/P30P33Documents.aspx
>
> > Furthermore, the read status has to be to the same "partition" and you have to end the resume with a read status too "If the suspended partition was placed in Read Array mode or a Program Loop"
>
> Mine says NOT to do that. You can program or read from any OTHER partition, but trying to do that to the same one that was being erased is not valid.

Partition != erase block, not sure how though.

>
> My Erase Suspend/Resume Flowchart says to do a read-status (0x70) before the 0xb0 suspend. (Interesting that we weren't doing that!) The the address for both must be the same, but can be "any device address."
>
> I don't see where they say the resume address must match the address of the erase.

It says Same Partition which will map to Any Address if you only got one partition.

BTW, when we went from 130 to 65 nm parts, bus timing changed to slower and we
had to adjust our chip select logic to match. The 65 nm parts needed some extra
time for the read access. Have you adjusted yours?

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

To verify things are as expected when doing the erase suspend I added some status checks. That section of chip_read() shown next. I wanted to be sure that once the for (;;) loop ends that we were properly in a suspended erase state with no unexpected status bits.

	case FL_ERASING:
...
		/* Erase suspend */
		map_write(map, CMD(0x70), adr);
		map_write(map, CMD(0xB0), adr);
...
		map_write(map, CMD(0x70), adr);
		chip->oldstate = FL_ERASING;
		chip->state = FL_ERASE_SUSPENDING;
		chip->erase_suspended = 1;
		for (;;) {
			status = map_read(map, adr);
			if (map_word_andequal(map, status, status_OK, status_OK))
			        break;
...
		}
		if (!map_word_bitsset(map, status, CMD(0x40)))
			printk(KERN_ERR "%s: Erase-suspend completed instead.\n", map->name);

		if (map_word_bitsset(map, status, CMD(0x3f))) {
			printk(KERN_ERR "%s: Erase-suspend had unexpected status bits %lx.\n", map->name, status.x[0]);
			BUG();
		}

		chip->state = FL_STATUS;
		return 0;

During UBI writing via rsync things failed:

NOR Flash: Erase-suspend had unexpected status bits c4.
kernel BUG at drivers/mtd/chips/cfi_cmdset_0001.c:874!
Unable to handle kernel NULL pointer dereference at virtual address 00000000
pgd = c7ee4000
*pte=0000000025
Internal error: Oops: 817 [#1] PREEMPT
last sysfs file: /sys/class/ubi/ubi4/ubi4_0/name
Modules linked in: sc16is7uart gpiopps gpiodriver
CPU: 0    Not tainted  (2.6.35.7 #22)
PC is at __bug+0x1c/0x28
LR is at __bug+0x18/0x28
pc : [<c0026f40>]    lr : [<c0026f3c>]    psr: 60000013
sp : c7ee1b78  ip : 00000000  fp : 00000188
r10: c7cf2f10  r9 : ffffda32  r8 : 017a3000
r7 : c7cf2ef8  r6 : c0349730  r5 : 000000c4  r4 : c7c857ac
r3 : 00000000  r2 : 00020000  r1 : 00002040  r0 : 0000003d
Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 0000397f  Table: a7ee4000  DAC: 00000015
Process rsync (pid: 399, stack limit = 0xc7ee0278)
Stack: (0xc7ee1b78 to 0xc7ee2000)
...
[<c0026f40>] (__bug+0x1c/0x28) from [<c01a5980>] (chip_ready+0x20c/0x36c)
[<c01a5980>] (chip_ready+0x20c/0x36c) from [<c01a5f48>] (get_chip+0x8c/0x224)
[<c01a5f48>] (get_chip+0x8c/0x224) from [<c01a6648>] (cfi_intelext_writev+0x1a4/0x600)
[<c01a6648>] (cfi_intelext_writev+0x1a4/0x600) from [<c01a6ad4>] (cfi_intelext_write_buffers+0x30/0x38)
[<c01a6ad4>] (cfi_intelext_write_buffers+0x30/0x38) from [<c019f5c4>] (part_write+0x8c/0xa0)
[<c019f5c4>] (part_write+0x8c/0xa0) from [<c01b0ddc>] (ubi_io_write+0x4c/0xa4)
[<c01b0ddc>] (ubi_io_write+0x4c/0xa4) from [<c01af22c>] (ubi_eba_write_leb+0x7c/0x770)
[<c01af22c>] (ubi_eba_write_leb+0x7c/0x770) from [<c01ae328>] (ubi_leb_write+0xf4/0xf8)
[<c01ae328>] (ubi_leb_write+0xf4/0xf8) from [<c0134020>] (ubifs_wbuf_write_nolock+0x230/0x324)
[<c0134020>] (ubifs_wbuf_write_nolock+0x230/0x324) from [<c0129704>] (write_head.clone.12.clone.14+0x40/0x60)
[<c0129704>] (write_head.clone.12.clone.14+0x40/0x60) from [<c01299c0>] (ubifs_jnl_update+0x29c/0x4f4)
[<c01299c0>] (ubifs_jnl_update+0x29c/0x4f4) from [<c012ea04>] (ubifs_create+0x114/0x1b8)
[<c012ea04>] (ubifs_create+0x114/0x1b8) from [<c009683c>] (vfs_create+0x84/0x88)
[<c009683c>] (vfs_create+0x84/0x88) from [<c00997d0>] (do_last.clone.55+0x55c/0x63c)
[<c00997d0>] (do_last.clone.55+0x55c/0x63c) from [<c0099a40>] (do_filp_open+0x190/0x4e4)
[<c0099a40>] (do_filp_open+0x190/0x4e4) from [<c008d4c0>] (do_sys_open+0x5c/0xa8)
[<c008d4c0>] (do_sys_open+0x5c/0xa8) from [<c0023f40>] (ret_fast_syscall+0x0/0x2c)
Code: e59f0010 e1a01003 eb098786 e3a03000 (e5833000) 

The c4 status above is strange. chip->status was FL_ERASING but after the suspend we had both ESS and PSS status set. That means that both and erase and a program have been suspended.

Huh? How do we ever get PSS set? I thought that without xip the code would not suspend writes. So I'm quite confused by this.

It's also interesting that do_write_buffer() is not shown in the stack dump. I assume it's being inlined.

Still looking...

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 12:20 PM, Joakim Tjernlund wrote:

> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 18:10:18:
>> On Feb 10, 2011, at 12:02 PM, Joakim Tjernlund wrote:
>> 
>>> And this reminds me that if the spec is to be trusted, the delay should be just before erase suspend, otherwise you miss the time between the initial erase and the first suspend.
>> 
>> Probably true to be completely sure. I bet the need for "repeated violations" is why I've been able to make it work by delaying after. But I agree.
> 
> Yes, but you also indicated that a throw away status read made the problem go away?
> Can you move that status read to just before suspend and get the same results?

Well, sort of. The place where I've been doing the udelay or throw-away status read is when resuming, not suspending.

But interestingly, doing it right before the resume works just as well as right after.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 10:59 AM, Michael Cashwell wrote:

> I'm going to run my test on the older 130nm (2003 vintage) parts just for grins.

Yup. That yielded the following:

Older 130nm parts:
run 1:
NOR Flash: block erase suspended and resumed 851 times.
NOR Flash: block erase suspended and resumed 490 times.
NOR Flash: block erase suspended and resumed 16598 times.
NOR Flash: block erase suspended and resumed 16 times.

run 2:
NOR Flash: block erase suspended and resumed 864 times.
NOR Flash: block erase suspended and resumed 16741 times.
NOR Flash: block erase suspended and resumed 9223 times.
NOR Flash: block erase suspended and resumed 16 times.

and suffered no failures.

Troublesome 65nm parts:
run 1:
NOR Flash: block erase suspended and resumed 29 times.
buffered write fails.

run 2:
NOR Flash: block erase suspended and resumed 89 times.
NOR Flash: block erase suspended and resumed 15 times.
buffered write fails.

So this does seem to be the characteristic that has changed.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Anders Grafström]

On 2011-02-10 17:43, Michael Cashwell wrote:
> On Feb 10, 2011, at 10:59 AM, Michael Cashwell wrote:
> Troublesome 65nm parts:
> run 1:
> NOR Flash: block erase suspended and resumed 29 times.
> buffered write fails.

Buffered write fails with SR[4] set?

Have you configured with CONFIG_MTD_UBI_DEBUG_PARANOID
so that UBI does the all 0xff check after erase?

I'm wondering if the blocks being written to are in a properly erased state.

/Anders

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 12:54 PM, Anders Grafström wrote:

> On 2011-02-10 17:43, Michael Cashwell wrote:
>> On Feb 10, 2011, at 10:59 AM, Michael Cashwell wrote:
>> Troublesome 65nm parts:
>> run 1:
>> NOR Flash: block erase suspended and resumed 29 times.
>> buffered write fails.
> 
> Buffered write fails with SR[4] set?

The error messages variously report block locked and Vpp errors but they are not legitimate. I changed them to actually print the status word and it's often 0xffff or other values with set bits in the upper byte. That tells me the chip is not properly in status-read mode at that point.

So I think the answer to your question is no, not reliably with SR[4] set because it's reading array data instead of status.

> Have you configured with CONFIG_MTD_UBI_DEBUG_PARANOID so that UBI does the all 0xff check after erase?

I've used some of the debugging modes at the top of cfi_cmdset_0001.c but I had not used the config option. I will do that and report back.

> I'm wondering if the blocks being written to are in a properly erased state.

Yes, it's a possibility. However, I've never seen an erase report any error.

More next week.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/11 16:05:54:
>
> On Feb 10, 2011, at 12:54 PM, Anders Grafström wrote:
>
> > On 2011-02-10 17:43, Michael Cashwell wrote:
> >> On Feb 10, 2011, at 10:59 AM, Michael Cashwell wrote:
> >> Troublesome 65nm parts:
> >> run 1:
> >> NOR Flash: block erase suspended and resumed 29 times.
> >> buffered write fails.
> >
> > Buffered write fails with SR[4] set?
>
> The error messages variously report block locked and Vpp errors but they are not legitimate. I changed them to actually print the status word and it's often 0xffff or other values with set bits in the upper byte. That tells me the chip is not properly in status-read mode at that point.
>
> So I think the answer to your question is no, not reliably with SR[4] set because it's reading array data instead of status.
>
> > Have you configured with CONFIG_MTD_UBI_DEBUG_PARANOID so that UBI does the all 0xff check after erase?
>
> I've used some of the debugging modes at the top of cfi_cmdset_0001.c but I had not used the config option. I will do that and report back.
>
> > I'm wondering if the blocks being written to are in a properly erased state.
>
> Yes, it's a possibility. However, I've never seen an erase report any error.

Mike, does this small patch change anything:
diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
index 9772a62..bdcd8c1 100644
--- a/drivers/mtd/chips/cfi_cmdset_0001.c
+++ b/drivers/mtd/chips/cfi_cmdset_0001.c
@@ -808,7 +808,8 @@ static int chip_ready (struct map_info *map, struct flchip *chip, unsigned long
 		     (mode == FL_WRITING && (cfip->SuspendCmdSupport & 1))))
 			goto sleep;

-
+		/* Numonyx Axcell chips needs a Read Status */
+		map_write(map, CMD(0x70), adr);
 		/* Erase suspend */
 		map_write(map, CMD(0xB0), adr);


Possibly this u-boot add on would make it easier to test suspend/resume:

http://lists.infradead.org/pipermail/linux-mtd/2008-April/021280.html

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 11, 2011, at 10:39 AM, Joakim Tjernlund wrote:

>>> I'm wondering if the blocks being written to are in a properly erased state.
>> 
>> Yes, it's a possibility. However, I've never seen an erase report any error.
> 
> Mike, does this small patch change anything:
> diff --git a/drivers/mtd/chips/cfi_cmdset_0001.c b/drivers/mtd/chips/cfi_cmdset_0001.c
> index 9772a62..bdcd8c1 100644
> --- a/drivers/mtd/chips/cfi_cmdset_0001.c
> +++ b/drivers/mtd/chips/cfi_cmdset_0001.c
> @@ -808,7 +808,8 @@ static int chip_ready (struct map_info *map, struct flchip *chip, unsigned long
> 		     (mode == FL_WRITING && (cfip->SuspendCmdSupport & 1))))
> 			goto sleep;
> 
> -
> +		/* Numonyx Axcell chips needs a Read Status */
> +		map_write(map, CMD(0x70), adr);
> 		/* Erase suspend */
> 		map_write(map, CMD(0xB0), adr);

No, this doesn't change the failures I see.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 18:54:31:
>
> On 2011-02-10 17:43, Michael Cashwell wrote:
> > On Feb 10, 2011, at 10:59 AM, Michael Cashwell wrote:
> > Troublesome 65nm parts:
> > run 1:
> > NOR Flash: block erase suspended and resumed 29 times.
> > buffered write fails.
>
> Buffered write fails with SR[4] set?
>
> Have you configured with CONFIG_MTD_UBI_DEBUG_PARANOID
> so that UBI does the all 0xff check after erase?
>
> I'm wondering if the blocks being written to are in a properly erased state.

Looking at the write buffer flow chart for Numonyx I noted that it
specifies that while waiting for the write buffer one have to retry the
WB cmd each time, a la:

	for (;;) {
		map_write(map, CMD(0xe8), cmd_adr);
		status = map_read(map, cmd_adr);
		if (map_word_andequal(map, status, CMD(0x80), CMD(0x80)))
			break;
		if (timeout) abort write
	}

What does other specs say?

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 10, 2011, at 9:04 AM, Joakim Tjernlund wrote:

> Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 14:21:36:
> 
>> I've seen this issue with Intel 28F640J5 chips as well.
>> 
>> There's an old thread on it.
>> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021266.html
>> 
>> A delay was suggested similar to the one you're experimenting with I think.
>> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021436.html
> 
> Oh, I had forgotten about this thread :)
> 
> I agree with the latency theory, for Numonyx there is this:
> 
> W602 is the typical time between an initial block erase or erase resume command and the a subsequent erase suspend
> command. Violating the specification repeatedly during any particular block erase may cause erase failures.

Interesting. I saw the W602 value but it also talks about "erase failures" which are not precisely what I'm seeing. I see failed buffered write. But it's sounding like the issue anyway.

I've just instrumented a suspend count and the erase that was active when a failed write occurred was suspended 29 times. That's not really very high so it fits with the idea that the issue is not the number of suspend/resumes but their timing.

> W602 is defined to 500us
> 
> Adding a delay after resume will do it but is a bit crude. Possibly one could add a timestamp at resume/initial erase and a check in suspend that enough time has passed before suspending again.
> 
> How does that sound?


I like this idea but how do we deal with the lack of precision? 500µs "typical" and violating this timing "repeatedly"? Yuk. Without hard numbers coding it will be tricky. And what about this all being Numonyx-specific? Do we need to key off of the manufacturer ID or does it apply to all chips handled by this cmd set?

Lastly, what's the general kernel API for µs resolution time? I recall having issues in the past when high-resolution timers is not enabled in the kernel config.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/10 16:43:40:
>
> On Feb 10, 2011, at 9:04 AM, Joakim Tjernlund wrote:
>
> > Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 14:21:36:
> >
> >> I've seen this issue with Intel 28F640J5 chips as well.
> >>
> >> There's an old thread on it.
> >> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021266.html
> >>
> >> A delay was suggested similar to the one you're experimenting with I think.
> >> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021436.html
> >
> > Oh, I had forgotten about this thread :)
> >
> > I agree with the latency theory, for Numonyx there is this:
> >
> > W602 is the typical time between an initial block erase or erase resume command and the a subsequent erase suspend
> > command. Violating the specification repeatedly during any particular block erase may cause erase failures.
>
> Interesting. I saw the W602 value but it also talks about "erase failures" which are not precisely what I'm seeing. I see failed buffered write. But it's sounding like the issue anyway.
>
> I've just instrumented a suspend count and the erase that was active when a failed write occurred was suspended 29 times. That's not really very high so it fits with the idea that the issue is not the number of suspend/resumes but their timing.

29 sounds very low, it may be some additional issue you see.

>
> > W602 is defined to 500us
> >
> > Adding a delay after resume will do it but is a bit crude. Possibly one could add a timestamp at resume/initial erase and a check in suspend that enough time has passed before suspending again.
> >
> > How does that sound?
>
>
> I like this idea but how do we deal with the lack of precision? 500µs "typical" and violating this timing "repeatedly"? Yuk. Without hard numbers coding it will be tricky. And what about this all being Numonyx-specific? Do we need to key off of the manufacturer ID or does it apply to all chips
handled by this cmd set?
>
> Lastly, what's the general kernel API for µs resolution time? I recall having issues in the past when high-resolution timers is not enabled in the kernel config.

I don't know, I have seen drivers(mpc52xx_spi.c) use get_tbl() though.

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 14:21:36:
>
> On 2011-02-09 22:59, Michael Cashwell wrote:
> > On Feb 9, 2011, at 3:13 PM, Joakim Tjernlund wrote:
> >
> >> hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)
> >>
> >> 5. W602: erase suspend resume operation
> >> Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
> >>        due to an internal firmware issue that is exhibited in certain applications that require at
> >>       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
> >> Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
> >>                does not damage the device in any way, but data in the block may be disturbed from its
> >>               original state.
>
> I've seen this issue with Intel 28F640J5 chips as well.
>
> There's an old thread on it.
> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021266.html
>
> A delay was suggested similar to the one you're experimenting with I think.
> http://lists.infradead.org/pipermail/linux-mtd/2008-April/021436.html

Been a while but it just occurred to me that you might see something similar as
Michael.

This program of yours:

static void erase_suspend(unsigned int loops)
{
	volatile unsigned int *flash = (unsigned int *)0x41040000;
	unsigned int i;
	unsigned int suspends = 0;
	unsigned int words = 2;
	unsigned int timeout;

	/* Make sure there's something to erase */
	for (i = 0; i < 0x10000; i++) {
		if (flash[i] == 0xffffffff) {
			flash[i] = 0x00400040;
			flash[i] = 0;
			while ((flash[i] & 0x00800080) != 0x00800080);
		}
	}

	/* Clear status */
	flash[0] = 0x00500050;

	/* Erase */
	flash[0] = 0x00200020;
	flash[0] = 0x00d000d0;

	while (1) {
		/* Suspend */
		flash[0] = 0x00b000b0;
		flash[0] = 0x00700070;
		timeout = 100000;
		while ((flash[0] & 0x00800080) != 0x00800080 && --timeout);
		if (!timeout)
			printf("suspend timeout\n");
		suspends++;

		/* Short delay */
		for (i = 0; i < 1000; i++);

		/* Resume */
		flash[0] = 0x00d000d0;
		flash[0] = 0x00700070;

		/* Erase done ? */
		if ((flash[0] & 0x00800080) == 0x00800080) {
			printf("\nstatus %08x\n", flash[0]);
			break;
		}

		/* Short delay */
		for (i = 0; i < loops; i++);
	}

	/* Read array */
	flash[0] = 0x00ff00ff;

	/* Show the first 2 failed words */
	for (i = 0; i < 0x10000; i++) {
		if (flash[i] != 0xffffffff) {
			printf("%08x\n", flash[i]);
			if (--words == 0)
				break;
		}
	}

	printf("%d suspends\n", suspends);
}

void test_flash_erase_suspend(void)
{
	unsigned int loops;

	for (loops = 6000; loops > 2000; loops -= 500) {
		printf("\n%d loops", loops);
		erase_suspend(loops);
	}
}


It produced this output at one occasion:

6000 loops
status 00800080
ffff0000
ffff0000
4783 suspends
---------------------
See the status 00800080 ?
Looking at the code this should not be possible, right?
looking closer though it becomes clearer:

if ((flash[0] & 0x00800080) == 0x00800080) {
	printf("\nstatus %08x\n", flash[0]);
	break;
}
There are two status reads here, one where you test and one where you
print. I suspect that if you add a dummy status read like Michael need to do:
stat = flash[0]; /* dummy, will contain garbage sometimes */
stat = flash[0];
if ((stat & 0x00800080) == 0x00800080) {
	printf("\nstatus %08x\n", stat);
	break;
}
You will see an improvement.

Michael, have you made any progress? Can you run Anders program too?

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 14:21:36:
> >
> > On 2011-02-09 22:59, Michael Cashwell wrote:
> > > On Feb 9, 2011, at 3:13 PM, Joakim Tjernlund wrote:
> > >
> > >> hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)
> > >>
> > >> 5. W602: erase suspend resume operation
> > >> Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
> > >>        due to an internal firmware issue that is exhibited in certain applications that require at
> > >>       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
> > >> Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
> > >>                does not damage the device in any way, but data in the block may be disturbed from its
> > >>               original state.
> >
> > I've seen this issue with Intel 28F640J5 chips as well.
> >
> > There's an old thread on it.
> > http://lists.infradead.org/pipermail/linux-mtd/2008-April/021266.html
> >
> > A delay was suggested similar to the one you're experimenting with I think.
> > http://lists.infradead.org/pipermail/linux-mtd/2008-April/021436.html
>
> Been a while but it just occurred to me that you might see something similar as
> Michael.
>
> This program of yours:
>
> static void erase_suspend(unsigned int loops)
> {
>    volatile unsigned int *flash = (unsigned int *)0x41040000;
>    unsigned int i;
>    unsigned int suspends = 0;
>    unsigned int words = 2;
>    unsigned int timeout;
>
>    /* Make sure there's something to erase */
>    for (i = 0; i < 0x10000; i++) {
>       if (flash[i] == 0xffffffff) {
>          flash[i] = 0x00400040;
>          flash[i] = 0;
>          while ((flash[i] & 0x00800080) != 0x00800080);
>       }
>    }
>
>    /* Clear status */
>    flash[0] = 0x00500050;
>
>    /* Erase */
>    flash[0] = 0x00200020;
>    flash[0] = 0x00d000d0;
>
>    while (1) {
>       /* Suspend */
>       flash[0] = 0x00b000b0;
>       flash[0] = 0x00700070;
>       timeout = 100000;
>       while ((flash[0] & 0x00800080) != 0x00800080 && --timeout);
>       if (!timeout)
>          printf("suspend timeout\n");
>       suspends++;
>
>       /* Short delay */
>       for (i = 0; i < 1000; i++);
>
>       /* Resume */
>       flash[0] = 0x00d000d0;
>       flash[0] = 0x00700070;
>
>       /* Erase done ? */
>       if ((flash[0] & 0x00800080) == 0x00800080) {
>          printf("\nstatus %08x\n", flash[0]);
>          break;
>       }
>
>       /* Short delay */
>       for (i = 0; i < loops; i++);
>    }
>
>    /* Read array */
>    flash[0] = 0x00ff00ff;
>
>    /* Show the first 2 failed words */
>    for (i = 0; i < 0x10000; i++) {
>       if (flash[i] != 0xffffffff) {
>          printf("%08x\n", flash[i]);
>          if (--words == 0)
>             break;
>       }
>    }
>
>    printf("%d suspends\n", suspends);
> }
>
> void test_flash_erase_suspend(void)
> {
>    unsigned int loops;
>
>    for (loops = 6000; loops > 2000; loops -= 500) {
>       printf("\n%d loops", loops);
>       erase_suspend(loops);
>    }
> }
>
>
> It produced this output at one occasion:
>
> 6000 loops
> status 00800080
> ffff0000
> ffff0000
> 4783 suspends
> ---------------------
> See the status 00800080 ?
> Looking at the code this should not be possible, right?

ehh, looking at my own post I see that I misread == as !=


> looking closer though it becomes clearer:
>
> if ((flash[0] & 0x00800080) == 0x00800080) {
>    printf("\nstatus %08x\n", flash[0]);
>    break;
> }
> There are two status reads here, one where you test and one where you
> print. I suspect that if you add a dummy status read like Michael need to do:
> stat = flash[0]; /* dummy, will contain garbage sometimes */
> stat = flash[0];
> if ((stat & 0x00800080) == 0x00800080) {
>    printf("\nstatus %08x\n", stat);
>    break;
> }
> You will see an improvement.
>
> Michael, have you made any progress? Can you run Anders program too?
>
>  Jocke
>
>
> ______________________________________________________
> Linux MTD discussion mailing list
> http://lists.infradead.org/mailman/listinfo/linux-mtd/

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

Anders Grafström <grfstrm@users.sourceforge.net> wrote on 2011/02/10 14:21:36:

> It produced this output at one occasion:
> 
> 6000 loops
> status 00800080
> ffff0000
> ffff0000
> 4783 suspends
> ---------------------
> See the status 00800080 ?
> Looking at the code this should not be possible, right?


It's similar but not identical to my issue. I was seeing a buffered programming operation (done while an erase was suspended) appear to fail because the status read looking for program completion would return garbage. Your case is only erase, not programming.

But yours looks similar to mine in that your resumed erase completes (00800080) and then the next several status read returns garbage. Interestingly, the low chip returns correct status (WSM busy, nothing suspended, no errors, etc.) but the high chip returns FFFF. That was often what mine did during buffer program.

I also sometimes would see other values, not always FFFF. But with bits set in the upper byte whatever was being read was clearly NOT status. Since FFFF is correct for erased array data I assumed the part had dropped out of status-read mode but I've not been able to determine why.

Also, on my parts there is a loose restriction on the minimum time between starting or resuming an erase and the next suspend of it. It's 500µs for my part and they say that "repeated violations" of that time can cause erase failures. The hard part is that the 500µs is only a typical value and no hard number is given for how many violations are needed to cause a failure. I suspect it varies from part to part.

Your code suspends immediately after starting the erase, so that would be a violation on my part. And depending on the value of loops you might be violating it often.

On Feb 24, 2011, at 6:36 AM, Joakim Tjernlund wrote:

> Michael, have you made any progress?

Sadly, management was breathing down my neck to get it working and I've been pulled completely off onto a different project. I do still want to find the real answer but currently the people who control the purse strings have other ideas. There is another board in the pipeline here that might have this part on it. When that arrives on my desk I'll see if I can pick this up again.

> Can you run Anders program too?

Not as written. My board only has one flash chip where Anders' clearly has two chips in parallel. It wouldn't be too hard to change it to 1-wide but I'm overloaded on my other project at present.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

>
> On Feb 9, 2011, at 3:13 PM, Joakim Tjernlund wrote:
>
> > hmm, this sounds similar(from http://www.numonyx.com/Documents/Specification%20Updates/SU-309045_P30.pdf)
> >
> > 5. W602: erase suspend resume operation
> > Problem: P30 product may fail to erase in intensive erase/suspend/resume environments. This is
> >        due to an internal firmware issue that is exhibited in certain applications that require at
> >       least 3000 to 4000 erase/suspend/resume cycles during the erase of a single block.
> > Implication: Customer may see erase failure (SR reports “A0”) during a background erase. This
> >                does not damage the device in any way, but data in the block may be disturbed from its
> >               original state.
> > Workaround: If such an erase failure occurs, customer should retry the erase with an increase to the
> > Tres (W602) spec from 500uS to 1mS. If the device still fails, continue to increase Tres
> > in increments of 500uS up to a maximum Tres of 2.5mS. Once the failing block passes,
> > subsequent blocks should revert back to original erase algorithm and timing for Tres
> > (500uS typical).
> > Status:
> > June 2008
> > 309045-09
> > This erratum does not apply to material marked with an FPO code dated x806xxxx or
> > later.
>
> Interesting. Thanks for the URL. I'll explore it. I have a 2009 errata sheet but had not seen the 2008 one. (I'm wondering if that's because your's is for a batch of the older 130nm parts which are no longer made. Just guessing.)
>
> It doesn't match exactly, since I'm not seeing erase failures. I'm seeing buffered write failures where, after the 0xd0 Write Confirm command I get back nonsense status. (See the 0xffff reported in my log. I've also seen many values other than 0xffff.)
>
> So the the program operation (0xe8) begins OK, the count and data are written, the confirm command is written but then the status read reads as junk. I'm thinking about adding status-read logs to my buffer if I can do it without disturbing the timing.
>
> The reason that status is nonsense in the status register is only in the lower 8 bits. If it's in read-status mode (which it should be) we should never see any set bits in the upper byte. Because I do see such bits I've suspected from the start that somehow the part is exiting the status-read mode
and returning array-read mode when it should not. (My very first post mentions this suspicion.)
>
> One more log point I think I may check is to count and report the number of suspend/resumes for each erase. It would be interesting to see if some sort of spike in that count correlates with my failures.
>
> More as I find it.

Mike, what if you move the udelay to just before doing erase suspend? Perhaps
you need to increase it a bit.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/05 20:19:59:
> On Feb 5, 2011, at 5:29 AM, Joakim Tjernlund wrote:
>
> > Michael Cashwell <mboards@prograde.net> wrote on 2011/02/04 18:09:01:
> >>
> >> That's where I get confused. It's true that another thread could do that but wouldn't it have to bracket its operation with calls to get_chip() and put_chip()? Those actually do the suspend and resume. I'm certainly seeing erases being suspended to do a buffered write and then being resumed.
> >
> > buffered write do get_chip that suspends the erase, then a WAIT_TIMEOUT which drops the locks and gives the suspended erase a chance to wakeup and run but now SR is holding the status for the write so the suspended erase are testing the wrong status, do you agree?
>
> It's not that simple. Just waking the suspended erase thread should not cause it to "run" the way you are saying.
>
> That thread *should* wake up in inval_cache_and_wait_for_operation() inside its while (chip->state != chip_state) loop. The purpose of that loop is to see if something else is going on with the chip and if so just go back to sleep. That should prevent what you are saying is happening and if it is
not then we need to figure out why.

dropping the lock MIGTH make another thread waiting on that lock run if the scheduler decides so
or so I think anyway but I am no expert :)

>
> In the case of a buffered write the erase thread should see chip->state as either FL_WRITING_TO_BUFFER (if after the 0xE8) or FL_WRITING (if after the 0xD0). Since those don't match the expected FL_ERASING state the thread should stay in the while loop and go back to sleep on the wait queue. It
should keep doing that until the chip->state has come back to FL_ERASING. That should not happen until the write function is finished and does its put_chip and erase resume.
>
> So what I'm saying is that just dropping the locks and letting other threads run is not, by itself itself, wrong. The code's supposed to do that. It's just that the other threads are supposed check the conditions when they wake up and only proceed if the conditions are correct.

So we need to know if dropping the lock is guarantied not to schedule some other thread

>
> But I do see something suspicious. I think it can be argued that all CFI thread wake-ups need to do the while (chip->state != chip_state) dance and go back to sleep if not.

Makes sense.

>
> That seems to be the case for inval_cache_and_wait_for_operation() but what about the other places where threads can be scheduled out? Won't they just wake up where they are or am I missing some wait queue magic?
>
> IOW: We should look for other places outside of inval_cache_and_wait_for_operation() that call things like msleep, schedule, and cond_resched. (One sneaky one is cfi_udelay as it may call cond_resched.)
>
> If any of those fail to do the chip->state != chip_state sleep loop when they awaken then we have have found our problem.
>

[SNIP]

>
> > I won't worry about this until you test my patch and still have a problem :)
> > Please test it.
>
> I tested it quickly on Friday and it didn't fix my problem, but we may be fighting different problems.

Yes, I am getting the feeling that there are 2 different problems.

>
> I also can't be sure the .c file didn't have other changes. I was really pressed for time that day.
>
> My plan is to retest your patch against a pristine copy of the file and report back. Unfortunately this has to wait until Monday as I don't have access to the hardware over the weekend.
>
> -Mike
>

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 6, 2011, at 4:40 AM, Joakim Tjernlund wrote:

> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/05 20:19:59:
>> 
> 
>> It's not that simple. Just waking the suspended erase thread should not cause it to "run" the way you are saying.
>> 
>> That thread *should* wake up in inval_cache_and_wait_for_operation() inside its while (chip->state != chip_state) loop. The purpose of that loop is to see if something else is going on with the chip and if so just go back to sleep. That should prevent what you are saying is happening and if it is
> not then we need to figure out why.
> 
> dropping the lock MIGTH make another thread waiting on that lock run if the scheduler decides so or so I think anyway but I am no expert :)

Nor am I! :-) And yes, that's completely true. But just running shouldn't do anything bad.

>> So what I'm saying is that just dropping the locks and letting other threads run is not, by itself itself, wrong. The code's supposed to do that. It's just that the other threads are supposed check the conditions when they wake up and only proceed if the conditions are correct.
> 
> So we need to know if dropping the lock is guarantied not to schedule some other thread

I think we can know that at least in SMP systems. If you have multiple cores, just dropping the chip->lock would immediately allow other threads to get past taking that same lock. And even on single-processor systems if the thread in question is over its quantum it can get scheduled out. (There may be special rules for kernel threads.)

>> But I do see something suspicious. I think it can be argued that all CFI thread wake-ups need to do the while (chip->state != chip_state) dance and go back to sleep if not.
> 
> Makes sense.
> 
>> That seems to be the case for inval_cache_and_wait_for_operation() but what about the other places where threads can be scheduled out? Won't they just wake up where they are or am I missing some wait queue magic?
>> 
>> IOW: We should look for other places outside of inval_cache_and_wait_for_operation() that call things like msleep, schedule, and cond_resched. (One sneaky one is cfi_udelay as it may call cond_resched.)
>> 
>> If any of those fail to do the chip->state != chip_state sleep loop when they awaken then we have have found our problem.

And I do see places where at least cond_resched() is being called but are not then followed by the chip->state test. But I need to go through it more rigorously. (cfi_udelay() really worries me. It makes it look like udelay() that doesn't schedule but really calls cond_resched() if the delay is large enough. Risky to hide that, IMO.)

>>> I won't worry about this until you test my patch and still have a problem :)
>>> Please test it.
>> 
>> I tested it quickly on Friday and it didn't fix my problem, but we may be fighting different problems.
> 
> Yes, I am getting the feeling that there are 2 different problems.

Yes. So a proper test of your patch on Monday and more digging.  Fun!

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 5, 2011, at 2:19 PM, Michael Cashwell wrote:

>> I won't worry about this until you test my patch and still have a problem :) Please test it.
> 
> My plan is to retest your patch against a pristine copy of the file and report back. Unfortunately this has to wait until Monday as I don't have access to the hardware over the weekend.

OK, I retested Joakim's patch from 4-feb on a clean source file and it doesn't help my problem:

[cashwell@mec-fedora14 linux-2.6.35.7-arm-gum]$ cat ../joakim.patch | patch -p1
patching file drivers/mtd/chips/cfi_cmdset_0001.c
Hunk #1 succeeded at 1227 (offset -18 lines).
Hunk #2 succeeded at 1266 (offset -18 lines).

(The offsets are just that we're on slightly different kernel versions, I assume. It applies OK.)

#### Exporting kernel linux-2.6.35.7-arm-gum to netboot.
Image Name:   2.6.35.7-gum1
Created:      Mon Feb  7 08:22:31 2011
Image Type:   ARM Linux Kernel Image (uncompressed)
Data Size:    1919908 Bytes = 1874.91 kB = 1.83 MB
Load Address: 0xA1000000
Entry Point:  0xA1000000

Booted and then did ubiformat, mount, rsync of about 20MB, and then during the umount of that file system:

UBI error: ubi_io_write: error -30 while writing 1968 bytes to PEB 17:37528, written 0 bytes
UBI warning: ubi_eba_write_leb: failed to write data to PEB 17
UBI warning: ubi_ro_mode: switch to read-only mode

which I'd previously traced to the -EROFS return in do_write_buffer because it thinks it got a block-locked error during write. I've also seen that sometimes see the bad Vpp error too. (Why one of those has a printk and not the other I don't know.)

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/07 16:10:03:
>
> On Feb 5, 2011, at 2:19 PM, Michael Cashwell wrote:
>
> >> I won't worry about this until you test my patch and still have a problem :) Please test it.
> >
> > My plan is to retest your patch against a pristine copy of the file and report back. Unfortunately this has to wait until Monday as I don't have access to the hardware over the weekend.
>
> OK, I retested Joakim's patch from 4-feb on a clean source file and it doesn't help my problem:
>
> [cashwell@mec-fedora14 linux-2.6.35.7-arm-gum]$ cat ../joakim.patch | patch -p1
> patching file drivers/mtd/chips/cfi_cmdset_0001.c
> Hunk #1 succeeded at 1227 (offset -18 lines).
> Hunk #2 succeeded at 1266 (offset -18 lines).
>
> (The offsets are just that we're on slightly different kernel versions, I assume. It applies OK.)

Yes, I got an extra patch in my driver as my chips both have top and bottom boot sector.


> #### Exporting kernel linux-2.6.35.7-arm-gum to netboot.
> Image Name:   2.6.35.7-gum1
> Created:      Mon Feb  7 08:22:31 2011
> Image Type:   ARM Linux Kernel Image (uncompressed)
> Data Size:    1919908 Bytes = 1874.91 kB = 1.83 MB
> Load Address: 0xA1000000
> Entry Point:  0xA1000000
>
> Booted and then did ubiformat, mount, rsync of about 20MB, and then during the umount of that file system:
>
> UBI error: ubi_io_write: error -30 while writing 1968 bytes to PEB 17:37528, written 0 bytes
> UBI warning: ubi_eba_write_leb: failed to write data to PEB 17
> UBI warning: ubi_ro_mode: switch to read-only mode
>
> which I'd previously traced to the -EROFS return in do_write_buffer because it thinks it got a block-locked error during write. I've also seen that sometimes see the bad Vpp error too. (Why one of those has a printk and not the other I don't know.)
>

Seems like you have another problem, does it only occur at umount? Perhaps UBI does something at umount
that the driver doesn't agree with?
Anyhow, will submit my patch soon, I hope you still agree that it fixes an bug. Just not your bug :(

I am on PPC BTW.

 Jocke

Re: Numonyx NOR and chip->mutex bug?

[Michael Cashwell]

On Feb 3, 2011, at 3:11 AM, Joakim Tjernlund wrote:

> Michael Cashwell <mboards@prograde.net> wrote on 2011/02/02 22:19:58:
>> 
> 
>> Note, the SR[7,2] bits its says are cleared by the command are not the error bits we're talking about. 7 and 2 are WSM-ready and erase-complete. The error bits are different ones. Maybe that's the confusion?
> 
> Yeah, didn't read this thoroughly enough, the comment talks about the status bits though. Seems like the safe thing to do even though I don't recall anyone running into this problem before.

Agreed. I expect it would only matter if the intervening operation (likely a buffered write) itself both failed and left its own error bits in the register. For all I know that can't happen because the status clear is done as part of handling those errors.

> Send it as a separate git patch though.

Is this a nudge to separate the patches (eg: don't do unrelated things in one patch), or are you saying the patch format must be based on a git tree? I must admit lameness regarding using git as it was not part of the workflow I inherited.

>>     map_write(map, CMD(0xd0), adr);
>> +    /* some numonyx P30 parts have an apparent delay after starting or
>> +     resuming some commands. this is normally covered by the cache
>> +     invalidation done between the command and the start of reading
>> +     for the busy status bit to clear. but no such cache invalidation
>> +     is done when resuming and this allows the status-reading thread
>> +     awakened below to read the status too soon and think its operation
>> +     has finished when it fact its resumption is still underway. */
>> +    udelay(20);

>>> Perhaps the chip gets confused by this command?
>>> Have you tried to remove the Read Status command?
>> 
>> I wondered about this too. But I recall seeing comments that said some particular Atmel part needed that command following an erase-resume in order to be in the Read-Status state the rest of the code expects. The comments also said that doing that command amounted to a NOP on other hardware, but maybe not. (!!)
>> 
>> It could be that removing that command instead of adding a delay would make mine work but I'm doubtful. If the 0x70 command is messing things up I don't see how adding a delay would avoid it.
> 
> Two things here:
> 1) Those comments about needing Read Status are very old may may not be true anymore.

Hmm. OK.

> 2) We need to explore the nature of this problem further. Adding a random delay isn't very appealing and may not fix the problem properly (it doesn't fix the problem for Stefan).

Yes, I agree. I'm not even sure Stefan's issue is the same as mine. His is a 1Gbit part I think.

>> I'm happy to try both of these and report back if you think it would help.
> 
> Yes, as I am not convinced this is the correct fix and what the problem really is. I still think it is worthwhile checking with Numonyx as we have seen buggy flashes from them earlier. Are you sure these flashes was delivered directly from Numonyx?

Well no. I'm just doing software support for a group that is using Gumstix CPU boards. We are not involved in any way in the manufacturing of the hardware and have no access or visibility into such information. (Gumstix won't release the CPU board schematics even under an NDA.) For these reasons we have a custom board in the pipeline but it's not ready yet so for now this is what we have.

I must say I'm confused by Numonyx not altering some chip ID number in the CFI data for these new parts. Once we do find a solution, if it needs to be specific to these parts that's going to be harder to pull off.

More to come after my testing today.

-Mike

Re: Numonyx NOR and chip->mutex bug?

[Joakim Tjernlund]

Michael Cashwell <mboards@prograde.net> wrote on 2011/02/03 14:24:53:
> On Feb 3, 2011, at 3:11 AM, Joakim Tjernlund wrote:
>
> > Michael Cashwell <mboards@prograde.net> wrote on 2011/02/02 22:19:58:
> >>
> >
> >> Note, the SR[7,2] bits its says are cleared by the command are not the error bits we're talking about. 7 and 2 are WSM-ready and erase-complete. The error bits are different ones. Maybe that's the confusion?
> >
> > Yeah, didn't read this thoroughly enough, the comment talks about the status bits though. Seems like the safe thing to do even though I don't recall anyone running into this problem before.
>
> Agreed. I expect it would only matter if the intervening operation (likely a buffered write) itself both failed and left its own error bits in the register. For all I know that can't happen because the status clear is done as part of handling those errors.
>
> > Send it as a separate git patch though.
>
> Is this a nudge to separate the patches (eg: don't do unrelated things in one patch), or are you saying the patch format must be based on a git tree? I must admit lameness regarding using git as it was not part of the workflow I inherited.

Both actually. I guess the patch doesn't doesn't have to be formatted with git but it
needs to follow some rules, see Documentation/SubmittingPatches

 Jocke

PS.
   Please hit enter every now and then :)