| Message ID | 20131204142009.GB2486@localhost |
|---|---|
| State | New |
| Headers | show |
Hi Ezequiel, Ezequiel Garcia <ezequiel.garcia@free-electrons.com> writes: > Thanks a lot for the patience! Well, if we let the machines win, it's over. >> root@humble:~# nandwrite -p /dev/mtd4 mtd4ro >> Writing data to block 0 at offset 0x0 >> [ 449.915173] pxa3xx-nand d00d0000.nand: Ready time out!!! >> libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 0, offset 2048) >> error 5 (Input/output error) >> Erasing failed write from 00000000 to 0x01ffff >> Writing data to block 1 at offset 0x20000 >> [ 450.115172] pxa3xx-nand d00d0000.nand: Ready time out!!! >> libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 1, offset 2048) >> error 5 (Input/output error) >> Erasing failed write from 0x020000 to 0x03ffff >> Writing data to block 2 at offset 0x40000 >> [ 450.315171] pxa3xx-nand d00d0000.nand: Ready time out!!! >> libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 2, offset 2048) >> error 5 (Input/output error) >> Erasing failed write from 0x040000 to 0x05ffff >> Writing data to block 3 at offset 0x60000 >> [ 450.515171] pxa3xx-nand d00d0000.nand: Ready time out!!! >> libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 3, offset 2048) >> error 5 (Input/output error) >> Erasing failed write from 0x060000 to 0x07ffff >> Writing data to block 4 at offset 0x80000 >> [ 450.715169] pxa3xx-nand d00d0000.nand: Ready time out!!! >> libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 4, offset 2048) >> error 5 (Input/output error) >> Erasing failed write from 0x080000 to 0x09ffff >> Writing data to block 5 at offset 0xa0000 >> [ 450.915171] pxa3xx-nand d00d0000.nand: Ready time out!!! >> libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 5, offset 2048) >> error 5 (Input/output error) >> Erasing failed write from 0x0a0000 to 0x0bffff >> Writing data to block 6 at offset 0xc0000 >> [ 451.115171] pxa3xx-nand d00d0000.nand: Ready time out!!! >> libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 6, offset 2048) >> error 5 (Input/output error) >> Erasing failed write from 0x0c0000 to 0x0dffff >> Writing data to block 7 at offset 0xe0000 >> >> > > So, let me confirm this: you have systematically obtained a "Ready > timeout" when writing to the device, on every single write to a page, > correct? yep, this is what I have on the RN2120. > I'll prepare a patch against the branch we're working that adds lots of > pr_info(). It'll be very annoying for you, but it's the only way I can > think of, to get the driver's dirty inner sequence and to see *where* > is failing. > > However, before that patch, please do a quick test for me. It's just a > shot in the dark. The below diff removes the NDCB0_AUTO_RS flag from > the PAGE_PROG command when the page size is 2048 byte (or less). > > diff --git a/drivers/mtd/nand/pxa3xx_nand.c b/drivers/mtd/nand/pxa3xx_nand.c > index fd0ef93..038cf5d 100644 > --- a/drivers/mtd/nand/pxa3xx_nand.c > +++ b/drivers/mtd/nand/pxa3xx_nand.c > @@ -831,7 +831,6 @@ static int prepare_set_command(struct pxa3xx_nand_info *info, int command, > } > } else { > info->ndcb0 |= NDCB0_CMD_TYPE(0x1) > - | NDCB0_AUTO_RS > | NDCB0_ST_ROW_EN > | NDCB0_DBC > | (NAND_CMD_PAGEPROG << 8) > > Please apply this diff, and then try to write at least one page. If at > all possible you might try different approaches: > > $ flash_erase /dev/mtd2 0 1 > $ dd if=page.raw of=/dev/mtd2 bs=2048 count=1 > > $ flash_erase /dev/mtd2 0 1 > $ nandwrite page.raw /dev/mtd2 That's very weird. With the patch applied (I did not redo the whole set of tests below w/o the patch): Let's erase the first block of /dev/mtd4 root@thin:~# flash_erase /dev/mtd4 0 1 Erasing 128 Kibyte @ 0 -- 100 % complete Create a 2048 byte file: root@thin:~# dd if=/dev/urandom of=/tmp/page.raw bs=2048 count=1 1+0 records in 1+0 records out 2048 bytes (2.0 kB) copied, 0.00104352 s, 2.0 MB/s dd that file to the first block root@thin:~# dd if=/tmp/page.raw of=/dev/mtd4 bs=2048 count=1 1+0 records in 1+0 records out 2048 bytes (2.0 kB) copied, 0.0008344 s, 2.5 MB/s Do the same with nandwrite: root@thin:~# flash_erase /dev/mtd4 0 1 Erasing 128 Kibyte @ 0 -- 100 % complete root@thin:~# nandwrite /dev/mtd4 /tmp/page.raw Writing data to block 0 at offset 0x0 As it seems to work, let's now try with a complete image: root@thin:~# flash_erase /dev/mtd4 0 0 Erasing 128 Kibyte @ 72e0000 -- 99 % complete flash_erase: Skipping bad block at 07300000 flash_erase: Skipping bad block at 07320000 flash_erase: Skipping bad block at 07340000 flash_erase: Skipping bad block at 07360000 flash_erase: Skipping bad block at 07380000 flash_erase: Skipping bad block at 073a0000 flash_erase: Skipping bad block at 073c0000 flash_erase: Skipping bad block at 073e0000 Erasing 128 Kibyte @ 73e0000 -- 100 % complete root@thin:~# nandwrite /dev/mtd4 mtd4ro Writing data to block 0 at offset 0x0 [ 421.406929] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 0, offset 2048) error 5 (Input/output error) Erasing failed write from 00000000 to 0x01ffff Writing data to block 1 at offset 0x20000 [ 421.606928] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 1, offset 2048) error 5 (Input/output error) Erasing failed write from 0x020000 to 0x03ffff Writing data to block 2 at offset 0x40000 [ 421.806928] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 2, offset 2048) error 5 (Input/output error) Erasing failed write from 0x040000 to 0x05ffff Writing data to block 3 at offset 0x60000 [ 422.006928] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 3, offset 2048) error 5 (Input/output error) Erasing failed write from 0x060000 to 0x07ffff Writing data to block 4 at offset 0x80000 [ 422.206928] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 4, offset 2048) error 5 (Input/output error) Erasing failed write from 0x080000 to 0x09ffff Writing data to block 5 at offset 0xa0000 ^C[ 422.406926] pxa3xx-nand d00d0000.nand: Ready time out!!! So let's try again with a single page: root@thin:~# flash_erase /dev/mtd4 0 1 Erasing 128 Kibyte @ 0 -- 100 % complete root@thin:~# nandwrite /dev/mtd4 /tmp/page.raw Writing data to block 0 at offset 0x0 FWIW, the version of nandwrite I have on my armhf debian is the following (no specific bug report related to that version of mtd-utils): root@thin:~# nandwrite --version nandwrite 1.5.0 Copyright (C) 2003 Thomas Gleixner nandwrite comes with NO WARRANTY to the extent permitted by law. You may redistribute copies of nandwrite under the terms of the GNU General Public Licence. See the file `COPYING' for more information. Ok, so let's see if the problem appears if we write more than 1 block: root@thin:/tmp# flash_erase /dev/mtd4 0 3 Erasing 128 Kibyte @ 40000 -- 100 % complete root@thin:/tmp# dd if=/dev/urandom of=/tmp/3-blocks.raw bs=128K count=3 3+0 records in 3+0 records out 393216 bytes (393 kB) copied, 0.120255 s, 3.3 MB/s root@thin:/tmp# nandwrite /dev/mtd4 /tmp/3-blocks.raw Writing data to block 0 at offset 0x0 Writing data to block 1 at offset 0x20000 Writing data to block 2 at offset 0x40000 Now, I am starting to wonder if nandwrite does not try and do something smart depending on the content of the file. So let's try and replace our "mtd4ro" file by a file of same size filled with random: root@thin:~# ls -l mtd4ro -rw-r--r-- 1 arno root 121634816 Dec 3 20:30 mtd4ro root@thin:~# dd if=/dev/urandom of=/tmp/whole.raw bs=128K count=928 928+0 records in 928+0 records out 121634816 bytes (122 MB) copied, 37.1333 s, 3.3 MB/s root@thin:~# flash_erase /dev/mtd4 0 1 Erasing 128 Kibyte @ 0 -- 100 % complete root@thin:~# nandwrite /dev/mtd4 /tmp/whole.raw Writing data to block 0 at offset 0x0 ... Writing data to block 916 at offset 0x7280000 Writing data to block 917 at offset 0x72a0000 Writing data to block 918 at offset 0x72c0000 Writing data to block 919 at offset 0x72e0000 Writing data to block 920 at offset 0x7300000 Bad block at 7300000, 1 block(s) from 7300000 will be skipped Writing data to block 921 at offset 0x7320000 Bad block at 7320000, 1 block(s) from 7320000 will be skipped Writing data to block 922 at offset 0x7340000 Bad block at 7340000, 1 block(s) from 7340000 will be skipped Writing data to block 923 at offset 0x7360000 Bad block at 7360000, 1 block(s) from 7360000 will be skipped Writing data to block 924 at offset 0x7380000 Bad block at 7380000, 1 block(s) from 7380000 will be skipped Writing data to block 925 at offset 0x73a0000 Bad block at 73a0000, 1 block(s) from 73a0000 will be skipped Writing data to block 926 at offset 0x73c0000 Bad block at 73c0000, 1 block(s) from 73c0000 will be skipped Writing data to block 927 at offset 0x73e0000 Bad block at 73e0000, 1 block(s) from 73e0000 will be skipped Writing data to block 928 at offset 0x7400000 libmtd: error!: bad eraseblock number 928, mtd4 has 928 eraseblocks nandwrite: error!: /dev/mtd4: MTD get bad block failed error 22 (Invalid argument) nandwrite: error!: Data was only partially written due to error error 22 (Invalid argument) I don't believe it! It works as expected. As said previously, the content of my "mtd4ro" is a simple a backup of the partition via dd (a ubi fs): root@thin:~# hexdump -C mtd4ro | less 00000000 55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02 |UBI#............| 00000010 00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00 |..........v.....| 00000020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| 00000030 00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a |............e.&:| 00000040 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| * 000007f0 00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00 |................| 00000800 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................| * 00020000 55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02 |UBI#............| 00020010 00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00 |..........v.....| 00020020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| 00020030 00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a |............e.&:| 00020040 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................| * 000207f0 00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00 |................| 00020800 55 42 49 21 01 01 00 00 00 00 00 00 00 00 00 00 |UBI!............| Just to be sure, I did the test three times for each input file: mtd4ro, whole.raw, mtd4ro, whole.raw, mtd4ro, whole.raw: - whole.raw: no error the three times - mtd4ro: errors each time Let's now try with the first block only: root@thin:~# dd if=mtd4ro of=/tmp/oneblock bs=128K count=1 1+0 records in 1+0 records out 131072 bytes (131 kB) copied, 0.00126152 s, 104 MB/s root@thin:~# flash_erase /dev/mtd4 0 1 Erasing 128 Kibyte @ 0 -- 100 % complete root@thin:~# nandwrite /dev/mtd4 /tmp/oneblock Writing data to block 0 at offset 0x0 [ 3860.346928] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 0, offset 2048) error 5 (Input/output error) Erasing failed write from 00000000 to 0x01ffff Writing data to block 1 at offset 0x20000 [ 3860.546928] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 1, offset 2048) error 5 (Input/output error) AFAICT, it seems someone in the process does not like the UBI fs dump I provide: nandwrite, your driver, mtd base code or the chip. I took a very quick look at nandwrite code and it has some options to do smart stuff but they seem to be all disabled by default when no cmd line option is passed. Could you try and dump the block to another flash. As I don't think I can attach a binary blob to this email, can you drop the following in a python shell: l = ["55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02", "00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00", "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00", "00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a", "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00"*0x7b, "00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00", "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff", "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff"*0x1f7f] open("/tmp/block.raw", "w").write("".join(l).replace(' ', '').decode("hex")) FWIW, you should have the following sha256 for the file: d3e5534e054f2ab1220194c434d90fbfe9580459de887016db8e308739aa3a7b If you have any additional idea, I am interested. I have no more time this evening to test the other debug patch you sent but I will definitely give it a try tomorrow. If I did something stupid in the process, do not hesitate! Cheers, a+
Hi Ezequiel, arno@natisbad.org (Arnaud Ebalard) writes: > Could you try and dump the block to another flash. As I don't think I can > attach a binary blob to this email, can you drop the following in a > python shell: > > l = ["55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02", > "00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00", > "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00", > "00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a", > "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00"*0x7b, > "00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00", > "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff", > "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff"*0x1f7f] > > open("/tmp/block.raw", "w").write("".join(l).replace(' ', '').decode("hex")) > > FWIW, you should have the following sha256 for the file: > d3e5534e054f2ab1220194c434d90fbfe9580459de887016db8e308739aa3a7b > > If you have any additional idea, I am interested. I have no more time > this evening to test the other debug patch you sent but I will > definitely give it a try tomorrow. I reused the block above to test on the kernel w/ your debug patch applied: root@thin:~# python Python 2.7.6 (default, Nov 19 2013, 18:53:23) [GCC 4.8.2] on linux2 Type "help", "copyright", "credits" or "license" for more information. l = ["55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02", "00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00", "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00", "00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a", "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00"*0x7b, "00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00", "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff", "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff"*0x1f7f] >>> l = ["55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02", ... "00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00", ... "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00", ... "00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a", ... "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00"*0x7b, ... "00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00", ... "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff", ... "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff"*0x1f7f] >>> >>> open("/tmp/block.raw", "w").write("".join(l).replace(' ', '').decode("hex")) root@thin:~# root@thin:/sys/kernel/debug/dynamic_debug# flash_erase /dev/mtd4 0 1 Erasing 128 Kibyte @ 0 -- 100 % complete root@thin:/sys/kernel/debug/dynamic_debug# nandwrite /dev/mtd4 /tmp/block.raw Writing data to block 0 at offset 0x0 [ 784.543390] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 0, offset 2048) error 5 (Input/output error) Erasing failed write from 00000000 to 0x01ffff Writing data to block 1 at offset 0x20000 [ 784.743391] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 1, offset 2048) error 5 (Input/output error) Erasing failed write from 0x020000 to 0x03ffff Writing data to block 2 at offset 0x40000 [ 784.943390] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 2, offset 2048) error 5 (Input/output error) Erasing failed write from 0x040000 to 0x05ffff Writing data to block 3 at offset 0x60000 [ 785.143391] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 3, offset 2048) error 5 (Input/output error) Erasing failed write from 0x060000 to 0x07ffff Writing data to block 4 at offset 0x80000 [ 785.343388] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 4, offset 2048) error 5 (Input/output error) Erasing failed write from 0x080000 to 0x09ffff Writing data to block 5 at offset 0xa0000 [ 785.543390] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 5, offset 2048) error 5 (Input/output error) Erasing failed write from 0x0a0000 to 0x0bffff Writing data to block 6 at offset 0xc0000 [ 785.743390] pxa3xx-nand d00d0000.nand: Ready time out!!! libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 6, offset 2048) error 5 (Input/output error) Erasing failed write from 0x0c0000 to 0x0dffff Writing data to block 7 at offset 0xe0000 And here is what I get in kernel logs: [ 766.262816] Command0 0x810070 [ 766.262827] Command1 0x0 [ 766.262833] Command2 0x0 [ 766.262838] Command3 0x0 [ 766.262853] Command0 0x24bd060 [ 766.262858] Command1 0x1800 [ 766.262863] Command2 0x0 [ 766.262868] Command3 0x0 [ 766.263617] Status: ready [ 766.263937] Waiting for device to be ready [ 766.263945] Device is ready [ 784.345577] Command0 0x810070 [ 784.345588] Command1 0x0 [ 784.345594] Command2 0x0 [ 784.345599] Command3 0x0 [ 784.345626] Command0 0x62c1080 [ 784.345632] Command1 0x18000000 [ 784.345637] Command2 0x0 [ 784.345642] Command3 0x0 [ 784.345960] Status: ready [ 784.345976] Waiting for device to be ready [ 784.345981] Device is ready [ 784.346006] Command0 0x810070 [ 784.346012] Command1 0x0 [ 784.346017] Command2 0x0 [ 784.346022] Command3 0x0 [ 784.346044] Waiting for device to be ready [ 784.543390] pxa3xx-nand d00d0000.nand: Ready time out!!! [ 784.548850] Command0 0x810070 [ 784.548857] Command1 0x0 [ 784.548863] Command2 0x0 [ 784.548868] Command3 0x0 [ 784.548888] Command0 0x24bd060 [ 784.548893] Command1 0x1800 [ 784.548898] Command2 0x0 [ 784.548903] Command3 0x0 [ 784.549648] Status: ready [ 784.549661] Waiting for device to be ready [ 784.549667] Device is ready [ 784.549701] Command0 0x810070 [ 784.549707] Command1 0x0 [ 784.549712] Command2 0x0 [ 784.549716] Command3 0x0 [ 784.549736] Command0 0x62c1080 [ 784.549742] Command1 0x18400000 [ 784.549747] Command2 0x0 [ 784.549751] Command3 0x0 [ 784.550074] Status: ready [ 784.550087] Waiting for device to be ready [ 784.550093] Device is ready [ 784.550109] Command0 0x810070 [ 784.550115] Command1 0x0 [ 784.550119] Command2 0x0 [ 784.550124] Command3 0x0 [ 784.550146] Waiting for device to be ready [ 784.743391] pxa3xx-nand d00d0000.nand: Ready time out!!! [ 784.748780] Command0 0x810070 [ 784.748786] Command1 0x0 [ 784.748792] Command2 0x0 [ 784.748797] Command3 0x0 [ 784.748815] Command0 0x24bd060 [ 784.748821] Command1 0x1840 [ 784.748826] Command2 0x0 [ 784.748831] Command3 0x0 [ 784.749575] Status: ready [ 784.749589] Waiting for device to be ready [ 784.749595] Device is ready [ 784.749628] Command0 0x810070 [ 784.749634] Command1 0x0 [ 784.749639] Command2 0x0 [ 784.749644] Command3 0x0 [ 784.749663] Command0 0x62c1080 [ 784.749669] Command1 0x18800000 [ 784.749674] Command2 0x0 [ 784.749679] Command3 0x0 [ 784.749995] Status: ready [ 784.750007] Waiting for device to be ready [ 784.750013] Device is ready [ 784.750028] Command0 0x810070 So let's now do the same with a fully random block: root@thin:/# dd if=/dev/urandom of=/tmp/block.random bs=131072 count=1 1+0 records in 1+0 records out 131072 bytes (131 kB) copied, 0.0406636 s, 3.2 MB/s root@thin:~# flash_erase /dev/mtd4 0 1 Erasing 128 Kibyte @ 0 -- 100 % complete root@thin:~# nandwrite /dev/mtd4 /tmp/block.random Writing data to block 0 at offset 0x0 In the log, I get the following: [ 1422.296953] Command0 0x810070 [ 1422.296965] Command1 0x0 [ 1422.296970] Command2 0x0 [ 1422.296975] Command3 0x0 [ 1422.296990] Command0 0x24bd060 [ 1422.296996] Command1 0x1800 [ 1422.297001] Command2 0x0 [ 1422.297006] Command3 0x0 [ 1422.297752] Status: ready [ 1422.297767] Waiting for device to be ready [ 1422.297773] Device is ready [ 1488.147298] Command0 0x810070 [ 1488.147310] Command1 0x0 [ 1488.147316] Command2 0x0 [ 1488.147321] Command3 0x0 [ 1488.147340] Command0 0x62c1080 [ 1488.147345] Command1 0x18000000 [ 1488.147350] Command2 0x0 [ 1488.147355] Command3 0x0 [ 1488.147673] Status: ready [ 1488.147689] Waiting for device to be ready [ 1488.147695] Device is ready [ 1488.147720] Command0 0x810070 [ 1488.147725] Command1 0x0 [ 1488.147730] Command2 0x0 [ 1488.147735] Command3 0x0 [ 1488.147754] Command0 0x62c1080 [ 1488.147759] Command1 0x18010000 [ 1488.147764] Command2 0x0 [ 1488.147769] Command3 0x0 [ 1488.148085] Status: ready [ 1488.148098] Waiting for device to be ready [ 1488.148103] Device is ready [ 1488.148125] Command0 0x810070 [ 1488.148130] Command1 0x0 [ 1488.148135] Command2 0x0 [ 1488.148140] Command3 0x0 [ 1488.148158] Command0 0x62c1080 [ 1488.148164] Command1 0x18020000 [ 1488.148169] Command2 0x0 [ 1488.148174] Command3 0x0 [ 1488.148490] Status: ready [ 1488.148503] Waiting for device to be ready [ 1488.148508] Device is ready [ 1488.148537] Command0 0x810070 [ 1488.148543] Command1 0x0 [ 1488.148548] Command2 0x0 [ 1488.148553] Command3 0x0 [ 1488.148567] Command0 0x62c1080 [ 1488.148572] Command1 0x18030000 [ 1488.148577] Command2 0x0 [ 1488.148582] Command3 0x0 [ 1488.148955] Status: ready [ 1488.148968] Waiting for device to be ready [ 1488.148973] Device is ready [ 1488.148995] Command0 0x810070 [ 1488.149001] Command1 0x0 [ 1488.149006] Command2 0x0 [ 1488.149011] Command3 0x0 [ 1488.149029] Command0 0x62c1080 [ 1488.149035] Command1 0x18040000 [ 1488.149039] Command2 0x0 [ 1488.149044] Command3 0x0 [ 1488.149417] Status: ready [ 1488.149429] Waiting for device to be ready [ 1488.149434] Device is ready [ 1488.149456] Command0 0x810070 [ 1488.149462] Command1 0x0 [ 1488.149466] Command2 0x0 [ 1488.149471] Command3 0x0 [ 1488.149486] Command0 0x62c1080 [ 1488.149491] Command1 0x18050000 [ 1488.149496] Command2 0x0 [ 1488.149501] Command3 0x0 [ 1488.149817] Status: ready [ 1488.149830] Waiting for device to be ready [ 1488.149835] Device is ready [ 1488.149857] Command0 0x810070 [ 1488.149863] Command1 0x0 [ 1488.149867] Command2 0x0 [ 1488.149872] Command3 0x0 [ 1488.149891] Command0 0x62c1080 [ 1488.149896] Command1 0x18060000 [ 1488.149901] Command2 0x0 [ 1488.149906] Command3 0x0 [ 1488.150279] Status: ready [ 1488.150292] Waiting for device to be ready [ 1488.150297] Device is ready [ 1488.150319] Command0 0x810070 [ 1488.150325] Command1 0x0 [ 1488.150330] Command2 0x0 [ 1488.150334] Command3 0x0 [ 1488.150353] Command0 0x62c1080 [ 1488.150359] Command1 0x18070000 [ 1488.150363] Command2 0x0 [ 1488.150368] Command3 0x0 [ 1488.150685] Status: ready [ 1488.150697] Waiting for device to be ready [ 1488.150702] Device is ready If you had the time to test the offending block on another device, did you manage to reproduce what I get? Cheers, a+
On Wed, Dec 04, 2013 at 09:48:04PM +0100, Arnaud Ebalard wrote: > Now, I am starting to wonder if nandwrite does not try and do something > smart depending on the content of the file. nandwrite does not do any data-dependent operations. It only checks the size of the file to verify against MTD alignment restrictions, but otherwise, it is simply a dump page-at-a-time programmer. However, there are other characteristics which do differentiate it from dd, so it's not surprising if nandwrite can uncover different code behaviors than dd. (BTW, I wouldn't recommend dd for NAND programming. It may be useful for certain debugging purposes, but it ignore bad blocks and is generally dangerous to use for any regular purposes.) Brian
On Thu, Dec 05, 2013 at 09:42:25PM +0100, Arnaud Ebalard wrote: > Hi Ezequiel, > > arno@natisbad.org (Arnaud Ebalard) writes: > > > Could you try and dump the block to another flash. As I don't think I can > > attach a binary blob to this email, can you drop the following in a > > python shell: > > > > l = ["55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02", > > "00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00", > > "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00", > > "00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a", > > "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00"*0x7b, > > "00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00", > > "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff", > > "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff"*0x1f7f] > > > > open("/tmp/block.raw", "w").write("".join(l).replace(' ', '').decode("hex")) > > > > FWIW, you should have the following sha256 for the file: > > d3e5534e054f2ab1220194c434d90fbfe9580459de887016db8e308739aa3a7b > > > > If you have any additional idea, I am interested. I have no more time > > this evening to test the other debug patch you sent but I will > > definitely give it a try tomorrow. > > I reused the block above to test on the kernel w/ your debug patch > applied: > > root@thin:~# python > Python 2.7.6 (default, Nov 19 2013, 18:53:23) > [GCC 4.8.2] on linux2 > Type "help", "copyright", "credits" or "license" for more information. > l = ["55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02", > "00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00", > "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00", > "00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a", > "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00"*0x7b, > "00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00", > "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff", > "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff"*0x1f7f] > > >>> l = ["55 42 49 23 01 00 00 00 00 00 00 00 00 00 00 02", > ... "00 00 08 00 00 00 10 00 16 9a 76 a5 00 00 00 00", > ... "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00", > ... "00 00 00 00 00 00 00 00 00 00 00 00 65 9c 26 3a", > ... "00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00"*0x7b, > ... "00 00 00 00 00 00 00 00 00 00 00 02 00 00 00 00", > ... "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff", > ... "ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff"*0x1f7f] > >>> > >>> open("/tmp/block.raw", "w").write("".join(l).replace(' ', '').decode("hex")) root@thin:~# > > root@thin:/sys/kernel/debug/dynamic_debug# flash_erase /dev/mtd4 0 1 > Erasing 128 Kibyte @ 0 -- 100 % complete > > root@thin:/sys/kernel/debug/dynamic_debug# nandwrite /dev/mtd4 /tmp/block.raw > Writing data to block 0 at offset 0x0 > [ 784.543390] pxa3xx-nand d00d0000.nand: Ready time out!!! > libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 0, offset 2048) > error 5 (Input/output error) > Erasing failed write from 00000000 to 0x01ffff > Writing data to block 1 at offset 0x20000 > [ 784.743391] pxa3xx-nand d00d0000.nand: Ready time out!!! > libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 1, offset 2048) > error 5 (Input/output error) > Erasing failed write from 0x020000 to 0x03ffff > Writing data to block 2 at offset 0x40000 > [ 784.943390] pxa3xx-nand d00d0000.nand: Ready time out!!! > libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 2, offset 2048) > error 5 (Input/output error) > Erasing failed write from 0x040000 to 0x05ffff > Writing data to block 3 at offset 0x60000 > [ 785.143391] pxa3xx-nand d00d0000.nand: Ready time out!!! > libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 3, offset 2048) > error 5 (Input/output error) > Erasing failed write from 0x060000 to 0x07ffff > Writing data to block 4 at offset 0x80000 > [ 785.343388] pxa3xx-nand d00d0000.nand: Ready time out!!! > libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 4, offset 2048) > error 5 (Input/output error) > Erasing failed write from 0x080000 to 0x09ffff > Writing data to block 5 at offset 0xa0000 > [ 785.543390] pxa3xx-nand d00d0000.nand: Ready time out!!! > libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 5, offset 2048) > error 5 (Input/output error) > Erasing failed write from 0x0a0000 to 0x0bffff > Writing data to block 6 at offset 0xc0000 > [ 785.743390] pxa3xx-nand d00d0000.nand: Ready time out!!! > libmtd: error!: cannot write 2048 bytes to mtd4 (eraseblock 6, offset 2048) > error 5 (Input/output error) > Erasing failed write from 0x0c0000 to 0x0dffff > Writing data to block 7 at offset 0xe0000 > > And here is what I get in kernel logs: > > [ 766.262816] Command0 0x810070 > [ 766.262827] Command1 0x0 > [ 766.262833] Command2 0x0 > [ 766.262838] Command3 0x0 > [ 766.262853] Command0 0x24bd060 > [ 766.262858] Command1 0x1800 > [ 766.262863] Command2 0x0 > [ 766.262868] Command3 0x0 > [ 766.263617] Status: ready > [ 766.263937] Waiting for device to be ready > [ 766.263945] Device is ready > [ 784.345577] Command0 0x810070 > [ 784.345588] Command1 0x0 > [ 784.345594] Command2 0x0 > [ 784.345599] Command3 0x0 > [ 784.345626] Command0 0x62c1080 > [ 784.345632] Command1 0x18000000 > [ 784.345637] Command2 0x0 > [ 784.345642] Command3 0x0 > [ 784.345960] Status: ready > [ 784.345976] Waiting for device to be ready > [ 784.345981] Device is ready > [ 784.346006] Command0 0x810070 > [ 784.346012] Command1 0x0 > [ 784.346017] Command2 0x0 > [ 784.346022] Command3 0x0 > [ 784.346044] Waiting for device to be ready > [ 784.543390] pxa3xx-nand d00d0000.nand: Ready time out!!! > [ 784.548850] Command0 0x810070 > [ 784.548857] Command1 0x0 > [ 784.548863] Command2 0x0 > [ 784.548868] Command3 0x0 > [ 784.548888] Command0 0x24bd060 > [ 784.548893] Command1 0x1800 > [ 784.548898] Command2 0x0 > [ 784.548903] Command3 0x0 > [ 784.549648] Status: ready > [ 784.549661] Waiting for device to be ready > [ 784.549667] Device is ready > [ 784.549701] Command0 0x810070 > [ 784.549707] Command1 0x0 > [ 784.549712] Command2 0x0 > [ 784.549716] Command3 0x0 > [ 784.549736] Command0 0x62c1080 > [ 784.549742] Command1 0x18400000 > [ 784.549747] Command2 0x0 > [ 784.549751] Command3 0x0 > [ 784.550074] Status: ready > [ 784.550087] Waiting for device to be ready > [ 784.550093] Device is ready > [ 784.550109] Command0 0x810070 > [ 784.550115] Command1 0x0 > [ 784.550119] Command2 0x0 > [ 784.550124] Command3 0x0 > [ 784.550146] Waiting for device to be ready > [ 784.743391] pxa3xx-nand d00d0000.nand: Ready time out!!! > [ 784.748780] Command0 0x810070 > [ 784.748786] Command1 0x0 > [ 784.748792] Command2 0x0 > [ 784.748797] Command3 0x0 > [ 784.748815] Command0 0x24bd060 > [ 784.748821] Command1 0x1840 > [ 784.748826] Command2 0x0 > [ 784.748831] Command3 0x0 > [ 784.749575] Status: ready > [ 784.749589] Waiting for device to be ready > [ 784.749595] Device is ready > [ 784.749628] Command0 0x810070 > [ 784.749634] Command1 0x0 > [ 784.749639] Command2 0x0 > [ 784.749644] Command3 0x0 > [ 784.749663] Command0 0x62c1080 > [ 784.749669] Command1 0x18800000 > [ 784.749674] Command2 0x0 > [ 784.749679] Command3 0x0 > [ 784.749995] Status: ready > [ 784.750007] Waiting for device to be ready > [ 784.750013] Device is ready > [ 784.750028] Command0 0x810070 > > > So let's now do the same with a fully random block: > > root@thin:/# dd if=/dev/urandom of=/tmp/block.random bs=131072 count=1 > 1+0 records in > 1+0 records out > 131072 bytes (131 kB) copied, 0.0406636 s, 3.2 MB/s > > root@thin:~# flash_erase /dev/mtd4 0 1 > Erasing 128 Kibyte @ 0 -- 100 % complete > > root@thin:~# nandwrite /dev/mtd4 /tmp/block.random > Writing data to block 0 at offset 0x0 > > In the log, I get the following: > > [ 1422.296953] Command0 0x810070 > [ 1422.296965] Command1 0x0 > [ 1422.296970] Command2 0x0 > [ 1422.296975] Command3 0x0 > [ 1422.296990] Command0 0x24bd060 > [ 1422.296996] Command1 0x1800 > [ 1422.297001] Command2 0x0 > [ 1422.297006] Command3 0x0 > [ 1422.297752] Status: ready > [ 1422.297767] Waiting for device to be ready > [ 1422.297773] Device is ready > [ 1488.147298] Command0 0x810070 > [ 1488.147310] Command1 0x0 > [ 1488.147316] Command2 0x0 > [ 1488.147321] Command3 0x0 > [ 1488.147340] Command0 0x62c1080 > [ 1488.147345] Command1 0x18000000 > [ 1488.147350] Command2 0x0 > [ 1488.147355] Command3 0x0 > [ 1488.147673] Status: ready > [ 1488.147689] Waiting for device to be ready > [ 1488.147695] Device is ready > [ 1488.147720] Command0 0x810070 > [ 1488.147725] Command1 0x0 > [ 1488.147730] Command2 0x0 > [ 1488.147735] Command3 0x0 > [ 1488.147754] Command0 0x62c1080 > [ 1488.147759] Command1 0x18010000 > [ 1488.147764] Command2 0x0 > [ 1488.147769] Command3 0x0 > [ 1488.148085] Status: ready > [ 1488.148098] Waiting for device to be ready > [ 1488.148103] Device is ready > [ 1488.148125] Command0 0x810070 > [ 1488.148130] Command1 0x0 > [ 1488.148135] Command2 0x0 > [ 1488.148140] Command3 0x0 > [ 1488.148158] Command0 0x62c1080 > [ 1488.148164] Command1 0x18020000 > [ 1488.148169] Command2 0x0 > [ 1488.148174] Command3 0x0 > [ 1488.148490] Status: ready > [ 1488.148503] Waiting for device to be ready > [ 1488.148508] Device is ready > [ 1488.148537] Command0 0x810070 > [ 1488.148543] Command1 0x0 > [ 1488.148548] Command2 0x0 > [ 1488.148553] Command3 0x0 > [ 1488.148567] Command0 0x62c1080 > [ 1488.148572] Command1 0x18030000 > [ 1488.148577] Command2 0x0 > [ 1488.148582] Command3 0x0 > [ 1488.148955] Status: ready > [ 1488.148968] Waiting for device to be ready > [ 1488.148973] Device is ready > [ 1488.148995] Command0 0x810070 > [ 1488.149001] Command1 0x0 > [ 1488.149006] Command2 0x0 > [ 1488.149011] Command3 0x0 > [ 1488.149029] Command0 0x62c1080 > [ 1488.149035] Command1 0x18040000 > [ 1488.149039] Command2 0x0 > [ 1488.149044] Command3 0x0 > [ 1488.149417] Status: ready > [ 1488.149429] Waiting for device to be ready > [ 1488.149434] Device is ready > [ 1488.149456] Command0 0x810070 > [ 1488.149462] Command1 0x0 > [ 1488.149466] Command2 0x0 > [ 1488.149471] Command3 0x0 > [ 1488.149486] Command0 0x62c1080 > [ 1488.149491] Command1 0x18050000 > [ 1488.149496] Command2 0x0 > [ 1488.149501] Command3 0x0 > [ 1488.149817] Status: ready > [ 1488.149830] Waiting for device to be ready > [ 1488.149835] Device is ready > [ 1488.149857] Command0 0x810070 > [ 1488.149863] Command1 0x0 > [ 1488.149867] Command2 0x0 > [ 1488.149872] Command3 0x0 > [ 1488.149891] Command0 0x62c1080 > [ 1488.149896] Command1 0x18060000 > [ 1488.149901] Command2 0x0 > [ 1488.149906] Command3 0x0 > [ 1488.150279] Status: ready > [ 1488.150292] Waiting for device to be ready > [ 1488.150297] Device is ready > [ 1488.150319] Command0 0x810070 > [ 1488.150325] Command1 0x0 > [ 1488.150330] Command2 0x0 > [ 1488.150334] Command3 0x0 > [ 1488.150353] Command0 0x62c1080 > [ 1488.150359] Command1 0x18070000 > [ 1488.150363] Command2 0x0 > [ 1488.150368] Command3 0x0 > [ 1488.150685] Status: ready > [ 1488.150697] Waiting for device to be ready > [ 1488.150702] Device is ready > > If you had the time to test the offending block on another device, did > you manage to reproduce what I get? > Thanks for the command trace! I'll look at this in detail tomorrow and let you know.
Hi Arnaud, On Thu, Dec 05, 2013 at 09:42:25PM +0100, Arnaud Ebalard wrote: [..] > [ 1488.150697] Waiting for device to be ready > [ 1488.150702] Device is ready > > If you had the time to test the offending block on another device, did > you manage to reproduce what I get? > Yes, I managed to reproduced your timeout. You found a bug on my dev_ready completion handler scheme, and now I officially hate this evil completion handler ;-) I've pushed a new branch for you to try: https://github.com/MISL-EBU-System-SW/mainline-public/tree/pxa3xx-armada-nand-new-ecc-v2 Please give it a try, and test as heavily and creatively as you can think off.
Hi Ezequiel, Ezequiel Garcia <ezequiel.garcia@free-electrons.com> writes: > Hi Arnaud, > > On Thu, Dec 05, 2013 at 09:42:25PM +0100, Arnaud Ebalard wrote: > [..] >> [ 1488.150697] Waiting for device to be ready >> [ 1488.150702] Device is ready >> >> If you had the time to test the offending block on another device, did >> you manage to reproduce what I get? >> > > Yes, I managed to reproduced your timeout. You found a bug on my > dev_ready completion handler scheme, and now I officially hate this > evil completion handler ;-) > > I've pushed a new branch for you to try: > > https://github.com/MISL-EBU-System-SW/mainline-public/tree/pxa3xx-armada-nand-new-ecc-v2 > > Please give it a try, and test as heavily and creatively as you can > think off. Sorry, but I was unable to find any more bug, i.e. AFAICT it does work as expected now :-) FWIW, thanks for your time, you can put my: Tested-by: Arnaud Ebalard <arno@natisbad.org> Cheers, a+
On Fri, Dec 06, 2013 at 10:41:32PM +0100, Arnaud Ebalard wrote: > Hi Ezequiel, > > Ezequiel Garcia <ezequiel.garcia@free-electrons.com> writes: > > > Hi Arnaud, > > > > On Thu, Dec 05, 2013 at 09:42:25PM +0100, Arnaud Ebalard wrote: > > [..] > >> [ 1488.150697] Waiting for device to be ready > >> [ 1488.150702] Device is ready > >> > >> If you had the time to test the offending block on another device, did > >> you manage to reproduce what I get? > >> > > > > Yes, I managed to reproduced your timeout. You found a bug on my > > dev_ready completion handler scheme, and now I officially hate this > > evil completion handler ;-) > > > > I've pushed a new branch for you to try: > > > > https://github.com/MISL-EBU-System-SW/mainline-public/tree/pxa3xx-armada-nand-new-ecc-v2 > > > > Please give it a try, and test as heavily and creatively as you can > > think off. > > Sorry, but I was unable to find any more bug, i.e. AFAICT it does work > as expected now :-) FWIW, thanks for your time, you can put my: > > Tested-by: Arnaud Ebalard <arno@natisbad.org> > Great! I'll push the patches then with your tested-by.
diff --git a/drivers/mtd/nand/pxa3xx_nand.c b/drivers/mtd/nand/pxa3xx_nand.c index fd0ef93..038cf5d 100644 --- a/drivers/mtd/nand/pxa3xx_nand.c +++ b/drivers/mtd/nand/pxa3xx_nand.c @@ -831,7 +831,6 @@ static int prepare_set_command(struct pxa3xx_nand_info *info, int command, } } else { info->ndcb0 |= NDCB0_CMD_TYPE(0x1) - | NDCB0_AUTO_RS | NDCB0_ST_ROW_EN | NDCB0_DBC | (NAND_CMD_PAGEPROG << 8)