Patchwork Fastmap and Atmel sam-ba

login
register
mail settings
Submitter Richard Weinberger
Date Aug. 23, 2013, 6:59 p.m.
Message ID <5217B101.3040306@nod.at>
Download mbox | patch
Permalink /patch/269521/
State New
Headers show

Comments

Richard Weinberger - Aug. 23, 2013, 6:59 p.m.
Hi again,
Am 23.08.2013 15:55, schrieb Richard Genoud:
> [arg ! I forgot to cc the mtd list. This new gmail interface is a pain !]
> 
> 2013/8/23 Richard Genoud <richard.genoud@gmail.com>:
>> Hi Artem, Richard,
>>
>> I'm starting to use fastmap (and I saved 650ms on a 240MiB partition,
>> allowing to boot in less than 2sec :) ) and I ran into a bug (or I
>> missed something).
>>
>> When I use ubinize to make a ubi image, then flash this image with
>> Atmel's sam-ba.
>>
>> Then, if I boot a kernel with fastmap *not compiled*, it's ok.
>> ( booting the kernel with "console=ttyS0,115200 loglevel=8 rw
>> root=ubi0:rootfs rootfstype=ubifs ubi.mtd=UBI" )
>> BUT, if I do the same with a kernel with fastmap compiled (but not
>> activated), I've got that kind of error:
>>
>> [    0.687500] UBI: default fastmap pool size: 95
>> [    0.695312] UBI: default fastmap WL pool size: 25
>> [    0.695312] UBI: attaching mtd2 to ubi0
>> [    0.703125] UBI DBG gen (pid 1): sizeof(struct ubi_ainf_peb) 48
>> [    0.710937] UBI DBG gen (pid 1): sizeof(struct ubi_wl_entry) 20
>> [    0.710937] UBI DBG gen (pid 1): min_io_size      2048
>> [    0.718750] UBI DBG gen (pid 1): max_write_size   2048
>> [    0.718750] UBI DBG gen (pid 1): hdrs_min_io_size 2048
>> [    0.726562] UBI DBG gen (pid 1): ec_hdr_alsize    2048
>> [    0.734375] UBI DBG gen (pid 1): vid_hdr_alsize   2048
>> [    0.734375] UBI DBG gen (pid 1): vid_hdr_offset   2048
>> [    0.742187] UBI DBG gen (pid 1): vid_hdr_aloffset 2048
>> [    0.742187] UBI DBG gen (pid 1): vid_hdr_shift    0
>> [    0.750000] UBI DBG gen (pid 1): leb_start        4096
>> [    0.757812] UBI DBG gen (pid 1): max_erroneous    196
>> [    0.757812] UBI DBG gen (pid 1): process PEB 0
>> [    0.765625] UBI DBG bld (pid 1): scan PEB 0
>> [    0.765625] UBI DBG io (pid 1): read EC header from PEB 0
>> [    0.773437] UBI DBG io (pid 1): read 64 bytes from PEB 0:0
>> [    0.781250] UBI DBG io (pid 1): read VID header from PEB 0
>> [    0.781250] UBI DBG io (pid 1): read 2048 bytes from PEB 0:2048
>> [    0.789062] UBI DBG bld (pid 1): PEB 0, LEB 2147479551:0, EC 0,
>> sqnum 0, bitflips 0
>> [    0.796875] UBI DBG bld (pid 1): added volume 2147479551
>> [    0.804687] UBI DBG gen (pid 1): process PEB 1
>> [...]
>> [   64.093750] UBI: scanning is finished
>> [   64.093750] UBI DBG gen (pid 1): max. sequence number:       0
>> [   64.101562] UBI DBG gen (pid 1): check layout volume
>> [   64.101562] UBI DBG io (pid 1): read 22528 bytes from PEB 0:4096
>> [   64.109375] UBI DBG io (pid 1): read 22528 bytes from PEB 1:4096
>> [   64.125000] UBI DBG wl (pid 1): schedule erasure of PEB 430, EC 0, torture 0
>> [...]
>> [   74.140625] UBI DBG wl (pid 1): add PEB 0 EC 0 to the used tree
>> [   74.148437] UBI DBG wl (pid 1): add PEB 1 EC 0 to the used tree
>> [...]
>> [   76.414062] UBI DBG wl (pid 1): found 1964 PEBs
>> [   76.421875] UBI DBG eba (pid 1): initialize EBA sub-system
>> [   76.421875] UBI DBG eba (pid 1): EBA sub-system is initialized
>> [   76.429687] UBI DBG gen (pid 1): ubi0 major is 252
>> [   76.437500] UBI DBG gen (pid 1): add volume 0
>> [   76.445312] UBI DBG gen (pid 1): add volume 2
>> [   76.445312] UBI: attached mtd2 (name "UBI", size 245 MiB) to ubi0
>> [   76.453125] UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
>> [   76.460937] UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
>> [   76.460937] UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
>> [   76.468750] UBI: good PEBs: 1964, bad PEBs: 0, corrupted PEBs: 0
>> [   76.476562] UBI: user volume: 2, internal volumes: 1, max. volumes count: 128
>> [   76.484375] UBI: max/mean erase counter: 1/0, WL threshold: 4096,
>> image sequence number: 27202009
>> [   76.492187] UBI: available PEBs: 926, total reserved PEBs: 1038,
>> PEBs reserved for bad PEB handling: 40
>> [   76.500000] UBIFS DBG gen (pid 1): name ubi0:rootfs, flags 0x8000
>> [   76.507812] UBI DBG gen (pid 1): open volume ubi0:rootfs, mode 1
>> [   76.507812] UBI DBG gen (pid 1): open device 0, volume rootfs, mode 1
>> [   76.515625] UBI DBG gen (pid 1): open device 0, volume 0, mode 1
>> [   76.523437] UBIFS DBG gen (pid 1): opened ubi0_0
>> [   76.523437] UBI DBG gen (pid 1): open device 0, volume 0, mode 2
>> [   76.531250] UBI: background thread "ubi_bgt0d" started, PID 352
>> [   76.539062] UBI DBG gen (pid 1): test LEB 0:0
>> [   76.546875] UBIFS DBG io (pid 1): LEB 0:0, superblock node, length 4096
>> [   76.546875] UBI DBG gen (pid 1): read 4096 bytes from LEB 0:0:0
>> [   76.554687] UBI DBG eba (pid 1): read 4096 bytes from offset 0 of
>> LEB 0:0, PEB 2
>> [   76.562500] UBI DBG io (pid 1): read 4096 bytes from PEB 2:4096
>> [   76.570312] UBI DBG wl (pid 352): erase PEB 430 EC 0 LEB -1:-1
>> [   76.570312] UBI DBG wl (pid 352): erase PEB 430, old EC 0
>> [   76.578125] UBI DBG io (pid 352): erase PEB 430
>> [   76.578125] UBIFS DBG mnt (pid 1): Auto resizing (sb) from 405 LEBs
>> to 512 LEBs
>> [   76.585937] UBI DBG gen (pid 1): atomically write 4096 bytes to LEB 0:0
>> [   76.593750] UBIFS error (pid 1): ubifs_leb_change: changing 4096
>> bytes in LEB 0 failed, error -28  <---- that's the problem I presume
>> [   76.601562] UBIFS warning (pid 1): ubifs_ro_mode: switched to
>> read-only mode, error -28
>> [   76.609375] CPU: 0 PID: 1 Comm: swapper Not tainted
>> 3.11.0-rc6-00144-g431413c-dirty #4
>> [   76.617187] [<c0012e20>] (unwind_backtrace+0x0/0xe0) from
>> [<c0010bb8>] (show_stack+0x10/0x14)
>> [   76.625000] [<c0010bb8>] (show_stack+0x10/0x14) from [<c00e9e30>]
>> (ubifs_leb_change+0xb8/0x114)
>> [   76.632812] [<c00e9e30>] (ubifs_leb_change+0xb8/0x114) from
>> [<c00e92a0>] (ubifs_read_superblock+0x4d0/0x8f8)
>> [   76.640625] [<c00e92a0>] (ubifs_read_superblock+0x4d0/0x8f8) from
>> [<c0256c60>] (mount_ubifs+0x470/0x1324)
>> [   76.648437] [<c0256c60>] (mount_ubifs+0x470/0x1324) from
>> [<c00e7d90>] (ubifs_mount+0x4dc/0x63c)
>> [   76.656250] [<c00e7d90>] (ubifs_mount+0x4dc/0x63c) from
>> [<c0079748>] (mount_fs+0x10/0xbc)
>> [   76.664062] [<c0079748>] (mount_fs+0x10/0xbc) from [<c008cfe0>]
>> (vfs_kern_mount+0x4c/0xc0)
>> [   76.671875] [<c008cfe0>] (vfs_kern_mount+0x4c/0xc0) from
>> [<c008ee70>] (do_mount+0x6cc/0x7ec)
>> [   76.679687] [<c008ee70>] (do_mount+0x6cc/0x7ec) from [<c008f014>]
>> (SyS_mount+0x84/0xb8)
>> [   76.687500] [<c008f014>] (SyS_mount+0x84/0xb8) from [<c033fdf4>]
>> (mount_block_root+0x108/0x23c)
>> [   76.695312] [<c033fdf4>] (mount_block_root+0x108/0x23c) from
>> [<c03401b8>] (prepare_namespace+0x88/0x1b0)
>> [   76.703125] [<c03401b8>] (prepare_namespace+0x88/0x1b0) from
>> [<c033fb1c>] (kernel_init_freeable+0x168/0x1ac)
>> [   76.710937] [<c033fb1c>] (kernel_init_freeable+0x168/0x1ac) from
>> [<c0253e1c>] (kernel_init+0x8/0xe4)
>> [   76.718750] [<c0253e1c>] (kernel_init+0x8/0xe4) from [<c000e590>]
>> (ret_from_fork+0x14/0x24)
>> [   76.726562] CPU: 0 PID: 1 Comm: swapper Not tainted
>> 3.11.0-rc6-00144-g431413c-dirty #4
>> [   76.734375] [<c0012e20>] (unwind_backtrace+0x0/0xe0) from
>> [<c0010bb8>] (show_stack+0x10/0x14)
>> [   76.742187] [<c0010bb8>] (show_stack+0x10/0x14) from [<c00e9e34>]
>> (ubifs_leb_change+0xbc/0x114)
>> [   76.750000] [<c00e9e34>] (ubifs_leb_change+0xbc/0x114) from
>> [<c00e92a0>] (ubifs_read_superblock+0x4d0/0x8f8)
>> [   76.757812] [<c00e92a0>] (ubifs_read_superblock+0x4d0/0x8f8) from
>> [<c0256c60>] (mount_ubifs+0x470/0x1324)
>> [   76.765625] [<c0256c60>] (mount_ubifs+0x470/0x1324) from
>> [<c00e7d90>] (ubifs_mount+0x4dc/0x63c)
>> [   76.773437] [<c00e7d90>] (ubifs_mount+0x4dc/0x63c) from
>> [<c0079748>] (mount_fs+0x10/0xbc)
>> [   76.781250] [<c0079748>] (mount_fs+0x10/0xbc) from [<c008cfe0>]
>> (vfs_kern_mount+0x4c/0xc0)
>> [   76.789062] [<c008cfe0>] (vfs_kern_mount+0x4c/0xc0) from
>> [<c008ee70>] (do_mount+0x6cc/0x7ec)
>> [   76.796875] [<c008ee70>] (do_mount+0x6cc/0x7ec) from [<c008f014>]
>> (SyS_mount+0x84/0xb8)
>> [   76.804687] [<c008f014>] (SyS_mount+0x84/0xb8) from [<c033fdf4>]
>> (mount_block_root+0x108/0x23c)
>> [   76.812500] [<c033fdf4>] (mount_block_root+0x108/0x23c) from
>> [<c03401b8>] (prepare_namespace+0x88/0x1b0)
>> [   76.820312] [<c03401b8>] (prepare_namespace+0x88/0x1b0) from
>> [<c033fb1c>] (kernel_init_freeable+0x168/0x1ac)
>> [   76.828125] [<c033fb1c>] (kernel_init_freeable+0x168/0x1ac) from
>> [<c0253e1c>] (kernel_init+0x8/0xe4)
>> [   76.835937] [<c0253e1c>] (kernel_init+0x8/0xe4) from [<c000e590>]
>> (ret_from_fork+0x14/0x24)
>> [   76.843750] UBI DBG wl (pid 352): erased PEB 430, new EC 1
>> [   76.851562] UBI DBG io (pid 352): write EC header to PEB 430
>> [   76.859375] UBI DBG io (pid 352): write 2048 bytes to PEB 430:0
>> [   76.859375] UBI DBG gen (pid 1): close device 0, volume 0, mode 2
>> [   76.867187] UBI DBG gen (pid 1): close device 0, volume 0, mode 1
>> [   76.875000] VFS: Cannot open root device "ubi0:rootfs" or
>> unknown-block(0,0): error -28
>>
>> NB: sam-ba flashes with the trimffs method. If I disable trimffs in
>> sam-ba and use mkfs.ubifs with -F, I've got the same error.
>>

I have an idea what's going on. As you are using a real (and rather slow) NAND device
erasing PEBs takes some time.
If you attach the very first time from an image created by ubinize UBI has to erase
all PEBs, parallel to that UBIFS requests one PEB but does not get one.
In this case UBI has to erase one PEB in sync-mode.

I have only nandsim, which is far to fast to hit that bug.
Who wants to donate me a board with NAND memory? ;-)

Anyway, can you please test the attached patch?

Thanks,
//richard
Richard Genoud - Aug. 26, 2013, 9:31 a.m.
2013/8/23 Richard Weinberger <richard@nod.at>:
> Hi again,
>
> I have an idea what's going on. As you are using a real (and rather slow) NAND device
> erasing PEBs takes some time.
> If you attach the very first time from an image created by ubinize UBI has to erase
> all PEBs, parallel to that UBIFS requests one PEB but does not get one.
> In this case UBI has to erase one PEB in sync-mode.
>
> I have only nandsim, which is far to fast to hit that bug.
> Who wants to donate me a board with NAND memory? ;-)
>
> Anyway, can you please test the attached patch?
To answer your previous question, yes, I see the issue every time
(i.e. I can never boot)

I tried your patch, and it worked ! Good catch !

Tried it with ubi.fm_autoconvert=0, every thing works fine.

With ubi.fm_autoconvert=1, I see this at the 1st boot (It boots fine):
[    0.812500] UBI: default fastmap pool size: 95
[    0.820312] UBI: default fastmap WL pool size: 25
[    0.820312] UBI: attaching mtd2 to ubi0
[    1.273437] UBI: scanning is finished
[    1.296875] UBI: attached mtd2 (name "UBI", size 245 MiB) to ubi0
[    1.304687] UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    1.304687] UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    1.312500] UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
[    1.320312] UBI: good PEBs: 1964, bad PEBs: 0, corrupted PEBs: 0
[    1.328125] UBI: user volume: 3, internal volumes: 1, max. volumes count: 128
[    1.328125] UBI: max/mean erase counter: 0/0, WL threshold: 4096,
image sequence number: 1933127782
[    1.335937] UBI: available PEBs: 306, total reserved PEBs: 1658,
PEBs reserved for bad PEB handling: 40
[    1.343750] UBI: background thread "ubi_bgt0d" started, PID 352
[    1.421875] UBI error: ubi_update_fastmap: could not find any anchor PEB
[    1.429687] UBI warning: ubi_update_fastmap: Unable to write new
fastmap, err=-28
[    1.437500] UBIFS: background thread "ubifs_bgt0_0" started, PID 354
[    1.515625] UBIFS: mounted UBI device 0, volume 0, name "rootfs"
[    1.515625] UBIFS: LEB size: 126976 bytes (124 KiB), min./max. I/O
unit sizes: 2048 bytes/2048 bytes
[    1.523437] UBIFS: FS size: 61583360 bytes (58 MiB, 485 LEBs),
journal size 8634368 bytes (8 MiB, 68 LEBs)
[    1.531250] UBIFS: reserved for root: 0 bytes (0 KiB)
[    1.539062] UBIFS: media format: w4/r0 (latest is w4/r0), UUID
5CA89910-239E-4C4B-9494-94E5C2990E6F, small LPT model
[    1.554687] VFS: Mounted root (ubifs filesystem) on device 0:11.
[    1.554687] devtmpfs: mounted
[    1.562500] Freeing unused kernel memory: 112K (c0335000 - c0351000)
[    2.195312] UBI error: ubi_update_fastmap: could not find any anchor PEB
[    2.195312] UBI warning: ubi_update_fastmap: Unable to write new
fastmap, err=-28


and at the 2nd boot, no more fastmap error and scanning is slow:
[    0.804687] UBI: default fastmap pool size: 95
[    0.804687] UBI: default fastmap WL pool size: 25
[    0.812500] UBI: attaching mtd2 to ubi0
[    1.562500] UBI: scanning is finished
[    1.585937] UBI: attached mtd2 (name "UBI", size 245 MiB) to ubi0
[    1.585937] UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    1.593750] UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    1.601562] UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
[    1.609375] UBI: good PEBs: 1964, bad PEBs: 0, corrupted PEBs: 0
[    1.609375] UBI: user volume: 3, internal volumes: 1, max. volumes count: 128
[    1.617187] UBI: max/mean erase counter: 2/0, WL threshold: 4096,
image sequence number: 1933127782
[    1.625000] UBI: available PEBs: 306, total reserved PEBs: 1658,
PEBs reserved for bad PEB handling: 40
[    1.640625] UBI: background thread "ubi_bgt0d" started, PID 352
[    1.656250] UBIFS: background thread "ubifs_bgt0_0" started, PID 354
[    1.718750] UBIFS: mounted UBI device 0, volume 0, name "rootfs"
[    1.726562] UBIFS: LEB size: 126976 bytes (124 KiB), min./max. I/O
unit sizes: 2048 bytes/2048 bytes
[    1.734375] UBIFS: FS size: 61583360 bytes (58 MiB, 485 LEBs),
journal size 8634368 bytes (8 MiB, 68 LEBs)
[    1.742187] UBIFS: reserved for root: 0 bytes (0 KiB)
[    1.750000] UBIFS: media format: w4/r0 (latest is w4/r0), UUID
5CA89910-239E-4C4B-9494-94E5C2990E6F, small LPT model
[    1.757812] VFS: Mounted root (ubifs filesystem) on device 0:11.
[    1.765625] devtmpfs: mounted
[    1.765625] Freeing unused kernel memory: 112K (c0335000 - c0351000)

and at the 3rd boot, every thing is normal (and fast !) \o/ :
[    0.820312] UBI: default fastmap pool size: 95
[    0.828125] UBI: default fastmap WL pool size: 25
[    0.828125] UBI: attaching mtd2 to ubi0
[    0.937500] UBI: attached by fastmap
[    0.937500] UBI: fastmap pool size: 95
[    0.945312] UBI: fastmap WL pool size: 25
[    0.960937] UBI: attached mtd2 (name "UBI", size 245 MiB) to ubi0
[    0.968750] UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
[    0.976562] UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
[    0.984375] UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
[    0.992187] UBI: good PEBs: 1964, bad PEBs: 0, corrupted PEBs: 0
[    0.992187] UBI: user volume: 3, internal volumes: 1, max. volumes count: 128
[    1.000000] UBI: max/mean erase counter: 2/0, WL threshold: 4096,
image sequence number: 1933127782
[    1.007812] UBI: available PEBs: 306, total reserved PEBs: 1658,
PEBs reserved for bad PEB handling: 40
[    1.015625] UBI: background thread "ubi_bgt0d" started, PID 352
[    1.039062] UBIFS: background thread "ubifs_bgt0_0" started, PID 354
[    1.085937] UBIFS: mounted UBI device 0, volume 0, name "rootfs"
[    1.093750] UBIFS: LEB size: 126976 bytes (124 KiB), min./max. I/O
unit sizes: 2048 bytes/2048 bytes
[    1.101562] UBIFS: FS size: 61583360 bytes (58 MiB, 485 LEBs),
journal size 8634368 bytes (8 MiB, 68 LEBs)
[    1.109375] UBIFS: reserved for root: 0 bytes (0 KiB)
[    1.117187] UBIFS: media format: w4/r0 (latest is w4/r0), UUID
5CA89910-239E-4C4B-9494-94E5C2990E6F, small LPT model
[    1.125000] VFS: Mounted root (ubifs filesystem) on device 0:11.
[    1.132812] devtmpfs: mounted
[    1.140625] Freeing unused kernel memory: 112K (c0335000 - c0351000)

Thanks !
Richard Weinberger - Aug. 26, 2013, 2:44 p.m.
Am 26.08.2013 11:31, schrieb Richard Genoud:
> 2013/8/23 Richard Weinberger <richard@nod.at>:
>> Hi again,
>>
>> I have an idea what's going on. As you are using a real (and rather slow) NAND device
>> erasing PEBs takes some time.
>> If you attach the very first time from an image created by ubinize UBI has to erase
>> all PEBs, parallel to that UBIFS requests one PEB but does not get one.
>> In this case UBI has to erase one PEB in sync-mode.
>>
>> I have only nandsim, which is far to fast to hit that bug.
>> Who wants to donate me a board with NAND memory? ;-)
>>
>> Anyway, can you please test the attached patch?
> To answer your previous question, yes, I see the issue every time
> (i.e. I can never boot)
> 
> I tried your patch, and it worked ! Good catch !
> 
> Tried it with ubi.fm_autoconvert=0, every thing works fine.
> 
> With ubi.fm_autoconvert=1, I see this at the 1st boot (It boots fine):
> [    0.812500] UBI: default fastmap pool size: 95
> [    0.820312] UBI: default fastmap WL pool size: 25
> [    0.820312] UBI: attaching mtd2 to ubi0
> [    1.273437] UBI: scanning is finished
> [    1.296875] UBI: attached mtd2 (name "UBI", size 245 MiB) to ubi0
> [    1.304687] UBI: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
> [    1.304687] UBI: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
> [    1.312500] UBI: VID header offset: 2048 (aligned 2048), data offset: 4096
> [    1.320312] UBI: good PEBs: 1964, bad PEBs: 0, corrupted PEBs: 0
> [    1.328125] UBI: user volume: 3, internal volumes: 1, max. volumes count: 128
> [    1.328125] UBI: max/mean erase counter: 0/0, WL threshold: 4096,
> image sequence number: 1933127782
> [    1.335937] UBI: available PEBs: 306, total reserved PEBs: 1658,
> PEBs reserved for bad PEB handling: 40
> [    1.343750] UBI: background thread "ubi_bgt0d" started, PID 352
> [    1.421875] UBI error: ubi_update_fastmap: could not find any anchor PEB
> [    1.429687] UBI warning: ubi_update_fastmap: Unable to write new
> fastmap, err=-28

The problem here is that the ubinized image uses all 64 anchor PEBs (0 to 63) for data
and fastmap has to move data first to get a free anchor PEBs.
Maybe I find a way to perform this task faster/better.

But IMHO the best thing is adding fastmap support to ubinize.

Thanks,
//richard

Patch

diff --git a/drivers/mtd/ubi/wl.c b/drivers/mtd/ubi/wl.c
index 5df49d3..7ba3e6d 100644
--- a/drivers/mtd/ubi/wl.c
+++ b/drivers/mtd/ubi/wl.c
@@ -599,10 +599,6 @@  static void refill_wl_user_pool(struct ubi_device *ubi)
 	return_unused_pool_pebs(ubi, pool);
 
 	for (pool->size = 0; pool->size < pool->max_size; pool->size++) {
-		if (!ubi->free.rb_node ||
-		   (ubi->free_count - ubi->beb_rsvd_pebs < 1))
-			break;
-
 		pool->pebs[pool->size] = __wl_get_peb(ubi);
 		if (pool->pebs[pool->size] < 0)
 			break;