* UBI wear leveling / torture testing algorithms having trouble with MLC flash
@ 2010-04-13 1:00 Darwin Rambo
2010-04-14 17:30 ` Artem Bityutskiy
0 siblings, 1 reply; 6+ messages in thread
From: Darwin Rambo @ 2010-04-13 1:00 UTC (permalink / raw)
To: linux-mtd
[-- Attachment #1: Type: text/plain, Size: 5842 bytes --]
Setup:
I am using a Samsung 2GB MLC flash with 4K page size and 8-bit
hardware ECC support. I am using a 2.6.31 kernel, but if I read the
code right, the problem I see is in the latest 2.6.34-rc2 code as well.
Summary:
I traced a torture test caught in a repeating loop, wearing out a
flash block. It appears that the torture test with it's simple
0xA5/0x5A/0x00 pattern is passing, whereas actual application data
is consistently showing a bit flip on the same block. MLC flashes I
have used regularly show corrected errors over several blocks in time,
and also show corrected errors consistently due to program-disturb
effects, but these program disturb effects appear to be data dependent,
based on device geometry (e.g. adjacent multi-bit cell effects). The
scenario above can cause an repeating scrubbing / torture test loop
to occur. It is initiated by the nand driver reporting a bit correction
in a block which starts the scrubbing/torturing loop.
Details:
(Please correct me if I have got ubi parts of this explanation wrong - Thanks).
A single bit correction is a relatively normal event with MLC flash and
this triggers a scrub operation in UBI in which the block is considered
marginal, and the data is moved from a marginal block to a good block. A
good block is one that is considered to have passed the UBI torture test,
which simply writes 0xA5, 0x5A, and 0x00 to a block with 3 erases, and
then does a 4th erase for the user data that will eventually be copied to
this block. But this torture test is too simplistic since it doesn't
understand the geometry of MLC flashes and in particular, write-disturb
and read-disturb effects from neighboring cells and columns. What's maybe
needed is a torture test that understands the geometry and the bit correction
level 1,4,8,12 etc and is able to toggle geometrically neighboring bits rather
than view it as a simple memory test, but this may be difficult. Perhaps
torturing MLC blocks with only 3000 cycles is inappropriate anyways, why not
just trust the error correction and only mark uncorrectable blocks as bad?.
Since the torture test passes with no bit errors I believe that it didn't
find certain error correction patterns that appear with actual application
data. As a result, when the torture test passes, the block shows no correctable
errors, and is returned to the free pool. The original block X that had a
correctable error is scrubbed and it's data is copied to the free block with
the highest erase count. The highest erase count block is chosen and will remain
partially written and available for new scrubs, and data will be scrubbed to it
from other marginal blocks while the other blocks catch up in erase count. However,
if block Y previously had a bit error and was torture tested and passed, it's
erase count will go up by 4. As a result, block Y has a higher probability of
being the target of the copy from X to Y. But when the copy of actual application
data is done, block Y now shows a data-dependent correctable bit error again and
the scrub operation fails, and block Y is again sent out for torture testing, and
the process repeats itself until block Y either shows no error or the block wears
out, is marked bad, and another free block is chosen. So not only do blocks wear
out, but many blocks can be taken out of service as well by being marked bad. If
the available pool of free blocks for bad block management (typically 1% of the
total blocks in a partition) go bad, then the file system is remounted read-only
and the product becomes unusable for writable data in that partition. If I have a
3000 erase MLC part, then only 750 quick loops of the scrub/torture (4 erase) cycle
will wear the block out. At that point the next free block will be used which may
or may not show a corrected error.
Possible Solutions:
I think that with MLC flashes, we perhaps shouldn't be so aggressive to scrub/torture
given the more frequent error rate than we see with SLC parts. Also hiding the actual
corrections in the nand driver to hide the problem in UBI isn't a good long term
solution easier. The UBI algorithm doesn't appear to understand different levels
of correction possible. For example, on a 12-bit part, an single corrected error
is much more common and normal than say, 11 bit corrections on a marginal block,
but UBI treats 1 or 11 bits the same algorithmically. The ecc correction capability
maybe should be known by UBI so it can make better decisions about when to run
scrub/torture algorithms? Or perhaps we don't do torturing at all with MLC flash and
rely on the multi-bit correction instead to help us. The correction level and the
flash type could be useful information for UBI to use in deciding algorithms like these.
The short term solution might be for the nand driver to hide error corrections from
the UBI wear leveling software by reporting all good corrections as 0 errors. Then
UBI shouldn't start scrubbing and torturing on a single bit error in a block. Two
blocks with a single error that are part of the scrubbing/torturing duo start the
loop of flash erasing/wear out.
I also attach a log file I collected demonstrating the problem, with some annotations
inline. The log are basically the existing printk's plus a few of my own converted to
log quickly to RAM to avoid cluttering the console and destabilizing real time.
I hope this helps us understand and support MLC flash a bit better. I am curious to
know if anyone else has seen problems like these and how they dealt with them.
Thanks.
Darwin
Disclaimer - Any views or opinions presented in this e-mail are solely those of the author
and do not necessarily represent those of the company.
[-- Attachment #2: mtd_torture_reasons.txt --]
[-- Type: text/plain, Size: 76818 bytes --]
0.000: 0.000: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
1.485: 1.485: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
129.584: 128.098: ubi_leb_read: UBI DBG (pid 1987): read 66 bytes from LEB 0:56:112280
129.592: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 66 bytes from offset 112280 of LEB 0:56, PEB 58
129.631: 0.039: ubi_io_read: UBI DBG (pid 1987): read 66 bytes from PEB 58:120472
180.587: 50.956: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 5:8192
181.144: 0.557: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:112120
181.150: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 112120 of LEB 0:56, PEB 58
181.152: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:120312
181.281: 0.129: ubi_leb_read: UBI DBG (pid 1987): read 1307 bytes from LEB 0:56:110808
181.286: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1307 bytes from offset 110808 of LEB 0:56, PEB 58
181.287: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1307 bytes from PEB 58:119000
281.086: 99.799: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 5
281.089: 0.002: ubi_eba_copy_leb: UBI warning: ubi_io_read_data MOVE_CANCEL_BITFLIPS
281.094: 0.005: wear_leveling_worker: UBI error: err 5 PEB1=253 PEB2=5
281.095: 0.000: wear_leveling_worker: UBI error: !!!!!!!!torture=1!!!!!!!!! err 5 PEB1=253 PEB2=5
281.096: 0.001: wear_leveling_worker: UBI DBG (pid 480): cancel moving PEB 253 (LEB 0:251) to PEB 5 (5)
281.099: 0.002: wear_leveling_worker: UBI DBG (pid 480): calling schedule_erase, torture=1
281.100: 0.001: schedule_erase: UBI DBG (pid 480): schedule erasure of PEB 5, EC 143, torture 1
281.108: 0.008: erase_worker: UBI DBG (pid 480): erase PEB 5 EC 143
281.110: 0.001: sync_erase: UBI DBG (pid 480): erase PEB 5, old EC 143
281.119: 0.009: ubi_io_read_ec_hdr: UBI DBG (pid 480): read EC header from PEB 5
281.121: 0.001: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
281.757: 0.636: torture_peb: UBI: run torture test for PEB 5
281.759: 0.002: do_sync_erase: UBI DBG (pid 480): erase PEB 5
301.897: 20.138: ubi_leb_read: UBI DBG (pid 1987): read 71 bytes from LEB 0:56:68480
301.998: 0.100: ubi_eba_read_leb: UBI DBG (pid 1987): read 71 bytes from offset 68480 of LEB 0:56, PEB 58
301.999: 0.001: ubi_io_read: UBI DBG (pid 1987): read 71 bytes from PEB 58:76672
412.476: 110.477: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:68320
412.483: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 68320 of LEB 0:56, PEB 58
412.484: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:76512
412.612: 0.128: ubi_leb_read: UBI DBG (pid 1987): read 855 bytes from LEB 0:56:67464
412.617: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 855 bytes from offset 67464 of LEB 0:56, PEB 58
412.618: 0.001: ubi_io_read: UBI DBG (pid 1987): read 855 bytes from PEB 58:75656
430.148: 17.529: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
569.659: 139.511: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
576.526: 6.867: ubi_leb_read: UBI DBG (pid 1987): read 72 bytes from LEB 0:56:73824
576.627: 0.101: ubi_eba_read_leb: UBI DBG (pid 1987): read 72 bytes from offset 73824 of LEB 0:56, PEB 58
576.629: 0.001: ubi_io_read: UBI DBG (pid 1987): read 72 bytes from PEB 58:82016
695.469: 118.839: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:73664
695.474: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 73664 of LEB 0:56, PEB 58
695.476: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:81856
696.638: 1.162: ubi_leb_read: UBI DBG (pid 1987): read 1246 bytes from LEB 0:56:72416
696.645: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1246 bytes from offset 72416 of LEB 0:56, PEB 58
696.646: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1246 bytes from PEB 58:80608
697.784: 1.137: ubi_leb_read: UBI DBG (pid 1987): read 1273 bytes from LEB 0:56:68552
697.791: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1273 bytes from offset 68552 of LEB 0:56, PEB 58
697.793: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1273 bytes from PEB 58:76744
709.389: 11.595: ubi_leb_read: UBI DBG (pid 1987): read 1202 bytes from LEB 0:56:69832
709.395: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1202 bytes from offset 69832 of LEB 0:56, PEB 58
709.397: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1202 bytes from PEB 58:78024
860.978: 151.581: ubi_leb_read: UBI DBG (pid 1987): read 1371 bytes from LEB 0:56:71040
860.985: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1371 bytes from offset 71040 of LEB 0:56, PEB 58
860.987: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1371 bytes from PEB 58:79232
871.862: 10.875: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
964.309: 92.447: do_sync_erase: UBI DBG (pid 480): erase PEB 5
1107.940: 143.630: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
1146.081: 38.141: ubi_leb_read: UBI DBG (pid 1987): read 64 bytes from LEB 0:56:264304
1146.088: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 64 bytes from offset 264304 of LEB 0:56, PEB 58
1146.089: 0.001: ubi_io_read: UBI DBG (pid 1987): read 64 bytes from PEB 58:272496
1251.786: 105.696: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:312:489752
1251.792: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 489752 of LEB 0:312, PEB 314
1251.793: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 314:497944
1252.350: 0.557: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:398976
1252.354: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 398976 of LEB 0:308, PEB 310
1252.355: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:407168
1252.874: 0.519: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:264144
1252.878: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 264144 of LEB 0:56, PEB 58
1252.879: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:272336
1253.421: 0.542: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:312:489944
1253.425: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 489944 of LEB 0:312, PEB 314
1253.426: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 314:498136
1253.990: 0.563: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:399360
1253.994: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 399360 of LEB 0:308, PEB 310
1253.995: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:407552
1254.515: 0.520: ubi_leb_read: UBI DBG (pid 1987): read 78 bytes from LEB 0:56:222304
1254.519: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 78 bytes from offset 222304 of LEB 0:56, PEB 58
1254.520: 0.001: ubi_io_read: UBI DBG (pid 1987): read 78 bytes from PEB 58:230496
1255.119: 0.598: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:222144
1255.133: 0.013: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 222144 of LEB 0:56, PEB 58
1255.134: 0.000: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:230336
1255.367: 0.233: ubi_leb_read: UBI DBG (pid 1987): read 996 bytes from LEB 0:56:221144
1255.373: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 996 bytes from offset 221144 of LEB 0:56, PEB 58
1255.375: 0.001: ubi_io_read: UBI DBG (pid 1987): read 996 bytes from PEB 58:229336
1262.230: 6.855: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
1349.294: 87.064: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:399168
1349.398: 0.103: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 399168 of LEB 0:308, PEB 310
1349.400: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:407360
1560.300: 210.900: ubi_leb_read: UBI DBG (pid 1987): read 69 bytes from LEB 0:56:243944
1560.306: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 69 bytes from offset 243944 of LEB 0:56, PEB 58
1560.307: 0.001: ubi_io_read: UBI DBG (pid 1987): read 69 bytes from PEB 58:252136
1560.860: 0.553: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:399936
1560.864: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 399936 of LEB 0:308, PEB 310
1560.872: 0.007: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:408128
1561.424: 0.552: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:243784
1561.428: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 243784 of LEB 0:56, PEB 58
1561.429: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:251976
1561.905: 0.475: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
1562.091: 0.186: ubi_leb_read: UBI DBG (pid 1987): read 1016 bytes from LEB 0:56:242768
1562.110: 0.019: ubi_eba_read_leb: UBI DBG (pid 1987): read 1016 bytes from offset 242768 of LEB 0:56, PEB 58
1562.111: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1016 bytes from PEB 58:250960
1569.760: 7.648: ubi_leb_read: UBI DBG (pid 1987): read 72 bytes from LEB 0:56:251624
1569.768: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 72 bytes from offset 251624 of LEB 0:56, PEB 58
1569.770: 0.001: ubi_io_read: UBI DBG (pid 1987): read 72 bytes from PEB 58:259816
1570.371: 0.601: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:400128
1570.376: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 400128 of LEB 0:308, PEB 310
1570.377: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:408320
1570.963: 0.585: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:251464
1570.967: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 251464 of LEB 0:56, PEB 58
1570.968: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:259656
1571.610: 0.642: ubi_leb_read: UBI DBG (pid 1987): read 501 bytes from LEB 0:56:250960
1571.616: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 501 bytes from offset 250960 of LEB 0:56, PEB 58
1571.618: 0.001: ubi_io_read: UBI DBG (pid 1987): read 501 bytes from PEB 58:259152
1572.043: 0.425: ubi_leb_read: UBI DBG (pid 1987): read 1649 bytes from LEB 0:56:245904
1572.051: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1649 bytes from offset 245904 of LEB 0:56, PEB 58
1572.052: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1649 bytes from PEB 58:254096
1575.046: 2.993: ubi_leb_read: UBI DBG (pid 1987): read 1596 bytes from LEB 0:56:247560
1575.051: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1596 bytes from offset 247560 of LEB 0:56, PEB 58
1575.053: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1596 bytes from PEB 58:255752
1577.320: 2.266: ubi_leb_read: UBI DBG (pid 1987): read 1799 bytes from LEB 0:56:249160
1577.324: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1799 bytes from offset 249160 of LEB 0:56, PEB 58
1577.325: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1799 bytes from PEB 58:257352
1663.951: 86.626: do_sync_erase: UBI DBG (pid 480): erase PEB 5
1806.124: 142.172: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
1957.009: 150.885: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
2264.119: 307.109: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
2349.849: 85.730: torture_peb: UBI: PEB 5 passed torture test, do not mark it a bad
PEB 5 is considered good at this point. Now it is available to copy data to. Ignore the history for now.
2349.852: 0.003: do_sync_erase: UBI DBG (pid 480): erase PEB 5
2493.081: 143.228: sync_erase: UBI DBG (pid 480): erased PEB 5, new EC 147 max_ec=143
Note that PEB 5's EC has gone up by 4, due to the torture test (3 erases/writes) and the final erase for new data.
2493.084: 0.002: ubi_io_write_ec_hdr: UBI DBG (pid 480): write EC header to PEB 5
2493.093: 0.009: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:0
The EC header has been written to PEB 5 now with EC 147.
2495.008: 1.914: ensure_wear_leveling: UBI DBG (pid 480): schedule scrubbing
2495.024: 0.016: wear_leveling_worker: UBI DBG (pid 480): scrub PEB 253 to PEB 5
PEB 253 previously reported a fixable bit error, so it is to be scrubbed. PEB 5 is the target due to it's high EC.
2495.026: 0.002: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 253
2495.028: 0.001: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 253:4096
Now we start copying data from PEB 253 to PEB 5
2495.620: 0.591: ubi_eba_copy_leb: UBI DBG (pid 480): copy LEB 0:251, PEB 253 to PEB 5
2495.627: 0.007: ubi_eba_copy_leb: UBI DBG (pid 480): read 516096 bytes of data
2495.628: 0.001: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 253:8192
2569.842: 74.214: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 253
PEB 253 is showing a bit flip again but not a problem since it is the source and is fixable.
2576.945: 7.102: ubi_io_write_vid_hdr: UBI DBG (pid 480): write VID header to PEB 5
2576.956: 0.011: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
2577.578: 0.622: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:4096
2579.395: 1.816: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 5
2579.398: 0.002: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
2580.011: 0.613: ubi_io_write: UBI DBG (pid 480): write 516096 bytes to PEB 5:8192
2717.385: 137.374: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
2717.415: 0.029: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
2899.315: 181.900: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 5:8192
We have written the PEB 5 volume id header (VID) and read it back, and wrote and read back the complete block.
2908.595: 9.279: ubi_leb_read: UBI DBG (pid 1987): read 70 bytes from LEB 0:56:264072
2908.602: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 70 bytes from offset 264072 of LEB 0:56, PEB 58
2908.604: 0.001: ubi_io_read: UBI DBG (pid 1987): read 70 bytes from PEB 58:272264
2984.661: 76.057: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 5
The target block PEB 5 is also showing a bit flip.
2984.663: 0.002: ubi_eba_copy_leb: UBI warning: ubi_io_read_data MOVE_CANCEL_BITFLIPS
The copy operation is canceled due to bitflips in the target block PEB 5.
2984.669: 0.005: wear_leveling_worker: UBI error: err 5 PEB1=253 PEB2=5
2984.669: 0.000: wear_leveling_worker: UBI error: !!!!!!!!torture=1!!!!!!!!! err 5 PEB1=253 PEB2=5
2984.671: 0.001: wear_leveling_worker: UBI DBG (pid 480): cancel moving PEB 253 (LEB 0:251) to PEB 5 (5)
2984.673: 0.002: wear_leveling_worker: UBI DBG (pid 480): calling schedule_erase, torture=1
2984.675: 0.001: scheule_erase: UBI DBG (pid 480): schedule erasure of PEB 5, EC 147, torture 1
The wear leveling worker doesn't like bit flips in the target block which is supposed to be freshly erased
and good. So torture test it to see what is going on with the bit flips in PEB 5.
2984.683: 0.008: erase_worker: UBI DBG (pid 480): erase PEB 5 EC 147
2984.684: 0.001: sync_erase: UBI DBG (pid 480): erase PEB 5, old EC 147
2984.694: 0.009: ubi_io_read_ec_hdr: UBI DBG (pid 480): read EC header from PEB 5
2984.695: 0.001: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
2984.743: 0.047: torture_peb: UBI: run torture test for PEB 5
2984.744: 0.001: do_sync_erase: UBI DBG (pid 480): erase PEB 5
Torture test for PEB 5 is underway. Ignore the pid 1987 stuff, that's a different thread from the wear leveling.
3111.976: 127.231: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:400320
3111.982: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 400320 of LEB 0:308, PEB 310
3111.984: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:408512
3112.519: 0.535: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:263912
3112.524: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 263912 of LEB 0:56, PEB 58
3112.525: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:272104
3113.161: 0.636: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:400512
3113.167: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 400512 of LEB 0:308, PEB 310
3113.168: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:408704
3113.724: 0.555: ubi_leb_read: UBI DBG (pid 1987): read 479 bytes from LEB 0:56:263432
3113.728: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 479 bytes from offset 263432 of LEB 0:56, PEB 58
3113.729: 0.001: ubi_io_read: UBI DBG (pid 1987): read 479 bytes from PEB 58:271624
3114.607: 0.877: ubi_leb_read: UBI DBG (pid 1987): read 1618 bytes from LEB 0:56:261808
3114.614: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1618 bytes from offset 261808 of LEB 0:56, PEB 58
3114.616: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1618 bytes from PEB 58:270000
3138.751: 24.135: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
3281.804: 143.052: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
3607.750: 325.945: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
3692.455: 84.705: do_sync_erase: UBI DBG (pid 480): erase PEB 5
3835.756: 143.301: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
3986.721: 150.964: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
Keep erasing and testing PEB 5.
4196.464: 209.742: ubi_leb_read: UBI DBG (pid 1987): read 84 bytes from LEB 0:56:242680
4196.471: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 84 bytes from offset 242680 of LEB 0:56, PEB 58
4196.473: 0.001: ubi_io_read: UBI DBG (pid 1987): read 84 bytes from PEB 58:250872
4282.565: 86.092: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:242520
4282.571: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 242520 of LEB 0:56, PEB 58
4282.573: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:250712
4282.710: 0.137: ubi_leb_read: UBI DBG (pid 1987): read 565 bytes from LEB 0:56:241952
4282.715: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 565 bytes from offset 241952 of LEB 0:56, PEB 58
4282.716: 0.001: ubi_io_read: UBI DBG (pid 1987): read 565 bytes from PEB 58:250144
4283.089: 0.372: ubi_leb_read: UBI DBG (pid 1987): read 1748 bytes from LEB 0:56:240200
4283.096: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1748 bytes from offset 240200 of LEB 0:56, PEB 58
4283.098: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1748 bytes from PEB 58:248392
4311.238: 28.140: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
4379.297: 68.059: ubi_leb_read: UBI DBG (pid 1987): read 81 bytes from LEB 0:56:237352
4379.305: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 81 bytes from offset 237352 of LEB 0:56, PEB 58
4379.306: 0.001: ubi_io_read: UBI DBG (pid 1987): read 81 bytes from PEB 58:245544
4395.013: 15.707: do_sync_erase: UBI DBG (pid 480): erase PEB 5
4523.789: 128.775: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:399744
4523.794: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 399744 of LEB 0:308, PEB 310
4523.795: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:407936
4524.329: 0.533: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:237192
4524.334: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 237192 of LEB 0:56, PEB 58
4524.335: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:245384
4524.976: 0.640: ubi_leb_read: UBI DBG (pid 1987): read 209 bytes from LEB 0:56:236976
4524.982: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 209 bytes from offset 236976 of LEB 0:56, PEB 58
4524.983: 0.001: ubi_io_read: UBI DBG (pid 1987): read 209 bytes from PEB 58:245168
4525.319: 0.335: ubi_leb_read: UBI DBG (pid 1987): read 1738 bytes from LEB 0:56:235232
4525.326: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1738 bytes from offset 235232 of LEB 0:56, PEB 58
4525.328: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1738 bytes from PEB 58:243424
4539.662: 14.334: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
4679.770: 140.108: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
4792.643: 112.873: ubi_leb_read: UBI DBG (pid 1987): read 79 bytes from LEB 0:56:230200
4792.650: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 79 bytes from offset 230200 of LEB 0:56, PEB 58
4792.652: 0.001: ubi_io_read: UBI DBG (pid 1987): read 79 bytes from PEB 58:238392
4970.647: 177.994: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:399552
4970.653: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 399552 of LEB 0:308, PEB 310
4970.654: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:407744
4971.505: 0.850: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
4971.866: 0.360: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:230040
4971.871: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 230040 of LEB 0:56, PEB 58
4971.872: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:238232
4972.579: 0.706: ubi_leb_read: UBI DBG (pid 1987): read 583 bytes from LEB 0:56:229456
4972.585: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 583 bytes from offset 229456 of LEB 0:56, PEB 58
4972.586: 0.001: ubi_io_read: UBI DBG (pid 1987): read 583 bytes from PEB 58:237648
4972.988: 0.401: ubi_leb_read: UBI DBG (pid 1987): read 1523 bytes from LEB 0:56:227928
4972.995: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1523 bytes from offset 227928 of LEB 0:56, PEB 58
4972.997: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1523 bytes from PEB 58:236120
5075.616: 102.619: torture_peb: UBI: PEB 5 passed torture test, do not mark it a bad
5075.620: 0.003: do_sync_erase: UBI DBG (pid 480): erase PEB 5
5261.789: 186.168: sync_erase: UBI DBG (pid 480): erased PEB 5, new EC 151 max_ec=147
Well, the simple 3 patterns were written and read back successfully without bit flips. Fixup PEB 5 headers.
5261.791: 0.002: ubi_io_write_ec_hdr: UBI DBG (pid 480): write EC header to PEB 5
5261.800: 0.009: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:0
5272.986: 11.185: ensure_wear_leveling: UBI DBG (pid 480): schedule scrubbing
5273.004: 0.018: wear_leveling_worker: UBI DBG (pid 480): scrub PEB 253 to PEB 5
PEB 5 is good based on torture test result. Now we scrub the original PEB 253 with bitflips. Since we scrub to the
PEB with the highest EC, good old PEB 5 is the target again.
5273.007: 0.002: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 253
5273.008: 0.001: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 253:4096
5273.708: 0.700: ubi_eba_copy_leb: UBI DBG (pid 480): copy LEB 0:251, PEB 253 to PEB 5
5273.716: 0.007: ubi_eba_copy_leb: UBI DBG (pid 480): read 516096 bytes of data
5273.717: 0.001: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 253:8192
5352.578: 78.861: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 253
Source PEB 253 is showing a bit flip reading it's data but no big deal.
5359.506: 6.927: ubi_io_write_vid_hdr: UBI DBG (pid 480): write VID header to PEB 5
5359.516: 0.010: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
5360.152: 0.635: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:4096
5362.063: 1.911: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 5
5362.065: 0.002: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
5362.686: 0.620: ubi_io_write: UBI DBG (pid 480): write 516096 bytes to PEB 5:8192
5500.296: 137.609: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
5500.325: 0.029: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
5681.364: 181.039: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 5:8192
5782.059: 100.694: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 5
5782.061: 0.002: ubi_eba_copy_leb: UBI warning: ubi_io_read_data MOVE_CANCEL_BITFLIPS
But the target PEB 5 is showing another fixable bit flip even though it passed the torture test previously.
So it appears that the simple torture test patterns aren't good enough to represent real data
patterns that show specific bit flips. Another problem is that UBI is panicking on bit flips which
aren't necessarily problems for MLC and are perhaps more appropriate concerns for SLC. We should
consider hiding these benign bit flips from UBI so it doesn't enter these loops, killing blocks of
flash with excessive erase activity. We should also look into why the 2 blocks are each getting bit flips.
5782.066: 0.005: wear_leveling_worker: UBI error: err 5 PEB1=253 PEB2=5
5782.067: 0.000: wear_leveling_worker: UBI error: !!!!!!!!torture=1!!!!!!!!! err 5 PEB1=253 PEB2=5
5782.069: 0.001: wear_leveling_worker: UBI DBG (pid 480): cancel moving PEB 253 (LEB 0:251) to PEB 5 (5)
5782.071: 0.002: wear_leveling_worker: UBI DBG (pid 480): calling schedule_erase, torture=1
5782.073: 0.001: schedule_erase: UBI DBG (pid 480): schedule erasure of PEB 5, EC 151, torture 1
5782.082: 0.008: erase_worker: UBI DBG (pid 480): erase PEB 5 EC 151
5782.083: 0.001: sync_erase: UBI DBG (pid 480): erase PEB 5, old EC 151
5782.093: 0.009: ubi_io_read_ec_hdr: UBI DBG (pid 480): read EC header from PEB 5
5782.094: 0.001: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
5782.142: 0.048: torture_peb: UBI: run torture test for PEB 5
5782.144: 0.001: do_sync_erase: UBI DBG (pid 480): erase PEB 5
5925.311: 143.166: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
6021.403: 96.092: ubi_leb_read: UBI DBG (pid 1987): read 72 bytes from LEB 0:56:226288
6021.410: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 72 bytes from offset 226288 of LEB 0:56, PEB 58
6021.412: 0.001: ubi_io_read: UBI DBG (pid 1987): read 72 bytes from PEB 58:234480
6063.802: 42.389: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
6188.641: 124.839: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:226128
6188.647: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 226128 of LEB 0:56, PEB 58
6188.649: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:234320
6188.789: 0.139: ubi_leb_read: UBI DBG (pid 1987): read 509 bytes from LEB 0:56:225616
6188.794: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 509 bytes from offset 225616 of LEB 0:56, PEB 58
6188.795: 0.001: ubi_io_read: UBI DBG (pid 1987): read 509 bytes from PEB 58:233808
6189.201: 0.405: ubi_leb_read: UBI DBG (pid 1987): read 1660 bytes from LEB 0:56:222384
6189.209: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1660 bytes from offset 222384 of LEB 0:56, PEB 58
6189.211: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1660 bytes from PEB 58:230576
6192.222: 3.011: ubi_leb_read: UBI DBG (pid 1987): read 1567 bytes from LEB 0:56:224048
6192.228: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1567 bytes from offset 224048 of LEB 0:56, PEB 58
6192.230: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1567 bytes from PEB 58:232240
6386.106: 193.876: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
6461.327: 75.221: ubi_leb_read: UBI DBG (pid 1987): read 74 bytes from LEB 0:56:261728
6461.335: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 74 bytes from offset 261728 of LEB 0:56, PEB 58
6461.376: 0.041: ubi_io_read: UBI DBG (pid 1987): read 74 bytes from PEB 58:269920
6471.220: 9.844: do_sync_erase: UBI DBG (pid 480): erase PEB 5
6599.652: 128.432: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:261568
6599.658: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 261568 of LEB 0:56, PEB 58
6599.660: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:269760
6599.800: 0.139: ubi_leb_read: UBI DBG (pid 1987): read 933 bytes from LEB 0:56:260632
6599.804: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 933 bytes from offset 260632 of LEB 0:56, PEB 58
6599.806: 0.001: ubi_io_read: UBI DBG (pid 1987): read 933 bytes from PEB 58:268824
6600.362: 0.556: ubi_leb_read: UBI DBG (pid 1987): read 1783 bytes from LEB 0:56:252896
6600.369: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1783 bytes from offset 252896 of LEB 0:56, PEB 58
6600.371: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1783 bytes from PEB 58:261088
6603.832: 3.461: ubi_leb_read: UBI DBG (pid 1987): read 1468 bytes from LEB 0:56:254680
6603.838: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1468 bytes from offset 254680 of LEB 0:56, PEB 58
6603.840: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1468 bytes from PEB 58:262872
6606.163: 2.323: ubi_leb_read: UBI DBG (pid 1987): read 1524 bytes from LEB 0:56:256152
6606.168: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1524 bytes from offset 256152 of LEB 0:56, PEB 58
6606.169: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1524 bytes from PEB 58:264344
6608.453: 2.283: ubi_leb_read: UBI DBG (pid 1987): read 1200 bytes from LEB 0:56:257680
6608.457: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1200 bytes from offset 257680 of LEB 0:56, PEB 58
6608.458: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1200 bytes from PEB 58:265872
6611.399: 2.940: ubi_leb_read: UBI DBG (pid 1987): read 1751 bytes from LEB 0:56:258880
6611.405: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1751 bytes from offset 258880 of LEB 0:56, PEB 58
6611.406: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1751 bytes from PEB 58:267072
6629.201: 17.795: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
6767.960: 138.758: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
7082.009: 314.049: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
7177.357: 95.347: do_sync_erase: UBI DBG (pid 480): erase PEB 5
7211.693: 34.336: ubi_leb_read: UBI DBG (pid 1987): read 72 bytes from LEB 0:56:252824
7211.796: 0.103: ubi_eba_read_leb: UBI DBG (pid 1987): read 72 bytes from offset 252824 of LEB 0:56, PEB 58
7211.798: 0.001: ubi_io_read: UBI DBG (pid 1987): read 72 bytes from PEB 58:261016
7306.799: 95.000: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:252664
7306.805: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 252664 of LEB 0:56, PEB 58
7306.807: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:260856
7306.943: 0.136: ubi_leb_read: UBI DBG (pid 1987): read 968 bytes from LEB 0:56:251696
7306.948: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 968 bytes from offset 251696 of LEB 0:56, PEB 58
7306.949: 0.001: ubi_io_read: UBI DBG (pid 1987): read 968 bytes from PEB 58:259888
7330.160: 23.210: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
7476.590: 146.430: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
7517.937: 41.347: ubi_leb_read: UBI DBG (pid 1987): read 74 bytes from LEB 0:56:240120
7517.944: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 74 bytes from offset 240120 of LEB 0:56, PEB 58
7517.946: 0.001: ubi_io_read: UBI DBG (pid 1987): read 74 bytes from PEB 58:248312
7763.137: 245.191: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:239960
7763.143: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 239960 of LEB 0:56, PEB 58
7763.145: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:248152
7763.282: 0.136: ubi_leb_read: UBI DBG (pid 1987): read 718 bytes from LEB 0:56:239240
7763.286: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 718 bytes from offset 239240 of LEB 0:56, PEB 58
7763.288: 0.001: ubi_io_read: UBI DBG (pid 1987): read 718 bytes from PEB 58:247432
7763.686: 0.398: ubi_leb_read: UBI DBG (pid 1987): read 1800 bytes from LEB 0:56:237440
7763.693: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1800 bytes from offset 237440 of LEB 0:56, PEB 58
7763.695: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1800 bytes from PEB 58:245632
7781.264: 17.569: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
7875.708: 94.443: torture_peb: UBI: PEB 5 passed torture test, do not mark it a bad
7875.712: 0.003: do_sync_erase: UBI DBG (pid 480): erase PEB 5
7948.019: 72.307: ubi_leb_read: UBI DBG (pid 1987): read 79 bytes from LEB 0:56:245824
7948.026: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 79 bytes from offset 245824 of LEB 0:56, PEB 58
7948.028: 0.001: ubi_io_read: UBI DBG (pid 1987): read 79 bytes from PEB 58:254016
8017.000: 68.972: sync_erase: UBI DBG (pid 480): erased PEB 5, new EC 155 max_ec=151
8017.002: 0.002: ubi_io_write_ec_hdr: UBI DBG (pid 480): write EC header to PEB 5
8017.011: 0.008: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:0
8018.861: 1.850: ensure_wear_leveling: UBI DBG (pid 480): schedule scrubbing
8018.876: 0.014: wear_leveling_worker: UBI DBG (pid 480): scrub PEB 253 to PEB 5
8018.878: 0.002: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 253
8018.879: 0.001: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 253:4096
8019.447: 0.567: ubi_eba_copy_leb: UBI DBG (pid 480): copy LEB 0:251, PEB 253 to PEB 5
8019.453: 0.006: ubi_eba_copy_leb: UBI DBG (pid 480): read 516096 bytes of data
8019.454: 0.001: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 253:8192
8087.708: 68.253: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 253
8088.199: 0.490: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:245664
8088.204: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 245664 of LEB 0:56, PEB 58
8088.206: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:253856
8089.384: 1.177: ubi_leb_read: UBI DBG (pid 1987): read 1645 bytes from LEB 0:56:244016
8089.390: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1645 bytes from offset 244016 of LEB 0:56, PEB 58
8089.392: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1645 bytes from PEB 58:252208
8097.010: 7.618: ubi_io_write_vid_hdr: UBI DBG (pid 480): write VID header to PEB 5
8097.022: 0.011: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
8097.598: 0.576: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:4096
8099.278: 1.680: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 5
8099.280: 0.001: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
8099.795: 0.515: ubi_io_write: UBI DBG (pid 480): write 516096 bytes to PEB 5:8192
8187.209: 87.413: ubi_leb_read: UBI DBG (pid 1987): read 80 bytes from LEB 0:56:227848
8187.216: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 80 bytes from offset 227848 of LEB 0:56, PEB 58
8187.218: 0.001: ubi_io_read: UBI DBG (pid 1987): read 80 bytes from PEB 58:236040
8254.447: 67.229: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
8254.476: 0.028: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
8412.287: 157.810: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 5:8192
8412.863: 0.575: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:227688
8412.869: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 227688 of LEB 0:56, PEB 58
8412.870: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:235880
8413.007: 0.136: ubi_leb_read: UBI DBG (pid 1987): read 1321 bytes from LEB 0:56:226360
8413.012: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1321 bytes from offset 226360 of LEB 0:56, PEB 58
8413.013: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1321 bytes from PEB 58:234552
8521.422: 108.408: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 5
8521.424: 0.002: ubi_eba_copy_leb: UBI warning: ubi_io_read_data MOVE_CANCEL_BITFLIPS
8521.430: 0.005: wear_leveling_worker: UBI error: err 5 PEB1=253 PEB2=5
8521.431: 0.001: wear_leveling_worker: UBI error: !!!!!!!!torture=1!!!!!!!!! err 5 PEB1=253 PEB2=5
8521.432: 0.001: wear_leveling_worker: UBI DBG (pid 480): cancel moving PEB 253 (LEB 0:251) to PEB 5 (5)
8521.435: 0.002: wear_leveling_worker: UBI DBG (pid 480): calling schedule_erase, torture=1
8521.436: 0.001: schedule_erase: UBI DBG (pid 480): schedule erasure of PEB 5, EC 155, torture 1
8521.444: 0.008: erase_worker: UBI DBG (pid 480): erase PEB 5 EC 155
8521.446: 0.001: sync_erase: UBI DBG (pid 480): erase PEB 5, old EC 155
8521.455: 0.009: ubi_io_read_ec_hdr: UBI DBG (pid 480): read EC header from PEB 5
8521.457: 0.001: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
8522.079: 0.622: torture_peb: UBI: run torture test for PEB 5
8522.081: 0.002: do_sync_erase: UBI DBG (pid 480): erase PEB 5
8533.376: 11.294: ubi_leb_read: UBI DBG (pid 1987): read 83 bytes from LEB 0:56:235144
8533.383: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 83 bytes from offset 235144 of LEB 0:56, PEB 58
8533.384: 0.001: ubi_io_read: UBI DBG (pid 1987): read 83 bytes from PEB 58:243336
8658.103: 124.718: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:234984
8658.108: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 234984 of LEB 0:56, PEB 58
8658.110: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:243176
8658.252: 0.142: ubi_leb_read: UBI DBG (pid 1987): read 996 bytes from LEB 0:56:233984
8658.257: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 996 bytes from offset 233984 of LEB 0:56, PEB 58
8658.258: 0.001: ubi_io_read: UBI DBG (pid 1987): read 996 bytes from PEB 58:242176
8658.720: 0.462: ubi_leb_read: UBI DBG (pid 1987): read 1881 bytes from LEB 0:56:230280
8658.728: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1881 bytes from offset 230280 of LEB 0:56, PEB 58
8658.730: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1881 bytes from PEB 58:238472
8663.085: 4.354: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
8666.227: 3.142: ubi_leb_read: UBI DBG (pid 1987): read 1809 bytes from LEB 0:56:232168
8666.326: 0.099: ubi_eba_read_leb: UBI DBG (pid 1987): read 1809 bytes from offset 232168 of LEB 0:56, PEB 58
8666.328: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1809 bytes from PEB 58:240360
8811.130: 144.801: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
9125.992: 314.862: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
9179.319: 53.327: ubi_leb_read: UBI DBG (pid 1987): read 64 bytes from LEB 0:56:149408
9179.368: 0.049: ubi_eba_read_leb: UBI DBG (pid 1987): read 64 bytes from offset 149408 of LEB 0:56, PEB 58
9179.370: 0.002: ubi_io_read: UBI DBG (pid 1987): read 64 bytes from PEB 58:157600
9209.639: 30.268: do_sync_erase: UBI DBG (pid 480): erase PEB 5
9351.451: 141.812: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:149248
9351.457: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 149248 of LEB 0:56, PEB 58
9351.459: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:157440
9351.506: 0.047: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:395520
9351.509: 0.002: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 395520 of LEB 0:308, PEB 310
9351.510: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:403712
9352.049: 0.538: ubi_leb_read: UBI DBG (pid 1987): read 71 bytes from LEB 0:56:143296
9352.053: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 71 bytes from offset 143296 of LEB 0:56, PEB 58
9352.054: 0.001: ubi_io_read: UBI DBG (pid 1987): read 71 bytes from PEB 58:151488
9353.120: 1.065: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:395904
9353.124: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 395904 of LEB 0:308, PEB 310
9353.125: 0.000: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:404096
9353.652: 0.527: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:143136
9353.657: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 143136 of LEB 0:56, PEB 58
9353.658: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:151328
9354.319: 0.660: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:396096
9354.324: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 396096 of LEB 0:308, PEB 310
9354.326: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:404288
9354.879: 0.553: ubi_leb_read: UBI DBG (pid 1987): read 1074 bytes from LEB 0:56:142056
9354.884: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1074 bytes from offset 142056 of LEB 0:56, PEB 58
9354.885: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1074 bytes from PEB 58:150248
9356.194: 1.309: ubi_leb_read: UBI DBG (pid 1987): read 1990 bytes from LEB 0:56:131600
9356.201: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1990 bytes from offset 131600 of LEB 0:56, PEB 58
9356.202: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1990 bytes from PEB 58:139792
9359.102: 2.900: ubi_leb_read: UBI DBG (pid 1987): read 1813 bytes from LEB 0:56:133592
9359.108: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1813 bytes from offset 133592 of LEB 0:56, PEB 58
9359.109: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1813 bytes from PEB 58:141784
9368.019: 8.909: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
9371.368: 3.349: ubi_leb_read: UBI DBG (pid 1987): read 1722 bytes from LEB 0:56:135408
9371.376: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1722 bytes from offset 135408 of LEB 0:56, PEB 58
9371.377: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1722 bytes from PEB 58:143600
9494.765: 123.388: ubi_leb_read: UBI DBG (pid 1987): read 1610 bytes from LEB 0:56:137136
9494.771: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1610 bytes from offset 137136 of LEB 0:56, PEB 58
9494.773: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1610 bytes from PEB 58:145328
9497.082: 2.309: ubi_leb_read: UBI DBG (pid 1987): read 1634 bytes from LEB 0:56:138752
9497.087: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1634 bytes from offset 138752 of LEB 0:56, PEB 58
9497.088: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1634 bytes from PEB 58:146944
9499.968: 2.879: ubi_leb_read: UBI DBG (pid 1987): read 1660 bytes from LEB 0:56:140392
9499.974: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1660 bytes from offset 140392 of LEB 0:56, PEB 58
9499.975: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1660 bytes from PEB 58:148584
9521.152: 21.177: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
9597.669: 76.516: ubi_leb_read: UBI DBG (pid 1987): read 1795 bytes from LEB 0:60:37272
9597.676: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1795 bytes from offset 37272 of LEB 0:60, PEB 62
9597.677: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1795 bytes from PEB 62:45464
9841.711: 244.034: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
9934.626: 92.914: do_sync_erase: UBI DBG (pid 480): erase PEB 5
10078.090: 143.464: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
10218.594: 140.504: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
10363.468: 144.874: ubi_leb_read: UBI DBG (pid 1987): read 78 bytes from LEB 0:56:145640
10363.475: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 78 bytes from offset 145640 of LEB 0:56, PEB 58
10363.477: 0.001: ubi_io_read: UBI DBG (pid 1987): read 78 bytes from PEB 58:153832
10510.033: 146.555: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:145480
10510.038: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 145480 of LEB 0:56, PEB 58
10510.039: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:153672
10510.177: 0.137: ubi_leb_read: UBI DBG (pid 1987): read 946 bytes from LEB 0:56:144528
10510.182: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 946 bytes from offset 144528 of LEB 0:56, PEB 58
10510.184: 0.001: ubi_io_read: UBI DBG (pid 1987): read 946 bytes from PEB 58:152720
10510.686: 0.502: ubi_leb_read: UBI DBG (pid 1987): read 1159 bytes from LEB 0:56:143368
10510.693: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1159 bytes from offset 143368 of LEB 0:56, PEB 58
10510.695: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1159 bytes from PEB 58:151560
10521.634: 10.939: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
10605.861: 84.226: torture_peb: UBI: PEB 5 passed torture test, do not mark it a bad
10605.864: 0.003: do_sync_erase: UBI DBG (pid 480): erase PEB 5
10749.935: 144.070: sync_erase: UBI DBG (pid 480): erased PEB 5, new EC 159 max_ec=155
10749.938: 0.002: ubi_io_write_ec_hdr: UBI DBG (pid 480): write EC header to PEB 5
10749.947: 0.009: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:0
10752.003: 2.055: ensure_wear_leveling: UBI DBG (pid 480): schedule scrubbing
10752.019: 0.016: wear_leveling_worker: UBI DBG (pid 480): scrub PEB 253 to PEB 5
10752.021: 0.002: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 253
10752.022: 0.001: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 253:4096
10752.614: 0.592: ubi_eba_copy_leb: UBI DBG (pid 480): copy LEB 0:251, PEB 253 to PEB 5
10752.622: 0.007: ubi_eba_copy_leb: UBI DBG (pid 480): read 516096 bytes of data
10752.623: 0.001: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 253:8192
10826.858: 74.235: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 253
10833.930: 7.071: ubi_io_write_vid_hdr: UBI DBG (pid 480): write VID header to PEB 5
10833.941: 0.011: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
10834.578: 0.637: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:4096
10836.415: 1.836: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 5
10836.417: 0.002: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
10837.020: 0.602: ubi_io_write: UBI DBG (pid 480): write 516096 bytes to PEB 5:8192
10974.796: 137.775: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
10974.825: 0.028: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
11050.473: 75.647: ubi_leb_read: UBI DBG (pid 1987): read 75 bytes from LEB 0:56:131520
11050.481: 0.008: ubi_eba_read_leb: UBI DBG (pid 1987): read 75 bytes from offset 131520 of LEB 0:56, PEB 58
11050.482: 0.001: ubi_io_read: UBI DBG (pid 1987): read 75 bytes from PEB 58:139712
11151.242: 100.759: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 5:8192
11151.798: 0.555: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:131360
11151.804: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 131360 of LEB 0:56, PEB 58
11151.805: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:139552
11151.941: 0.135: ubi_leb_read: UBI DBG (pid 1987): read 776 bytes from LEB 0:56:130584
11151.947: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 776 bytes from offset 130584 of LEB 0:56, PEB 58
11151.948: 0.001: ubi_io_read: UBI DBG (pid 1987): read 776 bytes from PEB 58:138776
11153.533: 1.585: ubi_leb_read: UBI DBG (pid 1987): read 1551 bytes from LEB 0:56:126296
11153.542: 0.008: ubi_eba_read_leb: UBI DBG (pid 1987): read 1551 bytes from offset 126296 of LEB 0:56, PEB 58
11153.543: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1551 bytes from PEB 58:134488
11157.017: 3.473: ubi_leb_read: UBI DBG (pid 1987): read 1560 bytes from LEB 0:56:127848
11157.023: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1560 bytes from offset 127848 of LEB 0:56, PEB 58
11157.024: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1560 bytes from PEB 58:136040
11159.306: 2.281: ubi_leb_read: UBI DBG (pid 1987): read 1172 bytes from LEB 0:56:129408
11159.311: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1172 bytes from offset 129408 of LEB 0:56, PEB 58
11159.312: 0.000: ubi_io_read: UBI DBG (pid 1987): read 1172 bytes from PEB 58:137600
11271.099: 111.787: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 5
11271.102: 0.002: ubi_eba_copy_leb: UBI warning: ubi_io_read_data MOVE_CANCEL_BITFLIPS
11271.107: 0.005: wear_leveling_worker: UBI error: err 5 PEB1=253 PEB2=5
11271.108: 0.000: wear_leveling_worker: UBI error: !!!!!!!!torture=1!!!!!!!!! err 5 PEB1=253 PEB2=5
11271.109: 0.001: wear_leveling_worker: UBI DBG (pid 480): cancel moving PEB 253 (LEB 0:251) to PEB 5 (5)
11271.112: 0.002: wear_leveling_worker: UBI DBG (pid 480): calling schedule_erase, torture=1
11271.113: 0.001: schedule_erase: UBI DBG (pid 480): schedule erasure of PEB 5, EC 159, torture 1
11271.122: 0.008: erase_worker: UBI DBG (pid 480): erase PEB 5 EC 159
11271.123: 0.001: sync_erase: UBI DBG (pid 480): erase PEB 5, old EC 159
11271.133: 0.009: ubi_io_read_ec_hdr: UBI DBG (pid 480): read EC header from PEB 5
11271.134: 0.001: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
11271.763: 0.629: torture_peb: UBI: run torture test for PEB 5
11271.766: 0.002: do_sync_erase: UBI DBG (pid 480): erase PEB 5
11445.647: 173.881: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
11594.507: 148.860: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
11646.559: 52.051: ubi_leb_read: UBI DBG (pid 1987): read 73 bytes from LEB 0:56:126216
11646.566: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 73 bytes from offset 126216 of LEB 0:56, PEB 58
11646.568: 0.001: ubi_io_read: UBI DBG (pid 1987): read 73 bytes from PEB 58:134408
11727.232: 80.664: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:126056
11727.238: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 126056 of LEB 0:56, PEB 58
11727.240: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:134248
11727.380: 0.140: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:395712
11727.385: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 395712 of LEB 0:308, PEB 310
11727.387: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:403904
11727.946: 0.559: ubi_leb_read: UBI DBG (pid 1987): read 796 bytes from LEB 0:56:125256
11727.950: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 796 bytes from offset 125256 of LEB 0:56, PEB 58
11727.952: 0.001: ubi_io_read: UBI DBG (pid 1987): read 796 bytes from PEB 58:133448
11729.040: 1.088: ubi_leb_read: UBI DBG (pid 1987): read 1618 bytes from LEB 0:56:115768
11729.048: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1618 bytes from offset 115768 of LEB 0:56, PEB 58
11729.049: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1618 bytes from PEB 58:123960
11732.029: 2.979: ubi_leb_read: UBI DBG (pid 1987): read 1317 bytes from LEB 0:56:117392
11732.035: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1317 bytes from offset 117392 of LEB 0:56, PEB 58
11732.036: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1317 bytes from PEB 58:125584
11734.324: 2.287: ubi_leb_read: UBI DBG (pid 1987): read 877 bytes from LEB 0:56:118712
11734.327: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 877 bytes from offset 118712 of LEB 0:56, PEB 58
11734.328: 0.000: ubi_io_read: UBI DBG (pid 1987): read 877 bytes from PEB 58:126904
11737.242: 2.913: ubi_leb_read: UBI DBG (pid 1987): read 1518 bytes from LEB 0:56:119592
11737.248: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1518 bytes from offset 119592 of LEB 0:56, PEB 58
11737.250: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1518 bytes from PEB 58:127784
11739.564: 2.313: ubi_leb_read: UBI DBG (pid 1987): read 1312 bytes from LEB 0:56:121112
11739.568: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1312 bytes from offset 121112 of LEB 0:56, PEB 58
11739.569: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1312 bytes from PEB 58:129304
11751.401: 11.831: ubi_leb_read: UBI DBG (pid 1987): read 1544 bytes from LEB 0:56:122424
11751.407: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1544 bytes from offset 122424 of LEB 0:56, PEB 58
11751.409: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1544 bytes from PEB 58:130616
11902.630: 151.220: ubi_leb_read: UBI DBG (pid 1987): read 1286 bytes from LEB 0:56:123968
11902.636: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1286 bytes from offset 123968 of LEB 0:56, PEB 58
11902.638: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1286 bytes from PEB 58:132160
11911.640: 9.002: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
12004.077: 92.436: do_sync_erase: UBI DBG (pid 480): erase PEB 5
12146.869: 142.792: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
12296.723: 149.854: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
12602.226: 305.502: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
12697.392: 95.165: do_sync_erase: UBI DBG (pid 480): erase PEB 5
12841.811: 144.418: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
12968.045: 126.234: ubi_leb_read: UBI DBG (pid 1987): read 71 bytes from LEB 0:56:115696
12968.053: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 71 bytes from offset 115696 of LEB 0:56, PEB 58
12968.055: 0.001: ubi_io_read: UBI DBG (pid 1987): read 71 bytes from PEB 58:123888
12988.009: 19.954: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:115536
12988.015: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 115536 of LEB 0:56, PEB 58
12988.016: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:123728
12988.156: 0.139: ubi_leb_read: UBI DBG (pid 1987): read 1472 bytes from LEB 0:56:114064
12988.161: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1472 bytes from offset 114064 of LEB 0:56, PEB 58
12988.162: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1472 bytes from PEB 58:122256
12989.712: 1.549: ubi_leb_read: UBI DBG (pid 1987): read 1475 bytes from LEB 0:56:112584
12989.719: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1475 bytes from offset 112584 of LEB 0:56, PEB 58
12989.721: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1475 bytes from PEB 58:120776
12992.118: 2.397: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
13271.213: 279.095: ubi_leb_read: UBI DBG (pid 1987): read 72 bytes from LEB 0:56:149176
13271.220: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 72 bytes from offset 149176 of LEB 0:56, PEB 58
13271.222: 0.001: ubi_io_read: UBI DBG (pid 1987): read 72 bytes from PEB 58:157368
13306.548: 35.325: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
13377.774: 71.226: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:396288
13377.779: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 396288 of LEB 0:308, PEB 310
13377.781: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:404480
13378.326: 0.545: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:149016
13378.330: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 149016 of LEB 0:56, PEB 58
13378.331: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:157208
13378.972: 0.640: ubi_leb_read: UBI DBG (pid 1987): read 1649 bytes from LEB 0:56:147360
13378.977: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1649 bytes from offset 147360 of LEB 0:56, PEB 58
13378.979: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1649 bytes from PEB 58:155552
13380.576: 1.597: ubi_leb_read: UBI DBG (pid 1987): read 1636 bytes from LEB 0:56:145720
13380.584: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1636 bytes from offset 145720 of LEB 0:56, PEB 58
13380.585: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1636 bytes from PEB 58:153912
13409.065: 28.480: torture_peb: UBI: PEB 5 passed torture test, do not mark it a bad
13409.069: 0.003: do_sync_erase: UBI DBG (pid 480): erase PEB 5
13560.390: 151.320: sync_erase: UBI DBG (pid 480): erased PEB 5, new EC 163 max_ec=159
13560.392: 0.002: ubi_io_write_ec_hdr: UBI DBG (pid 480): write EC header to PEB 5
13560.402: 0.009: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:0
13563.553: 3.150: ensure_wear_leveling: UBI DBG (pid 480): schedule scrubbing
13563.569: 0.016: wear_leveling_worker: UBI DBG (pid 480): scrub PEB 253 to PEB 5
13563.571: 0.002: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 253
13563.572: 0.001: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 253:4096
13564.169: 0.596: ubi_eba_copy_leb: UBI DBG (pid 480): copy LEB 0:251, PEB 253 to PEB 5
13564.176: 0.007: ubi_eba_copy_leb: UBI DBG (pid 480): read 516096 bytes of data
13564.177: 0.001: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 253:8192
13609.759: 45.582: ubi_leb_read: UBI DBG (pid 1987): read 64 bytes from LEB 0:56:50016
13609.808: 0.048: ubi_eba_read_leb: UBI DBG (pid 1987): read 64 bytes from offset 50016 of LEB 0:56, PEB 58
13609.809: 0.001: ubi_io_read: UBI DBG (pid 1987): read 64 bytes from PEB 58:58208
13636.592: 26.782: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 253
13643.699: 7.107: ubi_io_write_vid_hdr: UBI DBG (pid 480): write VID header to PEB 5
13643.710: 0.010: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
13644.320: 0.610: ubi_io_write: UBI DBG (pid 480): write 4096 bytes to PEB 5:4096
13646.108: 1.787: ubi_io_read_vid_hdr: UBI DBG (pid 480): read VID header from PEB 5
13646.109: 0.001: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
13646.682: 0.572: ubi_io_write: UBI DBG (pid 480): write 516096 bytes to PEB 5:8192
13778.255: 131.572: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
13778.284: 0.029: ubi_io_read: UBI DBG (pid 480): read 4096 bytes from PEB 5:4096
13935.903: 157.618: ubi_io_read: UBI DBG (pid 480): read 516096 bytes from PEB 5:8192
13936.457: 0.554: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:49856
13936.462: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 49856 of LEB 0:56, PEB 58
13936.464: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:58048
13936.510: 0.046: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:393408
13936.513: 0.002: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 393408 of LEB 0:308, PEB 310
13936.513: 0.000: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:401600
13937.117: 0.603: ubi_leb_read: UBI DBG (pid 1987): read 75 bytes from LEB 0:56:47680
13937.122: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 75 bytes from offset 47680 of LEB 0:56, PEB 58
13937.123: 0.001: ubi_io_read: UBI DBG (pid 1987): read 75 bytes from PEB 58:55872
13937.739: 0.615: ubi_leb_read: UBI DBG (pid 1987): read 188 bytes from LEB 0:308:393600
13937.744: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 188 bytes from offset 393600 of LEB 0:308, PEB 310
13937.745: 0.001: ubi_io_read: UBI DBG (pid 1987): read 188 bytes from PEB 310:401792
13938.330: 0.584: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:47520
13938.334: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 47520 of LEB 0:56, PEB 58
13938.335: 0.000: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:55712
13939.047: 0.712: ubi_leb_read: UBI DBG (pid 1987): read 580 bytes from LEB 0:56:46936
13939.053: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 580 bytes from offset 46936 of LEB 0:56, PEB 58
13939.054: 0.001: ubi_io_read: UBI DBG (pid 1987): read 580 bytes from PEB 58:55128
13939.461: 0.406: ubi_leb_read: UBI DBG (pid 1987): read 1882 bytes from LEB 0:56:45048
13939.469: 0.008: ubi_eba_read_leb: UBI DBG (pid 1987): read 1882 bytes from offset 45048 of LEB 0:56, PEB 58
13939.470: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1882 bytes from PEB 58:53240
14062.128: 122.658: ubi_io_read: UBI DBG (pid 480): fixable bit-flip detected at PEB 5
14062.131: 0.002: ubi_eba_copy_leb: UBI warning: ubi_io_read_data MOVE_CANCEL_BITFLIPS
14062.137: 0.005: wear_leveling_worker: UBI error: err 5 PEB1=253 PEB2=5
14062.138: 0.001: wear_leveling_worker: UBI error: !!!!!!!!torture=1!!!!!!!!! err 5 PEB1=253 PEB2=5
14062.139: 0.001: wear_leveling_worker: UBI DBG (pid 480): cancel moving PEB 253 (LEB 0:251) to PEB 5 (5)
14062.142: 0.003: wear_leveling_worker: UBI DBG (pid 480): calling schedule_erase, torture=1
14062.143: 0.001: schedule_erase: UBI DBG (pid 480): schedule erasure of PEB 5, EC 163, torture 1
14062.151: 0.008: erase_worker: UBI DBG (pid 480): erase PEB 5 EC 163
14062.152: 0.001: sync_erase: UBI DBG (pid 480): erase PEB 5, old EC 163
14062.162: 0.009: ubi_io_read_ec_hdr: UBI DBG (pid 480): read EC header from PEB 5
14062.164: 0.001: ubi_io_read: UBI DBG (pid 480): read 64 bytes from PEB 5:0
14062.791: 0.626: torture_peb: UBI: run torture test for PEB 5
14062.793: 0.002: do_sync_erase: UBI DBG (pid 480): erase PEB 5
14103.081: 40.287: ubi_leb_read: UBI DBG (pid 1987): read 80 bytes from LEB 0:56:49776
14103.088: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 80 bytes from offset 49776 of LEB 0:56, PEB 58
14103.089: 0.001: ubi_io_read: UBI DBG (pid 1987): read 80 bytes from PEB 58:57968
14201.959: 98.869: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
14325.597: 123.638: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:49616
14325.603: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 49616 of LEB 0:56, PEB 58
14325.605: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:57808
14325.742: 0.137: ubi_leb_read: UBI DBG (pid 1987): read 863 bytes from LEB 0:56:48752
14325.747: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 863 bytes from offset 48752 of LEB 0:56, PEB 58
14325.748: 0.001: ubi_io_read: UBI DBG (pid 1987): read 863 bytes from PEB 58:56944
14350.624: 24.876: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
14457.255: 106.630: ubi_leb_read: UBI DBG (pid 1987): read 81 bytes from LEB 0:56:44960
14457.362: 0.106: ubi_eba_read_leb: UBI DBG (pid 1987): read 81 bytes from offset 44960 of LEB 0:56, PEB 58
14457.363: 0.001: ubi_io_read: UBI DBG (pid 1987): read 81 bytes from PEB 58:53152
14640.194: 182.830: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:44800
14640.200: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 44800 of LEB 0:56, PEB 58
14640.201: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:52992
14640.339: 0.137: ubi_leb_read: UBI DBG (pid 1987): read 915 bytes from LEB 0:56:43880
14640.344: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 915 bytes from offset 43880 of LEB 0:56, PEB 58
14640.345: 0.001: ubi_io_read: UBI DBG (pid 1987): read 915 bytes from PEB 58:52072
14641.035: 0.689: ubi_leb_read: UBI DBG (pid 1987): read 1812 bytes from LEB 0:56:36272
14641.042: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1812 bytes from offset 36272 of LEB 0:56, PEB 58
14641.044: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1812 bytes from PEB 58:44464
14644.519: 3.475: ubi_leb_read: UBI DBG (pid 1987): read 1443 bytes from LEB 0:56:38088
14644.525: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 1443 bytes from offset 38088 of LEB 0:56, PEB 58
14644.527: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1443 bytes from PEB 58:46280
14646.800: 2.273: ubi_leb_read: UBI DBG (pid 1987): read 1677 bytes from LEB 0:56:39536
14646.804: 0.003: ubi_eba_read_leb: UBI DBG (pid 1987): read 1677 bytes from offset 39536 of LEB 0:56, PEB 58
14646.805: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1677 bytes from PEB 58:47728
14649.639: 2.834: ubi_leb_read: UBI DBG (pid 1987): read 1243 bytes from LEB 0:56:41216
14649.644: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1243 bytes from offset 41216 of LEB 0:56, PEB 58
14649.646: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1243 bytes from PEB 58:49408
14650.953: 1.306: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
14652.070: 1.117: ubi_leb_read: UBI DBG (pid 1987): read 1413 bytes from LEB 0:56:42464
14652.076: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1413 bytes from offset 42464 of LEB 0:56, PEB 58
14652.077: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1413 bytes from PEB 58:50656
14740.350: 88.272: do_sync_erase: UBI DBG (pid 480): erase PEB 5
14891.912: 151.562: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
15031.432: 139.519: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
15215.498: 184.065: ubi_leb_read: UBI DBG (pid 1987): read 78 bytes from LEB 0:56:48672
15215.506: 0.008: ubi_eba_read_leb: UBI DBG (pid 1987): read 78 bytes from offset 48672 of LEB 0:56, PEB 58
15215.507: 0.001: ubi_io_read: UBI DBG (pid 1987): read 78 bytes from PEB 58:56864
15353.213: 137.706: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:48512
15353.219: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 48512 of LEB 0:56, PEB 58
15353.221: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:56704
15353.355: 0.134: ubi_leb_read: UBI DBG (pid 1987): read 751 bytes from LEB 0:56:47760
15353.360: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 751 bytes from offset 47760 of LEB 0:56, PEB 58
15353.361: 0.001: ubi_io_read: UBI DBG (pid 1987): read 751 bytes from PEB 58:55952
15381.757: 28.396: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
15413.865: 32.108: ubi_leb_read: UBI DBG (pid 1987): read 64 bytes from LEB 0:56:156936
15413.873: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 64 bytes from offset 156936 of LEB 0:56, PEB 58
15413.874: 0.001: ubi_io_read: UBI DBG (pid 1987): read 64 bytes from PEB 58:165128
15462.431: 48.557: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:156776
15462.438: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 156776 of LEB 0:56, PEB 58
15462.440: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:164968
15462.486: 0.046: ubi_leb_read: UBI DBG (pid 1987): read 76 bytes from LEB 0:56:156696
15462.489: 0.002: ubi_eba_read_leb: UBI DBG (pid 1987): read 76 bytes from offset 156696 of LEB 0:56, PEB 58
15462.489: 0.000: ubi_io_read: UBI DBG (pid 1987): read 76 bytes from PEB 58:164888
15462.512: 0.022: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:156536
15462.515: 0.002: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 156536 of LEB 0:56, PEB 58
15462.516: 0.000: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:164728
15462.633: 0.117: ubi_leb_read: UBI DBG (pid 1987): read 1183 bytes from LEB 0:56:155352
15462.638: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 1183 bytes from offset 155352 of LEB 0:56, PEB 58
15462.639: 0.000: ubi_io_read: UBI DBG (pid 1987): read 1183 bytes from PEB 58:163544
15464.152: 1.513: ubi_leb_read: UBI DBG (pid 1987): read 1774 bytes from LEB 0:56:151936
15464.160: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1774 bytes from offset 151936 of LEB 0:56, PEB 58
15464.162: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1774 bytes from PEB 58:160128
15467.056: 2.894: ubi_leb_read: UBI DBG (pid 1987): read 1639 bytes from LEB 0:56:153712
15467.062: 0.005: ubi_eba_read_leb: UBI DBG (pid 1987): read 1639 bytes from offset 153712 of LEB 0:56, PEB 58
15467.063: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1639 bytes from PEB 58:161904
15477.373: 10.309: do_sync_erase: UBI DBG (pid 480): erase PEB 5
15481.538: 4.165: ubi_leb_read: UBI DBG (pid 2169): read 59 bytes from LEB 0:40:447584
15481.546: 0.007: ubi_eba_read_leb: UBI DBG (pid 2169): read 59 bytes from offset 447584 of LEB 0:40, PEB 42
15481.548: 0.001: ubi_io_read: UBI DBG (pid 2169): read 59 bytes from PEB 42:455776
15482.239: 0.691: ubi_leb_read: UBI DBG (pid 2169): read 188 bytes from LEB 0:308:298944
15482.245: 0.005: ubi_eba_read_leb: UBI DBG (pid 2169): read 188 bytes from offset 298944 of LEB 0:308, PEB 310
15482.246: 0.001: ubi_io_read: UBI DBG (pid 2169): read 188 bytes from PEB 310:307136
15483.366: 1.119: ubi_leb_read: UBI DBG (pid 2169): read 167 bytes from LEB 0:40:447416
15483.372: 0.005: ubi_eba_read_leb: UBI DBG (pid 2169): read 167 bytes from offset 447416 of LEB 0:40, PEB 42
15483.373: 0.001: ubi_io_read: UBI DBG (pid 2169): read 167 bytes from PEB 42:455608
15491.483: 8.110: ubi_leb_read: UBI DBG (pid 2216): read 2138 bytes from LEB 0:30:451216
15491.490: 0.007: ubi_eba_read_leb: UBI DBG (pid 2216): read 2138 bytes from offset 451216 of LEB 0:30, PEB 32
15491.492: 0.001: ubi_io_read: UBI DBG (pid 2216): read 2138 bytes from PEB 32:459408
15494.609: 3.117: ubi_leb_read: UBI DBG (pid 2216): read 65 bytes from LEB 0:15:128144
15494.617: 0.007: ubi_eba_read_leb: UBI DBG (pid 2216): read 65 bytes from offset 128144 of LEB 0:15, PEB 17
15494.619: 0.001: ubi_io_read: UBI DBG (pid 2216): read 65 bytes from PEB 17:136336
15495.284: 0.665: ubi_leb_read: UBI DBG (pid 2216): read 188 bytes from LEB 0:308:93888
15495.290: 0.005: ubi_eba_read_leb: UBI DBG (pid 2216): read 188 bytes from offset 93888 of LEB 0:308, PEB 310
15495.291: 0.001: ubi_io_read: UBI DBG (pid 2216): read 188 bytes from PEB 310:102080
15495.913: 0.621: ubi_leb_read: UBI DBG (pid 2216): read 160 bytes from LEB 0:15:127984
15495.918: 0.005: ubi_eba_read_leb: UBI DBG (pid 2216): read 160 bytes from offset 127984 of LEB 0:15, PEB 17
15495.919: 0.001: ubi_io_read: UBI DBG (pid 2216): read 160 bytes from PEB 17:136176
15496.570: 0.650: ubi_leb_read: UBI DBG (pid 2216): read 62 bytes from LEB 0:15:127920
15496.576: 0.005: ubi_eba_read_leb: UBI DBG (pid 2216): read 62 bytes from offset 127920 of LEB 0:15, PEB 17
15496.577: 0.001: ubi_io_read: UBI DBG (pid 2216): read 62 bytes from PEB 17:136112
15496.642: 0.064: ubi_leb_read: UBI DBG (pid 2216): read 160 bytes from LEB 0:15:127760
15496.645: 0.003: ubi_eba_read_leb: UBI DBG (pid 2216): read 160 bytes from offset 127760 of LEB 0:15, PEB 17
15496.647: 0.001: ubi_io_read: UBI DBG (pid 2216): read 160 bytes from PEB 17:135952
15496.828: 0.181: ubi_leb_read: UBI DBG (pid 2216): read 1214 bytes from LEB 0:15:126544
15496.834: 0.006: ubi_eba_read_leb: UBI DBG (pid 2216): read 1214 bytes from offset 126544 of LEB 0:15, PEB 17
15496.835: 0.001: ubi_io_read: UBI DBG (pid 2216): read 1214 bytes from PEB 17:134736
15650.499: 153.663: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
15801.023: 150.524: ubi_io_write: UBI DBG (pid 480): write 524288 bytes to PEB 5:0
15885.394: 84.371: ubi_leb_read: UBI DBG (pid 1987): read 77 bytes from LEB 0:56:151856
15885.401: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 77 bytes from offset 151856 of LEB 0:56, PEB 58
15885.403: 0.001: ubi_io_read: UBI DBG (pid 1987): read 77 bytes from PEB 58:160048
15943.195: 57.792: ubi_leb_read: UBI DBG (pid 1987): read 160 bytes from LEB 0:56:151696
15943.201: 0.006: ubi_eba_read_leb: UBI DBG (pid 1987): read 160 bytes from offset 151696 of LEB 0:56, PEB 58
15943.203: 0.001: ubi_io_read: UBI DBG (pid 1987): read 160 bytes from PEB 58:159888
15943.340: 0.137: ubi_leb_read: UBI DBG (pid 1987): read 456 bytes from LEB 0:56:151240
15943.345: 0.004: ubi_eba_read_leb: UBI DBG (pid 1987): read 456 bytes from offset 151240 of LEB 0:56, PEB 58
15943.346: 0.001: ubi_io_read: UBI DBG (pid 1987): read 456 bytes from PEB 58:159432
15944.740: 1.393: ubi_leb_read: UBI DBG (pid 1987): read 1763 bytes from LEB 0:56:149472
15944.747: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 1763 bytes from offset 149472 of LEB 0:56, PEB 58
15944.749: 0.001: ubi_io_read: UBI DBG (pid 1987): read 1763 bytes from PEB 58:157664
16134.340: 189.591: ubi_leb_read: UBI DBG (pid 1987): read 66 bytes from LEB 0:56:178368
16134.347: 0.007: ubi_eba_read_leb: UBI DBG (pid 1987): read 66 bytes from offset 178368 of LEB 0:56, PEB 58
16134.349: 0.001: ubi_io_read: UBI DBG (pid 1987): read 66 bytes from PEB 58:186560
16141.324: 6.975: ubi_io_read: UBI DBG (pid 480): read 524288 bytes from PEB 5:0
16221.047: 79.722: torture_peb: UBI: PEB 5 passed torture test, do not mark it a bad
16221.050: 0.003: do_sync_erase: UBI DBG (pid 480): erase PEB 5
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: UBI wear leveling / torture testing algorithms having trouble with MLC flash
2010-04-13 1:00 UBI wear leveling / torture testing algorithms having trouble with MLC flash Darwin Rambo
@ 2010-04-14 17:30 ` Artem Bityutskiy
2010-04-15 18:01 ` Darwin Rambo
0 siblings, 1 reply; 6+ messages in thread
From: Artem Bityutskiy @ 2010-04-14 17:30 UTC (permalink / raw)
To: Darwin Rambo; +Cc: linux-mtd
Hi Darwin,
On Mon, 2010-04-12 at 18:00 -0700, Darwin Rambo wrote:
> Setup:
> I am using a Samsung 2GB MLC flash with 4K page size and 8-bit
> hardware ECC support. I am using a 2.6.31 kernel, but if I read the
> code right, the problem I see is in the latest 2.6.34-rc2 code as well.
as usually, I recommend using the ubifs-2.6.31 tree, which is vanilla
2.6.31 plus all UBI/UBIFS patches back-ported. Take a look here:
http://git.infradead.org/users/dedekind/ubifs-v2.6.31.git/shortlog
> Summary:
> I traced a torture test caught in a repeating loop, wearing out a
> flash block. It appears that the torture test with it's simple
> 0xA5/0x5A/0x00 pattern is passing, whereas actual application data
> is consistently showing a bit flip on the same block. MLC flashes I
> have used regularly show corrected errors over several blocks in time,
> and also show corrected errors consistently due to program-disturb
> effects, but these program disturb effects appear to be data dependent,
> based on device geometry (e.g. adjacent multi-bit cell effects). The
> scenario above can cause an repeating scrubbing / torture test loop
> to occur. It is initiated by the nand driver reporting a bit correction
> in a block which starts the scrubbing/torturing loop.
Bear in mind we developed and tested all the UBI/UBIFS stuff only on
SLC. In fact, I never used MLC, and do not know this well enough. Thus,
it is up to you to amend UBI to support MLC better, because you have the
HW.
>
> Details:
>
> (Please correct me if I have got ubi parts of this explanation wrong - Thanks).
>
> A single bit correction is a relatively normal event with MLC flash and
> this triggers a scrub operation in UBI in which the block is considered
> marginal, and the data is moved from a marginal block to a good block.
Sounds right.
> A
> good block is one that is considered to have passed the UBI torture test,
> which simply writes 0xA5, 0x5A, and 0x00 to a block with 3 erases, and
> then does a 4th erase for the user data that will eventually be copied to
> this block.
Well, it did not necessarily pass the torture test. It might have been
just normally erased in the past.
> But this torture test is too simplistic since it doesn't
> understand the geometry of MLC flashes and in particular, write-disturb
> and read-disturb effects from neighboring cells and columns.
Right, it does not understand that. It is way less complicated than
that.
> What's maybe
> needed is a torture test that understands the geometry and the bit correction
> level 1,4,8,12 etc and is able to toggle geometrically neighboring bits rather
> than view it as a simple memory test, but this may be difficult.
May be, but then I think this function should be moved down from UBI to
the MTD level. Then the driver-level information like geometry may be
used.
> Perhaps
> torturing MLC blocks with only 3000 cycles is inappropriate anyways, why not
> just trust the error correction and only mark uncorrectable blocks as bad?.
May be. But on the other hand, ignoring soft-errors completely is not
very good, as they may develop into hard-errors. Probably, as usually,
we need a balance.
> Since the torture test passes with no bit errors I believe that it didn't
> find certain error correction patterns that appear with actual application
> data. As a result, when the torture test passes, the block shows no correctable
> errors, and is returned to the free pool.
Sounds OK, as expected.
> The original block X that had a
> correctable error is scrubbed and it's data is copied to the free block with
> the highest erase count.
Right.
Although I have one note, which is not very important here, but it is
nice to know this.
UBI does select an eraseblock with the highes EC. However, this happens
only when the difference between the max. and min. erasecounters is less
than WL_FREE_MAX_DIFF. Otherwise, UBI selects an eraseblock with
eraseconter around min. EC + WL_FREE_MAX_DIFF.
In other words, if there is one or few eraseblocks with very high EC,
then they will be out of the WL loop till other eraseblocks catch up.
BTW, WL_FREE_MAX_DIFF is defined as
#define WL_FREE_MAX_DIFF (2*UBI_WL_THRESHOLD)
UBI_WL_THRESHOLD is configurable, and in case of MLC it should not be
the default 4096 bytes value. Ideally, we should compute this value
automatically using some parameters from the MTD level. However, current
MTD does not provide anything like that.
> The highest erase count block is chosen and will remain
> partially written and available for new scrubs, and data will be scrubbed to it
> from other marginal blocks while the other blocks catch up in erase count. However,
> if block Y previously had a bit error and was torture tested and passed, it's
> erase count will go up by 4. As a result, block Y has a higher probability of
> being the target of the copy from X to Y. But when the copy of actual application
> data is done, block Y now shows a data-dependent correctable bit error again and
> the scrub operation fails, and block Y is again sent out for torture testing, and
> the process repeats itself until block Y either shows no error or the block wears
> out, is marked bad, and another free block is chosen.
Almost, but not exactly. UBI will stop picking Y when it's erasecounter
becomes greater than min. EC + WL_FREE_MAX_DIFF.
> So not only do blocks wear
> out, but many blocks can be taken out of service as well by being marked bad.
Yeah, this sounds bad.
> If
> the available pool of free blocks for bad block management (typically 1% of the
> total blocks in a partition) go bad, then the file system is remounted read-only
> and the product becomes unusable for writable data in that partition.
Right, bad.
> If I have a
> 3000 erase MLC part, then only 750 quick loops of the scrub/torture (4 erase) cycle
> will wear the block out.
This suggests you did not change the default UBI_WL_THRESHOLD = 4096.
You should set it to something smaller. This will make the problem less
severe, but will not fix it, of course.
> At that point the next free block will be used which may
> or may not show a corrected error.
>
> Possible Solutions:
> I think that with MLC flashes, we perhaps shouldn't be so aggressive to scrub/torture
> given the more frequent error rate than we see with SLC parts.
Absolutely.
> Also hiding the actual
> corrections in the nand driver to hide the problem in UBI isn't a good long term
> solution easier.
Right.
> The UBI algorithm doesn't appear to understand different levels
> of correction possible. For example, on a 12-bit part, an single corrected error
> is much more common and normal than say, 11 bit corrections on a marginal block,
> but UBI treats 1 or 11 bits the same algorithmically. The ecc correction capability
> maybe should be known by UBI so it can make better decisions about when to run
> scrub/torture algorithms? Or perhaps we don't do torturing at all with MLC flash and
> rely on the multi-bit correction instead to help us. The correction level and the
> flash type could be useful information for UBI to use in deciding algorithms like these.
>
> The short term solution might be for the nand driver to hide error corrections from
> the UBI wear leveling software by reporting all good corrections as 0 errors. Then
> UBI shouldn't start scrubbing and torturing on a single bit error in a block. Two
> blocks with a single error that are part of the scrubbing/torturing duo start the
> loop of flash erasing/wear out.
How about improving UBI a little and just teach it avoid doing any
scrubbing for eraseblocks with high enough erase-counter? Say, if UBI
notices a bit-flip in eraseblock A, then:
if (EC of eraseblock A < min. EC + WL_FREE_MAX_DIFF / 2)
do_scrubbing();
else
/* Do not do scrubbing for relatively "fresh" eraseblocks */
or something like that. This could be good enough to start with.
Also, torturing can be disabled or improved for MLC. This depends on how
much efforts you want to invest into UBI over MLC.
> I also attach a log file I collected demonstrating the problem, with some annotations
> inline. The log are basically the existing printk's plus a few of my own converted to
> log quickly to RAM to avoid cluttering the console and destabilizing real time.
>
> I hope this helps us understand and support MLC flash a bit better. I am curious to
> know if anyone else has seen problems like these and how they dealt with them.
Not me at least :-)
--
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
^ permalink raw reply [flat|nested] 6+ messages in thread
* RE: UBI wear leveling / torture testing algorithms having trouble with MLC flash
2010-04-14 17:30 ` Artem Bityutskiy
@ 2010-04-15 18:01 ` Darwin Rambo
2010-04-21 13:13 ` Artem Bityutskiy
0 siblings, 1 reply; 6+ messages in thread
From: Darwin Rambo @ 2010-04-15 18:01 UTC (permalink / raw)
To: dedekind1; +Cc: linux-mtd
Hi Artem,
> > What's maybe
> > needed is a torture test that understands the geometry and the bit correction
> > level 1,4,8,12 etc and is able to toggle geometrically neighboring bits rather
> > than view it as a simple memory test, but this may be difficult.
>
> May be, but then I think this function should be moved down from UBI to
> the MTD level. Then the driver-level information like geometry may be
> used.
Do you mean having a low level MTD function that does it's own type of torture
test on a block and returns test status to UBI?
> > Perhaps
> > torturing MLC blocks with only 3000 cycles is inappropriate anyways, why not
> > just trust the error correction and only mark uncorrectable blocks as bad?.
>
> May be. But on the other hand, ignoring soft-errors completely is not
> very good, as they may develop into hard-errors. Probably, as usually,
> we need a balance.
By MLC hard-errors, do you mean uncorrectable sectors, or do you mean permanently
stuck bits that are consistently corrected by ECC every read?
The permanently stuck bits I have often seen with MLC are typically stuck at 0 due to
neighbouring program disturb effects from other cells. These same stuck bits are the
reason for the torture test looping. If you look at the logs of the corrections,
it typically involves resetting these back to 1. Perhaps the nand driver can recognize
a stuck bit somehow and not report it as a correction but I think that's not right.
(Side-note: I also sometimes see a bit set to 0 after an erase operation with MLC.
E.g. you might see 0xfffffdff for example in the erased page.
Since the ECC is also erased, and FF data does not imply FF ECC in our case, it is
necessary to detect the all FF erased ECC and in software, fake these stuck low data
bits as high as if the ECC were present...but I digress).
In the case of MLC, I think we might ignore soft errors and let the ECC do it's job.
If the errors are program disturb effects as above, then they will be persistent and
will always be corrected within the ECC capability. If we get too many stuck bits then
the sector/page/block becomes bad and we know that without scrubbing or torturing
anyways. If they are random errors due to noise margins and read-disturb effects, then
I believe that this is also 'normal' behavior, and shouldn't trigger error recovery
operations like scrubbing/torturing, especially a single bit correction.
Also the programming during torturing might create more even more write disturb errors
and make the problem even worse. But we have to live with that anyways during regular
programming for application data so that's probably a moot point.
> > If I have a
> > 3000 erase MLC part, then only 750 quick loops of the scrub/torture (4 erase) cycle
> > will wear the block out.
>
> This suggests you did not change the default UBI_WL_THRESHOLD = 4096.
> You should set it to something smaller. This will make the problem less
> severe, but will not fix it, of course.
So that explains why the loop eventually did stop. I originally had the threshold at
4096 but later switched to 256. In both cases we saw torture testing loops.
> How about improving UBI a little and just teach it avoid doing any
> scrubbing for eraseblocks with high enough erase-counter? Say, if UBI
> notices a bit-flip in eraseblock A, then:
>
> if (EC of eraseblock A < min. EC + WL_FREE_MAX_DIFF / 2)
> do_scrubbing();
> else
> /* Do not do scrubbing for relatively "fresh" eraseblocks */
>
> or something like that. This could be good enough to start with.
>
> Also, torturing can be disabled or improved for MLC. This depends on how
> much efforts you want to invest into UBI over MLC.
Initially I think we might consider something like a config flag
(e.g. CONFIG_MTD_UBI_SCRUB_AND_TORTURE) to just shut off the sensitivity
to corrected errors, which are due to noise or the persistent stuck
bits I described above. Rather than decide to do scrubbing
based on the EC count as you suggest above, another way to look at it might
be to simply not start the scrubbing operation based on normal ECC corrections.
That's effectively what I'm doing today by hiding/reporting all ecc corrections
as 0 corrections.
Later, we might look into starting the scrubbing when the corrections
reaches a threshold based on the nand ECC correction limits. E.g. Set
CONFIG_MTD_UBI_SCRUB_AND_TORTURE=y and also add "CONFIG_MTD_UBI_ECC_CAPABILITY=12",
and then when we get close to 12 corrections (10,11,12?), we scrub, and perhaps
torture this _much_ more marginal block, maybe take it out of service, etc. This
could be combined with your erase-counter suggestion above.
The MLC parts could increase it to 4,8,12, etc. If it was not set, then the legacy
behavior of UBI could still be used.
Future work might involve more elegant MTD based torture tests that understand
flash geometry but I think that's a much tougher nut to crack. Especially since
there's no industry standard for MLC page/bit pairing algorithms by manufacturers.
These suggestions reduce the block erase frequency dramatically, and with
3000 measly MLC erases, I don't see a problem restricting scrub/torture operations
as a trade off for part lifetime.
Thanks.
Best regards,
Darwin
Disclaimer - Any views or opinions presented in this e-mail are solely those of the author
and do not necessarily represent those of the company.
^ permalink raw reply [flat|nested] 6+ messages in thread
* RE: UBI wear leveling / torture testing algorithms having trouble with MLC flash
2010-04-15 18:01 ` Darwin Rambo
@ 2010-04-21 13:13 ` Artem Bityutskiy
2010-04-21 16:51 ` Darwin Rambo
0 siblings, 1 reply; 6+ messages in thread
From: Artem Bityutskiy @ 2010-04-21 13:13 UTC (permalink / raw)
To: Darwin Rambo; +Cc: linux-mtd
On Thu, 2010-04-15 at 11:01 -0700, Darwin Rambo wrote:
> Hi Artem,
>
> > > What's maybe
> > > needed is a torture test that understands the geometry and the bit correction
> > > level 1,4,8,12 etc and is able to toggle geometrically neighboring bits rather
> > > than view it as a simple memory test, but this may be difficult.
> >
> > May be, but then I think this function should be moved down from UBI to
> > the MTD level. Then the driver-level information like geometry may be
> > used.
>
> Do you mean having a low level MTD function that does it's own type of torture
> test on a block and returns test status to UBI?
Something like that.
> > > Perhaps
> > > torturing MLC blocks with only 3000 cycles is inappropriate anyways, why not
> > > just trust the error correction and only mark uncorrectable blocks as bad?.
> >
> > May be. But on the other hand, ignoring soft-errors completely is not
> > very good, as they may develop into hard-errors. Probably, as usually,
> > we need a balance.
>
> By MLC hard-errors, do you mean uncorrectable sectors, or do you mean permanently
> stuck bits that are consistently corrected by ECC every read?
I actually meant uncorrectable ECC errors.
> The permanently stuck bits I have often seen with MLC are typically stuck at 0 due to
> neighbouring program disturb effects from other cells. These same stuck bits are the
> reason for the torture test looping. If you look at the logs of the corrections,
> it typically involves resetting these back to 1. Perhaps the nand driver can recognize
> a stuck bit somehow and not report it as a correction but I think that's not right.
Hm, for me this sounds as an idea which may work. What if we just change
the semantics of the -EBADMSG error code of the MTD subsystem. Change it
from "bit flips occured and were corrected" to "_dangerous_ bit flips
occurred, were corrected, but it is risky, so the data should be
refreshed".
Then for SLC, every bit-flip can cause -EBADMSG, just like now, and for
MLC - the driver will be able to decide.
The idea is that MLCs are so different that only the driver can know
whether a bit-flip is dangerous or not.
> Also the programming during torturing might create more even more write disturb errors
> and make the problem even worse. But we have to live with that anyways during regular
> programming for application data so that's probably a moot point.
This is another problem. We can disabling torturing for MLC, or change
it.
> > > If I have a
> > > 3000 erase MLC part, then only 750 quick loops of the scrub/torture (4 erase) cycle
> > > will wear the block out.
> >
> > This suggests you did not change the default UBI_WL_THRESHOLD = 4096.
> > You should set it to something smaller. This will make the problem less
> > severe, but will not fix it, of course.
>
> So that explains why the loop eventually did stop. I originally had the threshold at
> 4096 but later switched to 256. In both cases we saw torture testing loops.
>
> > How about improving UBI a little and just teach it avoid doing any
> > scrubbing for eraseblocks with high enough erase-counter? Say, if UBI
> > notices a bit-flip in eraseblock A, then:
> >
> > if (EC of eraseblock A < min. EC + WL_FREE_MAX_DIFF / 2)
> > do_scrubbing();
> > else
> > /* Do not do scrubbing for relatively "fresh" eraseblocks */
> >
> > or something like that. This could be good enough to start with.
> >
> > Also, torturing can be disabled or improved for MLC. This depends on how
> > much efforts you want to invest into UBI over MLC.
>
> Initially I think we might consider something like a config flag
> (e.g. CONFIG_MTD_UBI_SCRUB_AND_TORTURE) to just shut off the sensitivity
> to corrected errors, which are due to noise or the persistent stuck
> bits I described above. Rather than decide to do scrubbing
> based on the EC count as you suggest above, another way to look at it might
> be to simply not start the scrubbing operation based on normal ECC corrections.
> That's effectively what I'm doing today by hiding/reporting all ecc corrections
> as 0 corrections.
>
> Later, we might look into starting the scrubbing when the corrections
> reaches a threshold based on the nand ECC correction limits. E.g. Set
> CONFIG_MTD_UBI_SCRUB_AND_TORTURE=y and also add "CONFIG_MTD_UBI_ECC_CAPABILITY=12",
> and then when we get close to 12 corrections (10,11,12?), we scrub, and perhaps
> torture this _much_ more marginal block, maybe take it out of service, etc. This
> could be combined with your erase-counter suggestion above.
> The MLC parts could increase it to 4,8,12, etc. If it was not set, then the legacy
> behavior of UBI could still be used.
>
> Future work might involve more elegant MTD based torture tests that understand
> flash geometry but I think that's a much tougher nut to crack. Especially since
> there's no industry standard for MLC page/bit pairing algorithms by manufacturers.
>
> These suggestions reduce the block erase frequency dramatically, and with
> 3000 measly MLC erases, I don't see a problem restricting scrub/torture operations
> as a trade off for part lifetime.
In general, I think all the MLC-specific things like "ECC 12" should be
hidden in the MTD level. Just because this information is too
MLC-specific for UBI to know about it.
UBI should distinguish MLC and behave a bit different in that case, but
this should be about "torture MLC eraseblocks this special way", and the
like. IOW, on higher level than knowing about ECC levels.
--
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
^ permalink raw reply [flat|nested] 6+ messages in thread
* RE: UBI wear leveling / torture testing algorithms having trouble with MLC flash
2010-04-21 13:13 ` Artem Bityutskiy
@ 2010-04-21 16:51 ` Darwin Rambo
2010-04-21 18:13 ` Artem Bityutskiy
0 siblings, 1 reply; 6+ messages in thread
From: Darwin Rambo @ 2010-04-21 16:51 UTC (permalink / raw)
To: dedekind1; +Cc: linux-mtd
Hi Artem,
> > The permanently stuck bits I have often seen with MLC are typically stuck at 0 due to
> > neighbouring program disturb effects from other cells. These same stuck bits are the
> > reason for the torture test looping. If you look at the logs of the corrections,
> > it typically involves resetting these back to 1. Perhaps the nand driver can recognize
> > a stuck bit somehow and not report it as a correction but I think that's not right.
>
> Hm, for me this sounds as an idea which may work. What if we just change
> the semantics of the -EBADMSG error code of the MTD subsystem. Change it
> from "bit flips occured and were corrected" to "_dangerous_ bit flips
> occurred, were corrected, but it is risky, so the data should be
> refreshed".
>
> Then for SLC, every bit-flip can cause -EBADMSG, just like now, and for
> MLC - the driver will be able to decide.
>
> The idea is that MLCs are so different that only the driver can know
> whether a bit-flip is dangerous or not.
When bit flips are corrected we return -EUCLEAN and when uncorrectable errors occur we
return -EBADMSG. So you probably mean -EUCLEAN above? I think -EBADMSG should continue
to mean "uncorrectable".
But a permanently stuck bit is corrected each read and isn't really dangerous.
It's most likely just a write-disturb effect. I have seen that blocks that get heavily
erased & programmed start showing lots of correctable ECC errors. So I don't think we
should consider stuck bits or random bit flips as dangerous. But we should consider
high numbers of errors of both types together as a dangerous condition, likely indicating
block wearout.
>
> > Also the programming during torturing might create more even more write disturb errors
> > and make the problem even worse. But we have to live with that anyways during regular
> > programming for application data so that's probably a moot point.
>
> This is another problem. We can disabling torturing for MLC, or change
> it.
Torturing MLC flash just wears the MLC flash out more and creates more bit flips. But
scrubbing and torturing are different things, so we are scrubbing so that we increase
the probability of precious user data not being lost, disabling scrubbing is not a good
option, but disabling/changing torturing may be fine. Perhaps we should have MTD/MLC return
-EUCLEAN when say, 80-100% of the max possible corrections are done and then scrub the
data to a good block, and then either torture the marginal block or mark it bad and remove
the block from service?
Another idea might be to remember with a torture histogram how many times a each block
was sent out for torturing, and after N (3?) tortures, something is definitely bad, and
then the block could be marked bad permanently.
For MLC, you might consider just erasing the block and not torturing at all. Eventually the
marginal block will hit the N threshold above and be taken out of service anyways. Then you
don't need a mtd specific torture test at all...
>
>
>
> In general, I think all the MLC-specific things like "ECC 12" should be
> hidden in the MTD level. Just because this information is too
> MLC-specific for UBI to know about it.
>
> UBI should distinguish MLC and behave a bit different in that case, but
> this should be about "torture MLC eraseblocks this special way", and the
> like. IOW, on higher level than knowing about ECC levels.
I agree the mtd driver should hide this information if possible, and we suggested that
above for error reporting. But for torturing, that might mean we need to change the mtd
interface to be able to request a flash specific torture test and return a status.
Changing mtd seems to be harder than the suggestions above, and since torturing may make
things worse, I think we should try to keep our solution in the ubi layer for now.
Thanks.
Best regards,
Darwin
Disclaimer - Any views or opinions presented in this e-mail are solely those of the author
and do not necessarily represent those of the company.
^ permalink raw reply [flat|nested] 6+ messages in thread
* RE: UBI wear leveling / torture testing algorithms having trouble with MLC flash
2010-04-21 16:51 ` Darwin Rambo
@ 2010-04-21 18:13 ` Artem Bityutskiy
0 siblings, 0 replies; 6+ messages in thread
From: Artem Bityutskiy @ 2010-04-21 18:13 UTC (permalink / raw)
To: Darwin Rambo; +Cc: linux-mtd
Hi,
On Wed, 2010-04-21 at 09:51 -0700, Darwin Rambo wrote:
> Hi Artem,
>
> > > The permanently stuck bits I have often seen with MLC are typically stuck at 0 due to
> > > neighbouring program disturb effects from other cells. These same stuck bits are the
> > > reason for the torture test looping. If you look at the logs of the corrections,
> > > it typically involves resetting these back to 1. Perhaps the nand driver can recognize
> > > a stuck bit somehow and not report it as a correction but I think that's not right.
> >
> > Hm, for me this sounds as an idea which may work. What if we just change
> > the semantics of the -EBADMSG error code of the MTD subsystem. Change it
> > from "bit flips occured and were corrected" to "_dangerous_ bit flips
> > occurred, were corrected, but it is risky, so the data should be
> > refreshed".
> >
> > Then for SLC, every bit-flip can cause -EBADMSG, just like now, and for
> > MLC - the driver will be able to decide.
> >
> > The idea is that MLCs are so different that only the driver can know
> > whether a bit-flip is dangerous or not.
>
> When bit flips are corrected we return -EUCLEAN and when uncorrectable errors occur we
> return -EBADMSG. So you probably mean -EUCLEAN above? I think -EBADMSG should continue
> to mean "uncorrectable".
Yes, sorry, you are right. Sorry for confusion.
> But a permanently stuck bit is corrected each read and isn't really dangerous.
Then just do not return -EUCLEAN, that is my idea.
> It's most likely just a write-disturb effect. I have seen that blocks that get heavily
> erased & programmed start showing lots of correctable ECC errors. So I don't think we
> should consider stuck bits or random bit flips as dangerous.
Right, and you again do not return -EUCLEAN. The idea is that the driver
has the intimate HW knowlege and can decide when -EUCLEAN is returned.
> But we should consider
> high numbers of errors of both types together as a dangerous condition, likely indicating
> block wearout.
Ok.
> > > Also the programming during torturing might create more even more write disturb errors
> > > and make the problem even worse. But we have to live with that anyways during regular
> > > programming for application data so that's probably a moot point.
> >
> > This is another problem. We can disabling torturing for MLC, or change
> > it.
>
> Torturing MLC flash just wears the MLC flash out more and creates more bit flips. But
> scrubbing and torturing are different things, so we are scrubbing so that we increase
> the probability of precious user data not being lost, disabling scrubbing is not a good
> option, but disabling/changing torturing may be fine.
Ok, fine. As I said, you have the HW, you find out what works better for
you and submit patches :-)
> Perhaps we should have MTD/MLC return
> -EUCLEAN when say, 80-100% of the max possible corrections are done and then scrub the
> data to a good block, and then either torture the marginal block or mark it bad and remove
> the block from service?
Something like this.
> Another idea might be to remember with a torture histogram how many times a each block
> was sent out for torturing, and after N (3?) tortures, something is definitely bad, and
> then the block could be marked bad permanently.
Sounds reasonable and can be easily done. We have room in the EC header
to store this information.
> For MLC, you might consider just erasing the block and not torturing at all. Eventually the
> marginal block will hit the N threshold above and be taken out of service anyways. Then you
> don't need a mtd specific torture test at all...
I cannot comment on this because I do not know. If you see that this is
better for your HW, we can go this way. Send patches :-)
> > In general, I think all the MLC-specific things like "ECC 12" should be
> > hidden in the MTD level. Just because this information is too
> > MLC-specific for UBI to know about it.
> >
> > UBI should distinguish MLC and behave a bit different in that case, but
> > this should be about "torture MLC eraseblocks this special way", and the
> > like. IOW, on higher level than knowing about ECC levels.
>
> I agree the mtd driver should hide this information if possible, and we suggested that
> above for error reporting. But for torturing, that might mean we need to change the mtd
> interface to be able to request a flash specific torture test and return a status.
> Changing mtd seems to be harder than the suggestions above, and since torturing may make
> things worse, I think we should try to keep our solution in the ubi layer for now.
Then teach MTD to inform NAND type: SLC/MLC and UBI will avoid torturing
for MLC. Just send patches.
Really, just submit patches which work for your MLC. I can validate them
on the general level, but many decisions are up to you. Then if others
find your solution not good enough for their MLC - they will have to
improve it.
--
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2010-04-21 18:14 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2010-04-13 1:00 UBI wear leveling / torture testing algorithms having trouble with MLC flash Darwin Rambo
2010-04-14 17:30 ` Artem Bityutskiy
2010-04-15 18:01 ` Darwin Rambo
2010-04-21 13:13 ` Artem Bityutskiy
2010-04-21 16:51 ` Darwin Rambo
2010-04-21 18:13 ` Artem Bityutskiy
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.